All of lore.kernel.org
 help / color / mirror / Atom feed
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
To: lkp@lists.01.org
Subject: Re: [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600
Date: Wed, 24 Feb 2016 00:53:31 +0900	[thread overview]
Message-ID: <20160223155331.GA448@swordfish> (raw)
In-Reply-To: <20160223131538.GA2048@swordfish>

[-- Attachment #1: Type: text/plain, Size: 5181 bytes --]

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

WARNING: multiple messages have this Message-ID (diff)
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
To: kernel test robot <ying.huang@linux.intel.com>
Cc: lkp@01.org, LKML <linux-kernel@vger.kernel.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	Calvin Owens <calvinowens@fb.com>,
	Dave Jones <davej@codemonkey.org.uk>,
	Kyle McMartin <kyle@kernel.org>, Tejun Heo <tj@kernel.org>,
	Jan Kara <jack@suse.com>, Petr Mladek <pmladek@suse.com>,
	Stephen Rothwell <sfr@canb.auug.org.au>,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Subject: Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600
Date: Wed, 24 Feb 2016 00:53:31 +0900	[thread overview]
Message-ID: <20160223155331.GA448@swordfish> (raw)
In-Reply-To: <20160223131538.GA2048@swordfish>

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

       reply	other threads:[~2016-02-23 15:53 UTC|newest]

Thread overview: 24+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
     [not found] <20160223131538.GA2048@swordfish>
2016-02-23 15:53 ` Sergey Senozhatsky [this message]
2016-02-23 15:53   ` [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky
2016-02-24  1:19   ` Sergey Senozhatsky
2016-02-24  1:19     ` [lkp] " Sergey Senozhatsky
2016-02-24  1:19     ` Sergey Senozhatsky
2016-02-24 11:46     ` Petr Mladek
2016-02-24 11:46       ` [lkp] " Petr Mladek
2016-02-24 11:46       ` Petr Mladek
2016-02-24 12:50       ` Sergey Senozhatsky
2016-02-24 12:50         ` [lkp] " Sergey Senozhatsky
2016-02-24 12:50         ` Sergey Senozhatsky
2016-02-24 15:12         ` Sergey Senozhatsky
2016-02-24 15:12           ` [lkp] " Sergey Senozhatsky
2016-02-25  5:10           ` Sergey Senozhatsky
2016-02-25  5:10             ` [lkp] " Sergey Senozhatsky
2016-02-25  5:10             ` Sergey Senozhatsky
2016-03-02 10:30             ` Petr Mladek
2016-03-02 10:30               ` [lkp] " Petr Mladek
2016-03-02 10:41               ` Sergey Senozhatsky
2016-03-02 10:41                 ` [lkp] " Sergey Senozhatsky
2016-02-23  0:55 kernel test robot
2016-02-23  0:55 ` [lkp] " kernel test robot
2016-02-23 16:55 ` Petr Mladek
2016-02-23 16:55   ` [lkp] " Petr Mladek

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20160223155331.GA448@swordfish \
    --to=sergey.senozhatsky@gmail.com \
    --cc=lkp@lists.01.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.