Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600

[Petr Mladek]

On Wed 2016-02-24 10:19:41, Sergey Senozhatsky wrote:
> 
> Hello,
> 
> Cc Rob, Frank, Grant
> 
> On (02/24/16 00:53), Sergey Senozhatsky wrote:
> [..]
> >  284 [    0.000000]  per task-struct memory footprint: 2112 bytes
> >  285 [    0.000000]  per task-struct memory footprint: 2112 bytes
> >  286 [    0.000000] ------------------------
> >  287 [    0.000000] ------------------------
> >  288 [    0.000000] | Locking API testsuite:
> >  289 [    0.000000] | Locking API testsuite:
> >  290 [    0.000000] ----------------------------------------------------------------------------
> >  291 [    0.000000] ----------------------------------------------------------------------------
> >  292 [    0.000000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
> >  293 [    0.000000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
> >  294 [    0.000000]   --------------------------------------------------------------------------
> >  295 [    0.000000]   --------------------------------------------------------------------------
> > 
> > 
> > looking at your Kernel command line
> > 
> > [    0.000000] Kernel command line: root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-kbuild-yocto-i386-53/bisect_boot-1-yocto-minimal-i386.cgz-i386-randconfig-h1-02192137-34578dc67f38c02ccbe696e4099967884caa8e15-20160220-72722-vao2m5-0.yaml ARCH=i386 kconfig=i386-randconfig-h1-02192137 branch=linux-next/master commi     t=34578dc67f38c02ccbe696e4099967884caa8e15 BOOT_IMAGE=/pkg/linux/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe696e4099967884caa8e15/vmlinuz-4.5.0-rc4-00295-g34578dc max_uptime=600 RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-i386/yocto-minimal-i386.cgz/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe69     6e4099967884caa8e15/9 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal rw ip=::::vm-kbuild-yo     cto-i386-53::dhcp drbd.minor_count=8
> > 
> > 
> > - earlyprintk=ttyS0,115200
> > - console=ttyS0,115200
> > - console=tty0
> > 
> > and I see "bootconsole [earlyser0] enabled" but no "bootconsole [earlyser0] disabled" message, which
> > I'd expect to see...
> > 
> 
> 
> and you get the NMI watchdog softlockup because you have a whole bunch of
> 
>    "of_overlay_destroy: Could not find overlay #6"
>    "### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6"
> 
> messages to print. seems that somehitng just pushes them in a loop.
> there are too many of them:

This sounds like a reasonable explanation. It seems that
of_unittest_destroy_tracked_overlays() really ended in an infinite
loop.

But I am still curious why the softlookup points to

[   33.497718] EIP is at vprintk_emit+0x1ea/0x600

Also there is on the stack

[   33.497741]  [<c068e712>] vprintk_default+0x32/0x40
[   33.497741]  [<c068e712>] vprintk_default+0x32/0x40
[   33.497744]  [<c06fdf6e>] printk+0x11/0x13
[   33.497744]  [<c06fdf6e>] printk+0x11/0x13
[   33.497748]  [<c0df5eec>] of_unittest_overlay+0x8d1/0x900
[   33.497748]  [<c0df5eec>] of_unittest_overlay+0x8d1/0x900
[   33.497750]  [<c0df6b1f>] of_unittest+0xc04/0xc2d
[   33.497750]  [<c0df6b1f>] of_unittest+0xc04/0xc2d

I would expect that the soft lookup happens in console_unlock()
called with IRQs disabled. It seems to me that of_unittest_overlay()
is called with IRQs enabled.

I want to be sure that the patch in printk() did not introduce
a deadlock that is visible only under a high printk load.

I guess that the softlookup was not visible before the
printk patch was applied. I wonder if the patch made something
worse. It was supposed to improve things but...

Do I miss something, please?

Best Regards,
Petr