Date:	Mon, 21 Apr 2014 04:30:12 +0800
From:	Jet Chen <jet.chen@...el.com>
To:	Hong Zhiguo <zhiguohong@...cent.com>
CC:	Jens Axboe <axboe@...nel.dk>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	Fengguang Wu <fengguang.wu@...el.com>
Subject: [blk] WARNING: CPU: 0 PID: 300 at kernel/softirq.c:156 _local_bh_enable_ip()

Hi Zhiguo,

I 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 <zhiguohong@...cent.com>
AuthorDate: Wed Nov 20 10:35:05 2013 -0700
Commit:     Jens Axboe <axboe@...nel.dk>
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 <zhiguohong@...cent.com>
    Acked-by: Tejun Heo <tj@...nel.org>
    Cc: stable@...nel.org
    Signed-off-by: Jens Axboe <axboe@...nel.dk>



+-----------------------------------------------------------+------------+------------+
|                                                           | 82023bb7f7 | 2c575026fa |
+-----------------------------------------------------------+------------+------------+
| boot_successes                                            | 47         | 0          |
| boot_failures                                             | 13         | 20         |
| BUG:kernel_boot_hang                                      | 13         | 5          |
| inconsistent_IN-SOFTIRQ-W-SOFTIRQ-ON-W_usage              | 0          | 15         |
| backtrace:smpboot_thread_fn                               | 0          | 15         |
| backtrace:vfs_read                                        | 0          | 9          |
| backtrace:SyS_read                                        | 0          | 9          |
| WARNING:CPU:PID:at_kernel/softirq.c:_local_bh_enable_ip() | 0          | 7          |
| BUG:spinlock_lockup_suspected_on_CPU                      | 0          | 1          |
| backtrace:do_mount                                        | 0          | 6          |
| backtrace:SyS_mount                                       | 0          | 6          |
| backtrace:async_run_entry_fn                              | 0          | 0          |
+-----------------------------------------------------------+------------+------------+

[   12.318816] WARNING: CPU: 0 PID: 300 at kernel/softirq.c:156 _local_bh_enable_ip+0x34/0x97()
[   12.320012] CPU: 0 PID: 300 Comm: mount Not tainted 3.12.0-10878-g2c57502 #1
[   12.320012] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[   12.320012]  00000000 00000000 d0017b58 c0a2b528 d0017b70 c025daed c026085e c04efc4a
[   12.320012]  d1ff5044 d0017bdc d0017b80 c025db8a 00000009 00000000 d0017b8c c026085e
[   12.320012]  d0017bbc d0017b94 c02608cc d0017ba8 c04efc4a d1061140 d1ff4e10 d10242b0
[   12.320012] Call Trace:
[   12.320012]  [<c0a2b528>] dump_stack+0x16/0x18
[   12.320012]  [<c025daed>] warn_slowpath_common+0x50/0x67
[   12.320012]  [<c026085e>] ? _local_bh_enable_ip+0x34/0x97
[   12.320012]  [<c04efc4a>] ? blkg_rwstat_read+0x1d/0x24
[   12.320012]  [<c025db8a>] warn_slowpath_null+0xf/0x13
[   12.320012]  [<c026085e>] _local_bh_enable_ip+0x34/0x97
[   12.320012]  [<c02608cc>] local_bh_enable+0xb/0xd
[   12.320012]  [<c04efc4a>] blkg_rwstat_read+0x1d/0x24
[   12.320012]  [<c04f0f2c>] __cfq_set_active_queue+0x6b/0x188
[   12.320012]  [<c04f0760>] ? cfq_resort_rr_list+0x1f/0x23
[   12.320012]  [<c04ef459>] ? __arch_hweight32+0x8/0xa
[   12.320012]  [<c04f126f>] ? cfq_update_idle_window.isra.80+0x7d/0xe4
[   12.320012]  [<c024c11f>] ? kvm_clock_read+0x14/0x1d
[   12.320012]  [<c02329bc>] ? paravirt_sched_clock+0x9/0xd
[   12.320012]  [<c0232e67>] ? sched_clock+0x9/0xc
[   12.320012]  [<c0279714>] ? sched_clock_local.constprop.3+0xe/0x106
[   12.320012]  [<c04f367e>] cfq_dispatch_requests+0x528/0x7a8
[   12.320012]  [<c02329bc>] ? paravirt_sched_clock+0x9/0xd
[   12.320012]  [<c0232e67>] ? sched_clock+0x9/0xc
[   12.320012]  [<c04f26b0>] ? cfq_insert_request+0x18d/0x323
[   12.320012]  [<c0279902>] ? sched_clock_cpu+0xb8/0xc6
[   12.320012]  [<c02819f8>] ? trace_hardirqs_on+0xb/0xd
[   12.320012]  [<c0a34a8f>] ? _raw_spin_unlock_irq+0x27/0x30
[   12.320012]  [<c0281a9a>] ? trace_hardirqs_off+0xb/0xd
[   12.320012]  [<c04e0738>] blk_peek_request+0x57/0x180
[   12.320012]  [<c06007cf>] scsi_request_fn+0x38/0x42f
[   12.320012]  [<c04df0fc>] __blk_run_queue_uncond+0x21/0x2a
[   12.320012]  [<c04df118>] __blk_run_queue+0x13/0x15
[   12.320012]  [<c04e0ef9>] blk_queue_bio+0x1c7/0x1da
[   12.320012]  [<c04dfbf8>] generic_make_request+0x7f/0xb4
[   12.320012]  [<c04dfd02>] submit_bio+0xd5/0x107
[   12.320012]  [<c02f9872>] ? bio_alloc_bioset+0xb7/0x139
[   12.320012]  [<c02f782b>] _submit_bh+0x139/0x154
[   12.320012]  [<c02f7850>] submit_bh+0xa/0xc
[   12.320012]  [<c02f914c>] __bread+0x3e/0x59
[   12.320012]  [<c036ee6e>] ext4_fill_super+0x1c0/0x24d2
[   12.320012]  [<c04faec8>] ? string.isra.4+0x2d/0x92
[   12.320012]  [<c04ea741>] ? disk_name+0x20/0x65
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d96c8>] mount_bdev+0x12a/0x183
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d1013>] ? __kmalloc_track_caller+0x81/0xe2
[   12.320012]  [<c02ebd9d>] ? alloc_vfsmnt+0xe9/0x10f
[   12.320012]  [<c036b2e8>] ext4_mount+0x10/0x12
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d986b>] mount_fs+0xe/0x96
[   12.320012]  [<c02ec833>] vfs_kern_mount+0x40/0x9e
[   12.320012]  [<c02edc57>] do_mount+0x611/0x6f6
[   12.320012]  [<c02b900c>] ? strndup_user+0x2c/0x3d
[   12.320012]  [<c02edef4>] SyS_mount+0x71/0xa0
[   12.320012]  [<c0a35377>] syscall_call+0x7/0xb
[   12.320012] ---[ end trace 1790dec9013df875 ]---
[   12.320012]
[   12.320012] =================================
[   12.320012] [ INFO: inconsistent lock state ]
[   12.320012] 3.12.0-10878-g2c57502 #1 Tainted: G        W
[   12.320012] ---------------------------------
[   12.320012] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
[   12.320012] mount/300 [HC0[0]:SC0[0]:HE1:SE1] takes:
[   12.320012]  (&(&q->__queue_lock)->rlock){+.?...}, at: [<c04e0ed8>] blk_queue_bio+0x1a6/0x1da
[   12.320012] {IN-SOFTIRQ-W} state was registered at:
[   12.320012]   [<c0282acb>] __lock_acquire+0x27d/0xbfe
[   12.320012]   [<c02836d0>] lock_acquire+0x56/0x72
[   12.320012]   [<c0a348ae>] _raw_spin_lock+0x24/0x54
[   12.320012]   [<c06010b3>] scsi_device_unbusy+0x5b/0x7e
[   12.320012]   [<c05fc3ac>] scsi_finish_command+0x1d/0xc7
[   12.320012]   [<c0601294>] scsi_softirq_done+0xd6/0xde
[   12.320012]   [<c04e47ee>] blk_done_softirq+0x6e/0x77
[   12.320012]   [<c02606ac>] __do_softirq+0x94/0x16d
[   12.320012]   [<c02607a3>] run_ksoftirqd+0x1e/0x54
[   12.320012]   [<c0276b43>] smpboot_thread_fn+0x102/0x116
[   12.320012]   [<c0271c95>] kthread+0xa0/0xa5
[   12.320012]   [<c0a35a37>] ret_from_kernel_thread+0x1b/0x28
[   12.320012] irq event stamp: 2146
[   12.320012] hardirqs last  enabled at (2143): [<c0a34a8a>] _raw_spin_unlock_irq+0x22/0x30
[   12.320012] hardirqs last disabled at (2144): [<c0a34953>] _raw_spin_lock_irq+0x11/0x5e
[   12.320012] softirqs last  enabled at (2146): [<c04efc4a>] blkg_rwstat_read+0x1d/0x24
[   12.320012] softirqs last disabled at (2145): [<c04efc3e>] blkg_rwstat_read+0x11/0x24
[   12.320012]
[   12.320012] other info that might help us debug this:
[   12.320012]  Possible unsafe locking scenario:
[   12.320012]
[   12.320012]        CPU0
[   12.320012]        ----
[   12.320012]   lock(&(&q->__queue_lock)->rlock);
[   12.320012]   <Interrupt>
[   12.320012]     lock(&(&q->__queue_lock)->rlock);
[   12.320012]
[   12.320012]  *** DEADLOCK ***
[   12.320012]
[   12.320012] 2 locks held by mount/300:
[   12.320012]  #0:  (&type->s_umount_key#17/1){+.+.+.}, at: [<c02d8b1f>] sget+0x1e4/0x355
[   12.320012]  #1:  (&(&q->__queue_lock)->rlock){+.?...}, at: [<c04e0ed8>] blk_queue_bio+0x1a6/0x1da
[   12.320012]
[   12.320012] stack backtrace:
[   12.320012] CPU: 0 PID: 300 Comm: mount Tainted: G        W    3.12.0-10878-g2c57502 #1
[   12.320012] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[   12.320012]  00000000 d00935c0 d0017af4 c0a2b528 d0017b20 c0a27d03 c0d35294 c0d35193
[   12.320012]  c0d3515b c0d3517a c0d35184 c0d36010 d0093a44 c0281162 00000010 d0017b48
[   12.320012]  c028172e 00000006 00000000 d00935c0 00000004 00000006 d0093a44 d00935c0
[   12.320012] Call Trace:
[   12.320012]  [<c0a2b528>] dump_stack+0x16/0x18
[   12.320012]  [<c0a27d03>] print_usage_bug+0x180/0x18d
[   12.320012]  [<c0281162>] ? print_shortest_lock_dependencies+0x13c/0x13c
[   12.320012]  [<c028172e>] mark_lock+0xf7/0x1df
[   12.320012]  [<c0281871>] mark_held_locks+0x5b/0x72
[   12.320012]  [<c02608b9>] ? _local_bh_enable_ip+0x8f/0x97
[   12.320012]  [<c02819d3>] trace_hardirqs_on_caller+0x14b/0x165
[   12.320012]  [<c04efc4a>] ? blkg_rwstat_read+0x1d/0x24
[   12.320012]  [<c02819f8>] trace_hardirqs_on+0xb/0xd
[   12.320012]  [<c02608b9>] _local_bh_enable_ip+0x8f/0x97
[   12.320012]  [<c02608cc>] local_bh_enable+0xb/0xd
[   12.320012]  [<c04efc4a>] blkg_rwstat_read+0x1d/0x24
[   12.320012]  [<c04f0f2c>] __cfq_set_active_queue+0x6b/0x188
[   12.320012]  [<c04f0760>] ? cfq_resort_rr_list+0x1f/0x23
[   12.320012]  [<c04ef459>] ? __arch_hweight32+0x8/0xa
[   12.320012]  [<c04f126f>] ? cfq_update_idle_window.isra.80+0x7d/0xe4
[   12.320012]  [<c024c11f>] ? kvm_clock_read+0x14/0x1d
[   12.320012]  [<c02329bc>] ? paravirt_sched_clock+0x9/0xd
[   12.320012]  [<c0232e67>] ? sched_clock+0x9/0xc
[   12.320012]  [<c0279714>] ? sched_clock_local.constprop.3+0xe/0x106
[   12.320012]  [<c04f367e>] cfq_dispatch_requests+0x528/0x7a8
[   12.320012]  [<c02329bc>] ? paravirt_sched_clock+0x9/0xd
[   12.320012]  [<c0232e67>] ? sched_clock+0x9/0xc
[   12.320012]  [<c04f26b0>] ? cfq_insert_request+0x18d/0x323
[   12.320012]  [<c0279902>] ? sched_clock_cpu+0xb8/0xc6
[   12.320012]  [<c02819f8>] ? trace_hardirqs_on+0xb/0xd
[   12.320012]  [<c0a34a8f>] ? _raw_spin_unlock_irq+0x27/0x30
[   12.320012]  [<c0281a9a>] ? trace_hardirqs_off+0xb/0xd
[   12.320012]  [<c04e0738>] blk_peek_request+0x57/0x180
[   12.320012]  [<c06007cf>] scsi_request_fn+0x38/0x42f
[   12.320012]  [<c04df0fc>] __blk_run_queue_uncond+0x21/0x2a
[   12.320012]  [<c04df118>] __blk_run_queue+0x13/0x15
[   12.320012]  [<c04e0ef9>] blk_queue_bio+0x1c7/0x1da
[   12.320012]  [<c04dfbf8>] generic_make_request+0x7f/0xb4
[   12.320012]  [<c04dfd02>] submit_bio+0xd5/0x107
[   12.320012]  [<c02f9872>] ? bio_alloc_bioset+0xb7/0x139
[   12.320012]  [<c02f782b>] _submit_bh+0x139/0x154
[   12.320012]  [<c02f7850>] submit_bh+0xa/0xc
[   12.320012]  [<c02f914c>] __bread+0x3e/0x59
[   12.320012]  [<c036ee6e>] ext4_fill_super+0x1c0/0x24d2
[   12.320012]  [<c04faec8>] ? string.isra.4+0x2d/0x92
[   12.320012]  [<c04ea741>] ? disk_name+0x20/0x65
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d96c8>] mount_bdev+0x12a/0x183
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d1013>] ? __kmalloc_track_caller+0x81/0xe2
[   12.320012]  [<c02ebd9d>] ? alloc_vfsmnt+0xe9/0x10f
[   12.320012]  [<c036b2e8>] ext4_mount+0x10/0x12
[   12.320012]  [<c036ecae>] ? ext4_calculate_overhead+0x2df/0x2df
[   12.320012]  [<c02d986b>] mount_fs+0xe/0x96
[   12.320012]  [<c02ec833>] vfs_kern_mount+0x40/0x9e
[   12.320012]  [<c02edc57>] do_mount+0x611/0x6f6
[   12.320012]  [<c02b900c>] ? strndup_user+0x2c/0x3d
[   12.320012]  [<c02edef4>] SyS_mount+0x71/0xa0
[   12.320012]  [<c0a35377>] syscall_call+0x7/0xb



git bisect start v3.13 v3.12 --
git bisect good 3bad8bb5cd3048a67df43ac6b1e2f191f19d9ff0  # 15:26     20+      9  Merge branch 'for-next' of git://git.samba.org/sfrench/cifs-2.6
git bisect  bad 843f4f4bb1a2c4c196a1af1d18bb6477a580ac78  # 15:33      0-     12  Merge tag 'trace-fixes-3.13-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
git bisect good a45299e72737c528975546a0680cace5d7364d27  # 15:57     20+      3  Merge branch 'irq-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 09759d1e13e06c2f6346b1b3285fbde2c1e794c6  # 16:14     20+      1  Merge tag 'sound-3.13-rc3' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
git bisect  bad b52b342d31fecfeab0e2a256dfd84ea84954a8d3  # 16:20      0-      7  Merge branch 'stable' of git://git.kernel.org/pub/scm/linux/kernel/git/cmetcalf/linux-tile
git bisect good ef1e4e32d595d3e6c9a6d3d2956f087d5886c5e5  # 16:36     20+      6  Merge tag 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs
git bisect good 29be6345bbaec8502a70c4e2204d5818b48c4e8f  # 16:53     20+      4  Merge tag 'nfs-for-3.13-3' of git://git.linux-nfs.org/projects/trondmy/linux-nfs
git bisect  bad 5ee540613db504a10e15fafaf4c08cac96aa1823  # 17:00      0-      6  Merge branch 'for-linus' of git://git.kernel.dk/linux-block
git bisect  bad e345d767f6530ec9cb0aabab7ea248072a9c6975  # 17:08      0-      5  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  # 17:12      0-      1  block: submit_bio_wait() conversions
git bisect  bad 2c575026fae6e63771bd2a4c1d407214a8096a89  # 17:21      0-     12  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  # 17:42     60+     13  Merge tag 'pm+acpi-2-3.13-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
git bisect  bad 36efbdff85370263b2262022687c19ac7e7fe83e  # 17:42      0-     13  Add linux-next specific files for 20140417
git bisect  bad ebfc45ee7004088d610cd399d2dee6d95f87199b  # 17:50      0-     10  Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
git bisect  bad 36efbdff85370263b2262022687c19ac7e7fe83e  # 17:50      0-     13  Add linux-next specific files for 20140417

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[*]}"
-----------------------------------------------------------------------------

Attached dmesg for the parent commit, too, to help confirm whether it is a noise error.

Thanks,
Jet


View attachment "dmesg-yocto-lkp-ib04-1:20140419172117:i386-randconfig-x1-04191415:3.12.0-10878-g2c57502:1" of type "text/plain" (253747 bytes)

View attachment "dmesg-quantal-brickland3-142:20140419174037:i386-randconfig-x1-04191415:3.12.0-02794-g82023bb:2" of type "text/plain" (32152 bytes)

Download attachment "i386-randconfig-x1-04191415-36efbdff85370263b2262022687c19ac7e7fe83e-inconsistent----usage--27689.log" of type "application/octet-stream" (90021 bytes)

View attachment "config-3.12.0-10878-g2c57502" of type "text/plain" (87880 bytes)

Powered by blists - more mailing lists