Date:	Fri, 30 May 2014 12:28:45 +0800
From:	Jet Chen <jet.chen@...el.com>
To:	Jan Kara <jack@...e.cz>
CC:	Fengguang Wu <fengguang.wu@...el.com>,
	Yuanhan Liu <yuanhan.liu@...el.com>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>
Subject: [prink]  BUG: spinlock lockup suspected on CPU#0, swapper/1

Hi Jan,

0day kernel testing robot got the below dmesg and the first bad commit is

git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master
commit bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0
Author:     Jan Kara <jack@...e.cz>
AuthorDate: Thu May 22 10:43:35 2014 +1000
Commit:     Stephen Rothwell <sfr@...b.auug.org.au>
CommitDate: Thu May 22 10:43:35 2014 +1000

    printk: enable interrupts before calling console_trylock_for_printk()
        We need interrupts disabled when calling console_trylock_for_printk() only
    so that cpu id we pass to can_use_console() remains valid (for other
    things console_sem provides all the exclusion we need and deadlocks on
    console_sem due to interrupts are impossible because we use
    down_trylock()).  However if we are rescheduled, we are guaranteed to run
    on an online cpu so we can easily just get the cpu id in
    can_use_console().
        We can lose a bit of performance when we enable interrupts in
    vprintk_emit() and then disable them again in console_unlock() but OTOH it
    can somewhat reduce interrupt latency caused by console_unlock()
    especially since later in the patch series we will want to spin on
    console_sem in console_trylock_for_printk().
        Signed-off-by: Jan Kara <jack@...e.cz>
    Signed-off-by: Andrew Morton <akpm@...ux-foundation.org>

+----------------------------------------------------+------------+------------+
|                                                    | ee75ecbd8b | bafe980f5a |
+----------------------------------------------------+------------+------------+
| boot_successes                                     | 60         | 0          |
| boot_failures                                      | 0          | 20         |
| BUG:spinlock_lockup_suspected_on_CPU               | 0          | 20         |
| INFO:possible_circular_locking_dependency_detected | 0          | 20         |
| backtrace:do_sys_open                              | 0          | 20         |
| backtrace:SyS_open                                 | 0          | 20         |
| backtrace:kernel_init_freeable                     | 0          | 20         |
| backtrace:print_ICs                                | 0          | 20         |
| backtrace:setup_default_timer_irq                  | 0          | 20         |
| backtrace:hpet_time_init                           | 0          | 20         |
| backtrace:x86_late_time_init                       | 0          | 20         |
+----------------------------------------------------+------------+------------+


[    7.490555] EDD information not available.
[    7.490999] ### dt-test ### No testcase data in device tree; not running tests
[    7.491848] [    7.492350] BUG: spinlock lockup suspected on CPU#0, swapper/1
[    7.492350]  lock: serial8250_ports+0x0/0x4c0, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0
[    7.492350] CPU: 0 PID: 1 Comm: swapper Not tainted 3.15.0-rc5-00567-gbafe980 #1
[    7.492350]  80038000 80038000 80027a8c 81b9bd30 80027ab4 81b968d0 81eb5198 82755f80
[    7.492350]  dead4ead 80038340 00000001 00000000 82755f80 a08b8bfc 80027ad0 81077777
[    7.492350]  a08b8bfc 00000000 82755f80 00000086 00000001 80027af0 81baeda4 00000000
[    7.492350] Call Trace:
[    7.492350]  [<81b9bd30>] dump_stack+0x16/0x18
[    7.492350]  [<81b968d0>] spin_dump+0x90/0x97
[    7.492350]  [<81077777>] do_raw_spin_lock+0xa7/0xf0
[    7.492350]  [<81baeda4>] _raw_spin_lock_irqsave+0x54/0x60
[    7.492350]  [<815f652c>] ? serial8250_console_write+0x11c/0x140
[    7.492350]  [<815f6410>] ? serial8250_modem_status+0xc0/0xc0
[    7.492350]  [<815f652c>] serial8250_console_write+0x11c/0x140
[    7.492350]  [<815f6410>] ? serial8250_modem_status+0xc0/0xc0
[    7.492350]  [<8107b534>] call_console_drivers.constprop.20+0x64/0x130
[    7.492350]  [<8107bcb5>] console_unlock+0x445/0x4d0
[    7.492350]  [<8107be98>] vprintk_emit+0x158/0x4d0
[    7.492350]  [<81b969b9>] printk+0x38/0x3a
[    7.492350]  [<81b95fd0>] print_circular_bug_header+0x35/0xc1
[    7.492350]  [<81b960c6>] print_circular_bug+0x6a/0x268
[    7.492350]  [<810743c2>] __lock_acquire+0x19c2/0x1b20
[    7.492350]  [<81070d18>] ? check_irq_usage+0x88/0xc0
[    7.492350]  [<810750e5>] lock_acquire+0x85/0x190
[    7.492350]  [<8107dc8c>] ? __irq_get_desc_lock+0x3c/0x70
[    7.492350]  [<81baed9d>] _raw_spin_lock_irqsave+0x4d/0x60
[    7.492350]  [<8107dc8c>] ? __irq_get_desc_lock+0x3c/0x70
[    7.492350]  [<8107dc8c>] __irq_get_desc_lock+0x3c/0x70
[    7.492350]  [<8107eb1e>] __disable_irq_nosync+0x1e/0x50
[    7.492350]  [<8107eb58>] disable_irq_nosync+0x8/0x10
[    7.492350]  [<815f5c78>] serial8250_startup+0x488/0x720
[    7.492350]  [<810de6d0>] ? __get_free_pages+0x20/0x40
[    7.492350]  [<815f205e>] uart_startup.part.4+0x6e/0x1e0
[    7.492350]  [<815f2a40>] uart_open+0xe0/0x140
[    7.492350]  [<815f2960>] ? uart_ioctl+0x2f0/0x2f0
[    7.492350]  [<815e4b51>] tty_open+0x141/0x510
[    7.492350]  [<815e4a10>] ? tty_ioctl+0xb20/0xb20
[    7.492350]  [<81118bc0>] chrdev_open+0x60/0x140
[    7.492350]  [<8111372c>] do_dentry_open+0x14c/0x230
[    7.492350]  [<81118b60>] ? exact_lock+0x20/0x20
[    7.492350]  [<8111459e>] finish_open+0x2e/0x40
[    7.492350]  [<8112132a>] do_last+0x4aa/0xd30
[    7.492350]  [<8111f4fd>] ? link_path_walk+0x1dd/0x700
[    7.492350]  [<81121c5a>] path_openat+0xaa/0x610
[    7.492350]  [<811221ec>] do_filp_open+0x2c/0x70
[    7.492350]  [<81114a81>] do_sys_open+0x111/0x210
[    7.492350]  [<81600000>] ? _xfer_secondary_pool+0x150/0x230
[    7.492350]  [<81114b9d>] SyS_open+0x1d/0x20
[    7.492350]  [<8212bda4>] kernel_init_freeable+0x1c6/0x236
[    7.492350]  [<8212b4f2>] ? do_early_param+0x78/0x78
[    7.492350]  [<81b9238b>] kernel_init+0xb/0xd0
[    7.492350]  [<81063b12>] ? schedule_tail+0x12/0x40
[    7.492350]  [<81bb0080>] ret_from_kernel_thread+0x20/0x30
[    7.492350]  [<81b92380>] ? rest_init+0x130/0x130
[    7.492350] ======================================================

git bisect start 07dd999f99b1135fdece697e17c4f4248ab40f72 53a4fdb4a7c8aeef977f8450bcdb92d1962e321e --
git bisect  bad 54af61db1031c7ddef016987e9938cbbbaf92968  # 09:12      0-     18  Merge branch 'akpm-current/current'
git bisect good d93e8dbb6c2cd2fde8d46e1ad12d19ffa1868747  # 09:19     20+      0  mm: page_alloc: use unsigned int for order in more places
git bisect  bad 7ff60469e63f2bd110582cdf8ba95afa694bf7c6  # 09:24      0-      4  rtc: rtc-mv: make of_device_id array const
git bisect  bad 3c3ad385a174d5d2490b2f9c6513b588dc8a1ddb  # 09:27      0-     19  printk: disable preemption for printk_sched
git bisect good 456407d6fec5f28c1be67fcf803f9cca14b75142  # 09:31     20+      0  do_shared_fault(): check that mmap_sem is held
git bisect good e94a01e20b75345d1486e7d0bdf03313f8f47d0b  # 09:36     20+      0  kernel/utsname_sysctl.c: replace obsolete __initcall by device_initcall
git bisect good 6f83a1a8d7e0a9e71f3ee1641a965aede0ee4c6c  # 09:49     20+      0  printk: shrink too long messages
git bisect good 3bd16050e9c555cb7b08a4f830db95e9025336e6  # 09:54     20+      0  printk-release-lockbuf_lock-before-calling-console_trylock_for_printk-fix
git bisect  bad bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0  # 10:00      0-      4  printk: enable interrupts before calling console_trylock_for_printk()
git bisect good ee75ecbd8b9ad26cd0094573cd4b612ab20b3e71  # 10:10     20+      0  printk: fix lockdep instrumentation of console_sem
# first bad commit: [bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0] printk: enable interrupts before calling console_trylock_for_printk()
git bisect good ee75ecbd8b9ad26cd0094573cd4b612ab20b3e71  # 10:13     60+      0  printk: fix lockdep instrumentation of console_sem
git bisect  bad 07dd999f99b1135fdece697e17c4f4248ab40f72  # 10:13      0-     13  Add linux-next specific files for 20140529
git bisect good a991639c26c7231ddb6de7f34899fb70832b7d04  # 10:18     60+      0  Merge tag 'arm64-fixes' of git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux
git bisect  bad 07dd999f99b1135fdece697e17c4f4248ab40f72  # 10:18      0-     13  Add linux-next specific files for 20140529


This script may reproduce the error.

-----------------------------------------------------------------------------
#!/bin/bash

kernel=$1
initrd=yocto-minimal-i386.cgz

wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/$initrd

kvm=(
	qemu-system-x86_64 -cpu kvm64 -enable-kvm 	-kernel $kernel
	-initrd $initrd
	-smp 2
	-m 256M
	-net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
	-net user,vlan=0
	-net nic,vlan=1,model=e1000
	-net user,vlan=1
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-serial stdio
	-display none
	-monitor null
)

append=(
	debug
	sched_debug
	apic=debug
	ignore_loglevel
	sysrq_always_enabled
	panic=10
	prompt_ramdisk=0
	earlyprintk=ttyS0,115200
	console=ttyS0,115200
	console=tty0
	vga=normal
	root=/dev/ram0
	rw
)

"${kvm[@]}" --append "${append[*]}"
-----------------------------------------------------------------------------

Thanks,
Jet


View attachment "dmesg-yocto-ivb42-1:20140530095845:i386-randconfig-ib0-05300841:3.15.0-rc5-00567-gbafe980:1" of type "text/plain" (117683 bytes)

Download attachment "i386-randconfig-ib0-05300841-07dd999f99b1135fdece697e17c4f4248ab40f72-BUG:-spinlock-lockup-suspected-on-CPU---29720.log" of type "application/octet-stream" (49592 bytes)

View attachment "config-3.15.0-rc5-00567-gbafe980" of type "text/plain" (93624 bytes)

View attachment "Attached Message Part" of type "text/plain" (87 bytes)

Powered by blists - more mailing lists