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

[Sergey Senozhatsky]

On (02/23/16 22:15), Sergey Senozhatsky wrote:
> On (02/23/16 08:55), kernel test robot wrote:
> > [   33.497678] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
> > [   33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1]
> > [   33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1]
> > [   33.497695] Modules linked in:
> > [   33.497695] Modules linked in:
> > [   33.497696] irq event stamp: 69018756
> > [   33.497696] irq event stamp: 69018756
> 
> how may consoles do you have registered? is it possible that your
> call_console_drivers() loop push the same data to different consoles,
> but the messages end up in one place (serial port, etc... dunno)?
> does it happen to all of the messages?

oh... didn't notice there was a dmesg.xz attached.


ok, so everything is "doubled" in your dmesg, starting from "console [ttyS0] enabled" line

 254 [    0.000000]     vmalloc : 0xc47e0000 - 0xff7fe000   ( 944 MB)
 255 [    0.000000]     lowmem  : 0xb0000000 - 0xc3fe0000   ( 319 MB)
 256 [    0.000000]       .init : 0xc0dc4000 - 0xc0e3a000   ( 472 kB)
 257 [    0.000000]       .data : 0xc0a0a040 - 0xc0dc2560   (3809 kB)
 258 [    0.000000]       .text : 0xc0600000 - 0xc0a0a040   (4136 kB)
 259 [    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
 260 [    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
 261 [    0.000000] Running RCU self tests
 262 [    0.000000] NR_IRQS:2304 nr_irqs:256 16
 263 [    0.000000] CPU 0 irqstacks, hard=b002a000 soft=b002c000
 264 [    0.000000] console [ttyS0] enabled
 265 [    0.000000] console [ttyS0] enabled
 266 [    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
 267 [    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
 268 [    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
 269 [    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
 270 [    0.000000] ... MAX_LOCK_DEPTH:          48
 271 [    0.000000] ... MAX_LOCK_DEPTH:          48
 272 [    0.000000] ... MAX_LOCKDEP_KEYS:        8191
 273 [    0.000000] ... MAX_LOCKDEP_KEYS:        8191
 274 [    0.000000] ... CLASSHASH_SIZE:          4096
 275 [    0.000000] ... CLASSHASH_SIZE:          4096
 276 [    0.000000] ... MAX_LOCKDEP_ENTRIES:     32768
 277 [    0.000000] ... MAX_LOCKDEP_ENTRIES:     32768
 278 [    0.000000] ... MAX_LOCKDEP_CHAINS:      65536
 279 [    0.000000] ... MAX_LOCKDEP_CHAINS:      65536
 280 [    0.000000] ... CHAINHASH_SIZE:          32768
 281 [    0.000000] ... CHAINHASH_SIZE:          32768
 282 [    0.000000]  memory used by lock dependency info: 5167 kB
 283 [    0.000000]  memory used by lock dependency info: 5167 kB
 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


so you have two consoles: ttyS0 and tty0?


and I see "bootconsole [earlyser0] enabled" but no "bootconsole [earlyser0] disabled" message, which
I'd expect to see...

So how may consoles do you have? 2 or 3? so call_console_drivers() has to ->write()
every log line N times; at least to ttyS0->write() and to tty0->write()?

	-ss