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

[Linus Torvalds <torvalds@linux-foundation.org>]

On Fri, Apr 10, 2020 at 11:29 AM Randy Dunlap <rdunlap@infradead.org> 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..
>
> [I found the script's help output not so helpful.]

Heh.

I think the bigger problem is that decode_stacktrace.sh is probably
hardly mentioned anywhere.

It's been around for 6 years by now, but I guess we never really
advertised it. I end up mentioning it every few months to people when
their stack traces look particularly complex (particularly if the
function at some point goes through 5 levels of inlining and it's
really hard to even find what could possibly be the offending
instruction).

Yours wasn't actually so bad, and I don't think decode_stacktrace ends
up being a big deal in this case (and I find the line numbers less
than useful since this is about linux-next).

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.

> [  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.

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