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

Petr Mladek
2016-02-24T11:46:20Z

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