[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <538808FD.3060707@intel.com>
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