Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600
From: Petr Mladek <pmladek@suse.com>
Date: 2016-02-24 11:46:20
Also in:
lkml, oe-lkp
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: [..]quoted
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 p
anic=-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
quoted
- 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