2014-06-13 16:04:23

by Jet Chen

[permalink] [raw]
Subject: [block] WARNING: CPU: 0 PID: 99 at kernel/softirq.c:156 local_bh_enable()

Hi Zhiguo,

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

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit 2c575026fae6e63771bd2a4c1d407214a8096a89
Author: Hong Zhiguo <[email protected]>
AuthorDate: Wed Nov 20 10:35:05 2013 -0700
Commit: Jens Axboe <[email protected]>
CommitDate: Wed Nov 20 15:33:04 2013 -0700

Update of blkg_stat and blkg_rwstat may happen in bh context.
While u64_stats_fetch_retry is only preempt_disable on 32bit
UP system. This is not enough to avoid preemption by bh and
may read strange 64 bit value.
Signed-off-by: Hong Zhiguo <[email protected]>
Acked-by: Tejun Heo <[email protected]>
Cc: [email protected]
Signed-off-by: Jens Axboe <[email protected]>


+-------------------------------------------------------+------------+------------+
| | 82023bb7f7 | 2c575026fa |
+-------------------------------------------------------+------------+------------+
| boot_successes | 794 | 183 |
| boot_failures | 106 | 117 |
| BUG:kernel_test_crashed | 33 | |
| BUG:kernel_boot_hang | 73 | 91 |
| WARNING:CPU:PID:at_kernel/softirq.c:local_bh_enable() | 0 | 117 |
| inconsistent_SOFTIRQ-ON-W-IN-SOFTIRQ-W_usage | 0 | 117 |
| backtrace:do_mount | 0 | 85 |
| backtrace:SyS_mount | 0 | 85 |
| backtrace:redo_fd_request | 0 | 117 |
| backtrace:floppy_work_workfn | 0 | 0 |
| backtrace:fd_timer_workfn | 0 | 0 |
+-------------------------------------------------------+------------+------------+

[ 414.461526] power_supply test_battery: prop TEMP=26
[ 414.871358] power_supply test_battery: prop VOLTAGE_NOW=3300
[ 416.112247] ------------[ cut here ]------------
[ 416.113048] WARNING: CPU: 0 PID: 99 at kernel/softirq.c:156 local_bh_enable+0x39/0xc0()
[ 416.113048] CPU: 0 PID: 99 Comm: kworker/u2:1 Not tainted 3.12.0-10276-g2c57502 #1
[ 416.113048] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 416.113048] Workqueue: floppy redo_fd_request
[ 416.113048] 00000000 00000000 d1599c7c c13f3d3f d1599cac c023551b c1990f08 00000000
[ 416.113048] 00000063 c1991108 0000009c c0239219 c0239219 c060f801 d1661a14 d1660000
[ 416.113048] d1599cbc c02355dd 00000009 00000000 d1599cc8 c0239219 d1599cf0 d1599cd8
[ 416.113048] Call Trace:
[ 416.113048] [<c13f3d3f>] dump_stack+0x16/0x18
[ 416.113048] [<c023551b>] warn_slowpath_common+0x6b/0x90
[ 416.113048] [<c0239219>] ? local_bh_enable+0x39/0xc0
[ 416.113048] [<c0239219>] ? local_bh_enable+0x39/0xc0
[ 416.113048] [<c060f801>] ? blkg_rwstat_read+0x41/0x50
[ 416.113048] [<c02355dd>] warn_slowpath_null+0x1d/0x20
[ 416.113048] [<c0239219>] local_bh_enable+0x39/0xc0
[ 416.113048] [<c060f801>] blkg_rwstat_read+0x41/0x50
[ 416.113048] [<c0611b65>] __cfq_set_active_queue+0x75/0x180
[ 416.113048] [<c0220ab3>] ? kvm_clock_read+0x13/0x20
[ 416.113048] [<c0207738>] ? sched_clock+0x8/0x10
[ 416.113048] [<c025b8b5>] ? sched_clock_local.constprop.2+0x15/0x150
[ 416.113048] [<c06132f3>] cfq_dispatch_requests+0x613/0x990
[ 416.113048] [<c0220ab3>] ? kvm_clock_read+0x13/0x20
[ 416.113048] [<c0207738>] ? sched_clock+0x8/0x10
[ 416.113048] [<c025b8b5>] ? sched_clock_local.constprop.2+0x15/0x150
[ 416.113048] [<c08bceff>] ? redo_fd_request+0x3f/0x1010
[ 416.113048] [<c05f7e1e>] blk_peek_request+0x17e/0x1b0
[ 416.113048] [<c140945d>] ? _raw_spin_lock_irq+0x6d/0x80
[ 416.113048] [<c05f7e59>] blk_fetch_request+0x9/0x20
[ 416.113048] [<c08bcf45>] redo_fd_request+0x85/0x1010
[ 416.113048] [<c024a1e0>] ? process_one_work+0x1c0/0x3d0
[ 416.113048] [<c024a24a>] process_one_work+0x22a/0x3d0
[ 416.113048] [<c024a1e0>] ? process_one_work+0x1c0/0x3d0
[ 416.113048] [<c024a5bf>] worker_thread+0x1cf/0x330
[ 416.113048] [<c024a3f0>] ? process_one_work+0x3d0/0x3d0
[ 416.113048] [<c025108a>] kthread+0xaa/0xb0
[ 416.113048] [<c140a637>] ret_from_kernel_thread+0x1b/0x28
[ 416.113048] [<c0250fe0>] ? __kthread_unpark+0x40/0x40
[ 416.113048] ---[ end trace 053edd2998e0f96b ]---
[ 438.998238] block nbd12: Attempted send on closed socket


git bisect start v3.13 v3.12 --
git bisect good 3bad8bb5cd3048a67df43ac6b1e2f191f19d9ff0 # 12:35 300+ 46 Merge branch 'for-next' of git://git.samba.org/sfrench/cifs-2.6
git bisect bad dd0508093b79141e0044ca02f0acb6319f69f546 # 12:49 41- 1 Merge branch 'sched-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 3f02ff5c2c69753666787ed125708d283a823ffb # 13:07 93- 2 Merge tag 'tty-3.13-rc3' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/tty
git bisect good 1ab231b274ba51a54acebec23c6aded0f3cdf54e # 13:31 300+ 30 Merge branch 'timers-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 5ee540613db504a10e15fafaf4c08cac96aa1823 # 13:50 66- 5 Merge branch 'for-linus' of git://git.kernel.dk/linux-block
git bisect good 53c6de50262a8edd6932bb59a32db7b9d92f8d67 # 14:26 300+ 6 Merge branch 'x86/urgent' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 59fb2f0e9e30ad99a8bab0ff1efaf8f4a3b7105f # 14:50 300+ 57 Merge tag 'fbdev-fixes-3.13' of git://git.kernel.org/pub/scm/linux/kernel/git/tomba/linux
git bisect good ef1e4e32d595d3e6c9a6d3d2956f087d5886c5e5 # 15:17 300+ 32 Merge tag 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs
git bisect good 29be6345bbaec8502a70c4e2204d5818b48c4e8f # 19:00 300+ 40 Merge tag 'nfs-for-3.13-3' of git://git.linux-nfs.org/projects/trondmy/linux-nfs
git bisect bad e345d767f6530ec9cb0aabab7ea248072a9c6975 # 19:17 131- 8 Merge branch 'stable/for-jens-3.13-take-two' of git://git.kernel.org/pub/scm/linux/kernel/git/xen/tip into for-linus
git bisect bad c170bbb45febc03ac4d34ba2b8bb55e06104b7e7 # 19:33 15- 2 block: submit_bio_wait() conversions
git bisect bad 2c575026fae6e63771bd2a4c1d407214a8096a89 # 19:57 41- 2 Update of blkg_stat and blkg_rwstat may happen in bh context. While u64_stats_fetch_retry is only preempt_disable on 32bit UP system. This is not enough to avoid preemption by bh and may read strange 64 bit value.
# first bad commit: [2c575026fae6e63771bd2a4c1d407214a8096a89] Update of blkg_stat and blkg_rwstat may happen in bh context. While u64_stats_fetch_retry is only preempt_disable on 32bit UP system. This is not enough to avoid preemption by bh and may read strange 64 bit value.
git bisect good 82023bb7f75b0052f40d3e74169d191c3e4e6286 # 20:59 900+ 106 Merge tag 'pm+acpi-2-3.13-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
git bisect bad b1cce620fd4b6864c92e7307be7839789f9c8be0 # 20:59 0- 5 Add linux-next specific files for 20140612
git bisect bad 6d87c225f5d82d29243dc124f1ffcbb0e14ec358 # 21:29 89- 6 Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/sage/ceph-client
git bisect bad f9801c532e045c1ab89801d0597353c5e2a55671 # 21:58 113- 8 Add linux-next specific files for 20140613


This script may reproduce the error.

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

kernel=$1

kvm=(
qemu-system-x86_64 -cpu kvm64 -enable-kvm
-kernel $kernel
-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


Attachments:
dmesg-yocto-ivb42-41:20140613200222:i386-randconfig-tt0-06131036:3.12.0-10276-g2c57502:1 (60.56 kB)
Attached Message Part (86.00 B)
config-3.12.0-10276-g2c57502 (100.41 kB)
Download all attachments