Re: linux-next: Tree for Apr 10 (lib/test_printf.ko)

[Randy Dunlap]

On 4/10/20 12:05 PM, Linus Torvalds wrote:
> On Fri, Apr 10, 2020 at 11:29 AM Randy Dunlap <rdunlap@xxxxxxxxxxxxx> wrote:
>>
>>> I wonder if these scripts aren't well enough known, I see a lot of raw
>>> dumps that could be immensely improved with a little scripting - but
>>> they need the original vmlinux binary with debug info, so you can't do
>>> it after-the-fact somewhere else..
>>

> But even dump_stack.sh can't sort out how it got from test_printf_init
> to software_node_unregister_nodes even though it usually is good about
> following all the inlining (in this case selftest -> test_pointer ->
> fwnode_pointer).
> 
> That may be because of something like a DEBUG_INFO_REDUCED option.

No, that's enabled. (see below)


>> [  561.071144] _raw_spin_lock_irqsave (linux-next-20200410/rdd64/../include/linux/instrumented.h:71 linux-next-20200410/rdd64/../include/asm-generic/atomic-instrumented.h:695 linux-next-20200410/rdd64/../include/asm-generic/qspinlock.h:78 linux-next-20200410/rdd64/../include/linux/spinlock.h:194 linux-next-20200410/rdd64/../include/linux/spinlock_api_smp.h:119 linux-next-20200410/rdd64/../kernel/locking/spinlock.c:159)
>> [  561.074868] ? _raw_write_unlock_bh (linux-next-20200410/rdd64/../kernel/locking/spinlock.c:158)
>> [  561.078495] ? ida_destroy (linux-next-20200410/rdd64/../lib/idr.c:538)
>> [  561.082144] ida_free (linux-next-20200410/rdd64/../lib/idr.c:495 (discriminator 2))
>> [  561.085694] ? fprop_new_period.cold (linux-next-20200410/rdd64/../lib/idr.c:486)
>> [  561.089228] ? kasan_slab_free (linux-next-20200410/rdd64/../mm/kasan/common.c:466)
>> [  561.092738] ? kfree (linux-next-20200410/rdd64/../mm/slub.c:1478 linux-next-20200410/rdd64/../mm/slub.c:3035 linux-next-20200410/rdd64/../mm/slub.c:4003)
>> [  561.096183] software_node_release (linux-next-20200410/rdd64/../include/linux/list.h:132 linux-next-20200410/rdd64/../include/linux/list.h:146 linux-next-20200410/rdd64/../drivers/base/swnode.c:613)
>> [  561.099644] kobject_put (linux-next-20200410/rdd64/../lib/kobject.c:697 linux-next-20200410/rdd64/../lib/kobject.c:722 linux-next-20200410/rdd64/../include/linux/kref.h:65 linux-next-20200410/rdd64/../lib/kobject.c:739)
>> [  561.103109] kobject_del (linux-next-20200410/rdd64/../lib/kobject.c:629)
>> [  561.106457] kobject_put (linux-next-20200410/rdd64/../lib/kobject.c:690 linux-next-20200410/rdd64/../lib/kobject.c:722 linux-next-20200410/rdd64/../include/linux/kref.h:65 linux-next-20200410/rdd64/../lib/kobject.c:739)
>> [  561.109785] fwnode_remove_software_node (linux-next-20200410/rdd64/../drivers/base/swnode.c:784)
>> [  561.113061] software_node_unregister_nodes (linux-next-20200410/rdd64/../drivers/base/swnode.c:721 (discriminator 2))
>> [  561.116274] test_printf_init (linux-next-20200410/rdd64/../lib/test_printf.c:685 linux-next-20200410/rdd64/../lib/test_printf.c:688) test_printf
> 
> It does print out those multiple lines for some things, but doesn't
> have the nice "inlined by XYZ" I sometimes see that makes it really
> obvious.
> 

This is with FRAME_POINTER, not UNWIND_ORC. Maybe that's the difference?


> So it ends up still just looking like ida_free -> _raw_spin_lock_irqsave.
> 
> Strange. But it's all the same freeing path:
> 
>> [  561.278921] Freed by task 1454:
>> [  561.289528] kfree (linux-next-20200410/rdd64/../mm/slub.c:1478 linux-next-20200410/rdd64/../mm/slub.c:3035 linux-next-20200410/rdd64/../mm/slub.c:4003)
>> [  561.292183] software_node_release (linux-next-20200410/rdd64/../drivers/base/swnode.c:624)
>> [  561.294865] kobject_put (linux-next-20200410/rdd64/../lib/kobject.c:697 linux-next-20200410/rdd64/../lib/kobject.c:722 linux-next-20200410/rdd64/../include/linux/kref.h:65 linux-next-20200410/rdd64/../lib/kobject.c:739)
>> [  561.297501] kobject_del (linux-next-20200410/rdd64/../lib/kobject.c:629)
>> [  561.300154] kobject_put (linux-next-20200410/rdd64/../lib/kobject.c:690 linux-next-20200410/rdd64/../lib/kobject.c:722 linux-next-20200410/rdd64/../include/linux/kref.h:65 linux-next-20200410/rdd64/../lib/kobject.c:739)
>> [  561.302784] kobject_del (linux-next-20200410/rdd64/../lib/kobject.c:629)
>> [  561.305344] kobject_put (linux-next-20200410/rdd64/../lib/kobject.c:690 linux-next-20200410/rdd64/../lib/kobject.c:722 linux-next-20200410/rdd64/../include/linux/kref.h:65 linux-next-20200410/rdd64/../lib/kobject.c:739)
>> [  561.307914] fwnode_remove_software_node (linux-next-20200410/rdd64/../drivers/base/swnode.c:784)
> 
> so it at least superficially looks like software_node_release() might
> be called twice.
> 
> Maybe the child node is released after the parent node - and the child
> node seems to do the
> 
>         ida_simple_remove(&swnode->parent->child_ids, swnode->id);
> 
> and maybe it's that the parent->child_ids was already free'd by the
> previous software_node_release() call? Do children not keep a refcount
> to their parent, perhaps?
> 
> Somebody who knows the driver core thing needs to look at it. And
> since I don't play with linux-next apart from checking when I pull, I
> don't know what might have happened in this area..
> 
> Adding some driver core people to the cc.
> 
>                 Linus-- 
~Randy