* [BUG] INFO: inconsistent lock state
@ 2011-09-20 9:16 Srivatsa S. Bhat
2011-09-26 8:40 ` Paul Bolle
0 siblings, 1 reply; 12+ messages in thread
From: Srivatsa S. Bhat @ 2011-09-20 9:16 UTC (permalink / raw)
To: Linux PM mailing list; +Cc: linux-kernel, Rafael J. Wysocki
Hi,
While running kernel compilation along with suspend/resume
tests using the pm_test framework (at the processors level),
lockdep reports inconsistent lock state.
This is with Kernel 3.0.4.
Excerpt of the log:
kernel: [ 8221.176651] Freezing user space processes ... (elapsed 0.01 seconds) done.
kernel: [ 8221.247173] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
kernel: [ 8221.321962] PM: Preallocating image memory...
kernel: [ 8221.768104] =================================
kernel: [ 8221.806233] [ INFO: inconsistent lock state ]
kernel: [ 8221.842744] 3.0.4 #1
kernel: [ 8221.861076] ---------------------------------
kernel: [ 8221.897583] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
kernel: [ 8221.952270] test_processors/5971 [HC0[0]:SC0[0]:HE1:SE1] takes:
kernel: [ 8222.001872] (&sb->s_type->i_mutex_key#13){+.+.?.}, at: [<ffffffffa01262ee>] ext4_evict_inode+0x2e/0x3d0 [ext4]
kernel: [ 8222.086774] {RECLAIM_FS-ON-W} state was registered at:
kernel: [ 8222.129821] [<ffffffff810a6033>] mark_held_locks+0x73/0xa0
kernel: [ 8222.177316] [<ffffffff810a60ff>] lockdep_trace_alloc+0x9f/0xd0
kernel: [ 8222.227720] [<ffffffff81164dd6>] kmem_cache_alloc+0x36/0x1f0
kernel: [ 8222.276675] [<ffffffff81191927>] d_alloc+0x27/0x1d0
kernel: [ 8222.319078] [<ffffffff811864dd>] d_alloc_and_lookup+0x2d/0x90
kernel: [ 8222.368755] [<ffffffff81188473>] do_lookup+0x2b3/0x300
kernel: [ 8222.413340] [<ffffffff8118983f>] link_path_walk+0x18f/0x930
kernel: [ 8222.461564] [<ffffffff8118a665>] path_lookupat+0x55/0x690
kernel: [ 8222.508330] [<ffffffff8118acd1>] do_path_lookup+0x31/0xc0
kernel: [ 8222.555098] [<ffffffff8118b9c9>] user_path_at+0x59/0xa0
kernel: [ 8222.600413] [<ffffffff8118018c>] vfs_fstatat+0x4c/0x90
kernel: [ 8222.645001] [<ffffffff811802fb>] vfs_stat+0x1b/0x20
kernel: [ 8222.687397] [<ffffffff81180324>] sys_newstat+0x24/0x50
kernel: [ 8222.731986] [<ffffffff8152fa82>] system_call_fastpath+0x16/0x1b
kernel: [ 8222.783119] irq event stamp: 2109279487
kernel: [ 8222.815258] hardirqs last enabled at (2109279487): [<ffffffff81526fe0>] _raw_spin_unlock_irq+0x30/0x40
kernel: [ 8222.894087] hardirqs last disabled at (2109279486): [<ffffffff8152665f>] _raw_spin_lock_irq+0x1f/0x80
kernel: [ 8222.971464] softirqs last enabled at (2109279484): [<ffffffff8106ea7c>] __do_softirq+0x14c/0x250
kernel: [ 8223.045929] softirqs last disabled at (2109279461): [<ffffffff81530d3c>] call_softirq+0x1c/0x30
kernel: [ 8223.118941]
kernel: [ 8223.118942] other info that might help us debug this:
kernel: [ 8223.173776] Possible unsafe locking scenario:
kernel: [ 8223.173777]
kernel: [ 8223.223525] CPU0
kernel: [ 8223.244031] ----
kernel: [ 8223.264541] lock(&sb->s_type->i_mutex_key);
kernel: [ 8223.301204] <Interrupt>
kernel: [ 8223.323168] lock(&sb->s_type->i_mutex_key);
kernel: [ 8223.361284]
kernel: [ 8223.361285] *** DEADLOCK ***
kernel: [ 8223.361285]
kernel: [ 8223.411172] 5 locks held by test_processors/5971:
kernel: [ 8223.450586] #0: (&buffer->mutex){+.+.+.}, at: [<ffffffff811ee0a4>] sysfs_write_file+0x44/0x170
kernel: [ 8223.524561] #1: (s_active#79){.+.+.+}, at: [<ffffffff811ee12d>] sysfs_write_file+0xcd/0x170
kernel: [ 8223.596444] #2: (pm_mutex){+.+.+.}, at: [<ffffffff810b8a7c>] hibernate+0x1c/0x200
kernel: [ 8223.660968] #3: (shrinker_rwsem){++++..}, at: [<ffffffff8112b98d>] shrink_slab+0x3d/0x1b0
kernel: [ 8223.731320] #4: (iprune_sem){.+.+.-}, at: [<ffffffff81196cc1>] prune_icache+0x31/0x310
kernel: [ 8223.799493]
kernel: [ 8223.799493] stack backtrace:
kernel: [ 8223.836149] Pid: 5971, comm: test_processors Not tainted 3.0.4 #1
kernel: [ 8223.887194] Call Trace:
kernel: [ 8223.907706] [<ffffffff810a5439>] print_usage_bug+0x179/0x180
kernel: [ 8223.955846] [<ffffffff810a5440>] ? print_usage_bug+0x180/0x180
kernel: [ 8224.005444] [<ffffffff810a5aae>] mark_lock_irq+0xfe/0x290
kernel: [ 8224.051402] [<ffffffff810a5d91>] mark_lock+0x151/0x1f0
kernel: [ 8224.095182] [<ffffffff810a5ef6>] mark_irqflags+0xc6/0x190
kernel: [ 8224.141139] [<ffffffff810a7624>] __lock_acquire+0x344/0x4f0
kernel: [ 8224.188555] [<ffffffff810a7e84>] lock_acquire+0xa4/0x130
kernel: [ 8224.233792] [<ffffffffa01262ee>] ? ext4_evict_inode+0x2e/0x3d0 [ext4]
kernel: [ 8224.288477] [<ffffffff81524fed>] __mutex_lock_common+0x4d/0x3f0
kernel: [ 8224.338805] [<ffffffffa01262ee>] ? ext4_evict_inode+0x2e/0x3d0 [ext4]
kernel: [ 8224.393486] [<ffffffff810a190d>] ? trace_hardirqs_off+0xd/0x10
kernel: [ 8224.443082] [<ffffffff8109439f>] ? local_clock+0x6f/0x80
kernel: [ 8224.488323] [<ffffffffa01262ee>] ? ext4_evict_inode+0x2e/0x3d0 [ext4]
kernel: [ 8224.543012] [<ffffffff810a5865>] ? lock_release_holdtime+0x35/0x180
kernel: [ 8224.596243] [<ffffffff810a7c99>] ? __lock_release+0x129/0x190
kernel: [ 8224.645122] [<ffffffff811966d5>] ? evict+0x75/0x180
kernel: [ 8224.686721] [<ffffffff815254fa>] mutex_lock_nested+0x4a/0x60
kernel: [ 8224.734871] [<ffffffffa01262ee>] ext4_evict_inode+0x2e/0x3d0 [ext4]
kernel: [ 8224.788104] [<ffffffff811966e3>] evict+0x83/0x180
kernel: [ 8224.828248] [<ffffffff81196827>] dispose_list+0x47/0x60
kernel: [ 8224.872752] [<ffffffff81196de5>] prune_icache+0x155/0x310
kernel: [ 8224.918708] [<ffffffff81196fe6>] shrink_icache_memory+0x46/0x50
kernel: [ 8224.969034] [<ffffffff8112ba82>] shrink_slab+0x132/0x1b0
kernel: [ 8225.014268] [<ffffffff8112db02>] do_try_to_free_pages+0x2d2/0x3c0
kernel: [ 8225.066044] [<ffffffff8112dcad>] shrink_all_memory+0xbd/0xf0
kernel: [ 8225.114192] [<ffffffff81136d76>] ? next_online_pgdat+0x26/0x50
kernel: [ 8225.163789] [<ffffffff810ba6a5>] hibernate_preallocate_memory+0x1e5/0x2a0
kernel: [ 8225.221379] [<ffffffff810b896d>] hibernation_snapshot+0x8d/0x180
kernel: [ 8225.272424] [<ffffffff810b8b58>] hibernate+0xf8/0x200
kernel: [ 8225.315476] [<ffffffff810b6ffc>] state_store+0xec/0x100
kernel: [ 8225.359984] [<ffffffff8125f8b7>] kobj_attr_store+0x17/0x20
kernel: [ 8225.406670] [<ffffffff811ee146>] sysfs_write_file+0xe6/0x170
kernel: [ 8225.454809] [<ffffffff8117afd0>] vfs_write+0xd0/0x1a0
kernel: [ 8225.497856] [<ffffffff8117b1a4>] sys_write+0x54/0xa0
kernel: [ 8225.540180] [<ffffffff8152fa82>] system_call_fastpath+0x16/0x1b
kernel: [ 8226.890288] done (allocated 2511433 pages)
kernel: [ 8226.924630] PM: Allocated 10045732 kbytes in 5.54 seconds (1813.30 MB/s)
--
Regards,
Srivatsa S. Bhat <srivatsa.bhat@linux.vnet.ibm.com>
Linux Technology Center,
IBM India Systems and Technology Lab
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2011-09-20 9:16 [BUG] INFO: inconsistent lock state Srivatsa S. Bhat
@ 2011-09-26 8:40 ` Paul Bolle
2011-09-26 9:34 ` Paul Bolle
2011-09-26 9:51 ` Srivatsa S. Bhat
0 siblings, 2 replies; 12+ messages in thread
From: Paul Bolle @ 2011-09-26 8:40 UTC (permalink / raw)
To: Srivatsa S. Bhat; +Cc: Linux PM mailing list, linux-kernel, Rafael J. Wysocki
On Tue, 2011-09-20 at 14:46 +0530, Srivatsa S. Bhat wrote:
> While running kernel compilation along with suspend/resume
> tests using the pm_test framework (at the processors level),
> lockdep reports inconsistent lock state.
> This is with Kernel 3.0.4.
Something very similar happened to be in the logs of a machine running
v3.0.4 too. It happened a few days ago (but I missed it initially). I
have no idea what triggered this:
kernel: [ 3501.569697]
kernel: [ 3501.569699] =================================
kernel: [ 3501.569703] [ INFO: inconsistent lock state ]
kernel: [ 3501.569706] 3.0.4-local0.fc14.x86_64 #1
kernel: [ 3501.569708] ---------------------------------
kernel: [ 3501.569711] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
kernel: [ 3501.569714] kswapd0/25 [HC0[0]:SC0[0]:HE1:SE1] takes:
kernel: [ 3501.569717] (&sb->s_type->i_mutex_key#13){+.+.?.}, at: [<ffffffff811b08eb>] ext4_evict_inode+0x41/0x255
kernel: [ 3501.569728] {RECLAIM_FS-ON-W} state was registered at:
kernel: [ 3501.569730] [<ffffffff8108fcd1>] mark_held_locks+0x50/0x72
kernel: [ 3501.569736] [<ffffffff81090273>] lockdep_trace_alloc+0xa2/0xc6
kernel: [ 3501.569740] [<ffffffff811302da>] slab_pre_alloc_hook+0x1e/0x54
kernel: [ 3501.569745] [<ffffffff81132f3d>] kmem_cache_alloc+0x25/0x105
kernel: [ 3501.569749] [<ffffffff81155a26>] d_alloc+0x27/0x1b3
kernel: [ 3501.569754] [<ffffffff8114c785>] d_alloc_and_lookup+0x2c/0x6d
kernel: [ 3501.569758] [<ffffffff8114db93>] walk_component+0x1ea/0x3da
kernel: [ 3501.569762] [<ffffffff8114eda2>] link_path_walk+0x18a/0x477
kernel: [ 3501.569766] [<ffffffff8114f1a5>] path_lookupat+0x59/0x34b
kernel: [ 3501.569770] [<ffffffff8114f4c1>] do_path_lookup+0x2a/0x99
kernel: [ 3501.569774] [<ffffffff8114f8fb>] user_path_at+0x56/0x93
kernel: [ 3501.569778] [<ffffffff81147227>] vfs_fstatat+0x49/0x74
kernel: [ 3501.569782] [<ffffffff8114728d>] vfs_stat+0x1b/0x1d
kernel: [ 3501.569786] [<ffffffff811473a3>] sys_newstat+0x1f/0x39
kernel: [ 3501.569790] [<ffffffff814f62c2>] system_call_fastpath+0x16/0x1b
kernel: [ 3501.569796] irq event stamp: 2656001
kernel: [ 3501.569798] hardirqs last enabled at (2656001): [<ffffffff814efa54>] restore_args+0x0/0x30
kernel: [ 3501.569803] hardirqs last disabled at (2655999): [<ffffffff810632a8>] __do_softirq+0x15c/0x1ed
kernel: [ 3501.569809] softirqs last enabled at (2656000): [<ffffffff810632df>] __do_softirq+0x193/0x1ed
kernel: [ 3501.569813] softirqs last disabled at (2654505): [<ffffffff814f755c>] call_softirq+0x1c/0x30
kernel: [ 3501.569818]
kernel: [ 3501.569819] other info that might help us debug this:
kernel: [ 3501.569821] Possible unsafe locking scenario:
kernel: [ 3501.569822]
kernel: [ 3501.569824] CPU0
kernel: [ 3501.569826] ----
kernel: [ 3501.569827] lock(&sb->s_type->i_mutex_key);
kernel: [ 3501.569831] <Interrupt>
kernel: [ 3501.569833] lock(&sb->s_type->i_mutex_key);
kernel: [ 3501.569836]
kernel: [ 3501.569837] *** DEADLOCK ***
kernel: [ 3501.569837]
kernel: [ 3501.569840] 2 locks held by kswapd0/25:
kernel: [ 3501.569842] #0: (shrinker_rwsem){++++..}, at: [<ffffffff81101fc9>] shrink_slab+0x3d/0x189
kernel: [ 3501.569850] #1: (iprune_sem){++++.-}, at: [<ffffffff81158be2>] shrink_icache_memory+0x50/0x288
kernel: [ 3501.569857]
kernel: [ 3501.569858] stack backtrace:
kernel: [ 3501.569861] Pid: 25, comm: kswapd0 Not tainted 3.0.4-local0.fc14.x86_64 #1
kernel: [ 3501.569863] Call Trace:
kernel: [ 3501.569868] [<ffffffff8108e538>] valid_state+0x215/0x227
kernel: [ 3501.569873] [<ffffffff8108dd2e>] ? print_irq_inversion_bug+0x1c4/0x1c4
kernel: [ 3501.569876] [<ffffffff8108e62c>] mark_lock+0xe2/0x1d8
kernel: [ 3501.569880] [<ffffffff8108eafc>] __lock_acquire+0x3da/0xdd8
kernel: [ 3501.569885] [<ffffffff8108fcd1>] ? mark_held_locks+0x50/0x72
kernel: [ 3501.569889] [<ffffffff814efa54>] ? retint_restore_args+0x13/0x13
kernel: [ 3501.569892] [<ffffffff81158869>] ? evict+0x4f/0x127
kernel: [ 3501.569896] [<ffffffff8108fdfe>] ? trace_hardirqs_on_caller+0x10b/0x12f
kernel: [ 3501.569900] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
kernel: [ 3501.569904] [<ffffffff8108f9c6>] lock_acquire+0xb7/0xfb
kernel: [ 3501.569908] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
kernel: [ 3501.569912] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
kernel: [ 3501.569916] [<ffffffff814edb1f>] __mutex_lock_common+0x4c/0x361
kernel: [ 3501.569920] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
kernel: [ 3501.569924] [<ffffffff8108be8d>] ? trace_hardirqs_off+0xd/0xf
kernel: [ 3501.569928] [<ffffffff810802da>] ? local_clock+0x36/0x4d
kernel: [ 3501.569932] [<ffffffff8108c123>] ? lock_release_holdtime+0x54/0x5b
kernel: [ 3501.569936] [<ffffffff814edf43>] mutex_lock_nested+0x40/0x45
kernel: [ 3501.569940] [<ffffffff811b08eb>] ext4_evict_inode+0x41/0x255
kernel: [ 3501.569944] [<ffffffff81158899>] evict+0x7f/0x127
kernel: [ 3501.569947] [<ffffffff8115897f>] dispose_list+0x3e/0x50
kernel: [ 3501.569951] [<ffffffff81158dea>] shrink_icache_memory+0x258/0x288
kernel: [ 3501.569955] [<ffffffff81101fc9>] ? shrink_slab+0x3d/0x189
kernel: [ 3501.569958] [<ffffffff8110207e>] shrink_slab+0xf2/0x189
kernel: [ 3501.569962] [<ffffffff81104995>] balance_pgdat+0x2f7/0x5d3
kernel: [ 3501.569967] [<ffffffff81104f3f>] kswapd+0x2ce/0x314
kernel: [ 3501.569971] [<ffffffff8107a76a>] ? wake_up_bit+0x2a/0x2a
kernel: [ 3501.569975] [<ffffffff81104c71>] ? balance_pgdat+0x5d3/0x5d3
kernel: [ 3501.569978] [<ffffffff8107a25c>] kthread+0xa0/0xa8
kernel: [ 3501.569983] [<ffffffff8108fdfe>] ? trace_hardirqs_on_caller+0x10b/0x12f
kernel: [ 3501.569987] [<ffffffff814f7464>] kernel_thread_helper+0x4/0x10
kernel: [ 3501.569991] [<ffffffff814efa54>] ? retint_restore_args+0x13/0x13
kernel: [ 3501.569995] [<ffffffff8107a1bc>] ? __init_kthread_worker+0x5b/0x5b
kernel: [ 3501.569999] [<ffffffff814f7460>] ? gs_change+0x13/0x13
Paul Bolle
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2011-09-26 8:40 ` Paul Bolle
@ 2011-09-26 9:34 ` Paul Bolle
2011-09-26 9:51 ` Srivatsa S. Bhat
1 sibling, 0 replies; 12+ messages in thread
From: Paul Bolle @ 2011-09-26 9:34 UTC (permalink / raw)
To: Srivatsa S. Bhat; +Cc: Linux PM mailing list, linux-kernel, Rafael J. Wysocki
On Mon, 2011-09-26 at 10:40 +0200, Paul Bolle wrote:
> Something very similar happened to be in the logs of a machine running
> v3.0.4 too. It happened a few days ago (but I missed it initially). I
> have no idea what triggered this:
>
> kernel: [ 3501.569697]
> kernel: [ 3501.569699] =================================
> kernel: [ 3501.569703] [ INFO: inconsistent lock state ]
> kernel: [ 3501.569706] 3.0.4-local0.fc14.x86_64 #1
> kernel: [ 3501.569708] ---------------------------------
> kernel: [ 3501.569711] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
> kernel: [ 3501.569714] kswapd0/25 [HC0[0]:SC0[0]:HE1:SE1] takes:
> kernel: [ 3501.569717] (&sb->s_type->i_mutex_key#13){+.+.?.}, at: [<ffffffff811b08eb>] ext4_evict_inode+0x41/0x255
> [...]
A bit of background: ext4_evict_inode+0x41 should be the call to
mutex_lock() in ext4_evict_inode():
(gdb) disass /m ext4_evict_inode+48,+17
Dump of assembler code from 0xffffffff811b08da to 0xffffffff811b08eb:
193 mutex_lock(&inode->i_mutex);
0xffffffff811b08da <ext4_evict_inode+48>: lea 0x80(%rbx),%r12
0xffffffff811b08e1 <ext4_evict_inode+55>: xor %esi,%esi
0xffffffff811b08e3 <ext4_evict_inode+57>: mov %r12,%rdi
0xffffffff811b08e6 <ext4_evict_inode+60>: callq 0xffffffff814edf03 <mutex_lock_nested>
End of assembler dump.
That call to mutex_lock() and the following call to mutex_unlock() was
added by the backport of commit 2581fdc8 ("ext4: call ext4_ioend_wait
and ext4_flush_completed_IO in ext4_evict_inode") to v3.0 in the v3.0.4
patch.
Paul Bolle
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2011-09-26 8:40 ` Paul Bolle
2011-09-26 9:34 ` Paul Bolle
@ 2011-09-26 9:51 ` Srivatsa S. Bhat
1 sibling, 0 replies; 12+ messages in thread
From: Srivatsa S. Bhat @ 2011-09-26 9:51 UTC (permalink / raw)
To: Paul Bolle
Cc: Linux PM mailing list, linux-kernel, linux-ext4, linux-fsdevel,
Rafael J. Wysocki
On 09/26/2011 02:10 PM, Paul Bolle wrote:
> On Tue, 2011-09-20 at 14:46 +0530, Srivatsa S. Bhat wrote:
>> While running kernel compilation along with suspend/resume
>> tests using the pm_test framework (at the processors level),
>> lockdep reports inconsistent lock state.
>> This is with Kernel 3.0.4.
>
> Something very similar happened to be in the logs of a machine running
> v3.0.4 too. It happened a few days ago (but I missed it initially). I
> have no idea what triggered this:
>
> kernel: [ 3501.569697]
> kernel: [ 3501.569699] =================================
> kernel: [ 3501.569703] [ INFO: inconsistent lock state ]
> kernel: [ 3501.569706] 3.0.4-local0.fc14.x86_64 #1
> kernel: [ 3501.569708] ---------------------------------
> kernel: [ 3501.569711] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
> kernel: [ 3501.569714] kswapd0/25 [HC0[0]:SC0[0]:HE1:SE1] takes:
> kernel: [ 3501.569717] (&sb->s_type->i_mutex_key#13){+.+.?.}, at: [<ffffffff811b08eb>] ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569728] {RECLAIM_FS-ON-W} state was registered at:
> kernel: [ 3501.569730] [<ffffffff8108fcd1>] mark_held_locks+0x50/0x72
> kernel: [ 3501.569736] [<ffffffff81090273>] lockdep_trace_alloc+0xa2/0xc6
> kernel: [ 3501.569740] [<ffffffff811302da>] slab_pre_alloc_hook+0x1e/0x54
> kernel: [ 3501.569745] [<ffffffff81132f3d>] kmem_cache_alloc+0x25/0x105
> kernel: [ 3501.569749] [<ffffffff81155a26>] d_alloc+0x27/0x1b3
> kernel: [ 3501.569754] [<ffffffff8114c785>] d_alloc_and_lookup+0x2c/0x6d
> kernel: [ 3501.569758] [<ffffffff8114db93>] walk_component+0x1ea/0x3da
> kernel: [ 3501.569762] [<ffffffff8114eda2>] link_path_walk+0x18a/0x477
> kernel: [ 3501.569766] [<ffffffff8114f1a5>] path_lookupat+0x59/0x34b
> kernel: [ 3501.569770] [<ffffffff8114f4c1>] do_path_lookup+0x2a/0x99
> kernel: [ 3501.569774] [<ffffffff8114f8fb>] user_path_at+0x56/0x93
> kernel: [ 3501.569778] [<ffffffff81147227>] vfs_fstatat+0x49/0x74
> kernel: [ 3501.569782] [<ffffffff8114728d>] vfs_stat+0x1b/0x1d
> kernel: [ 3501.569786] [<ffffffff811473a3>] sys_newstat+0x1f/0x39
> kernel: [ 3501.569790] [<ffffffff814f62c2>] system_call_fastpath+0x16/0x1b
> kernel: [ 3501.569796] irq event stamp: 2656001
> kernel: [ 3501.569798] hardirqs last enabled at (2656001): [<ffffffff814efa54>] restore_args+0x0/0x30
> kernel: [ 3501.569803] hardirqs last disabled at (2655999): [<ffffffff810632a8>] __do_softirq+0x15c/0x1ed
> kernel: [ 3501.569809] softirqs last enabled at (2656000): [<ffffffff810632df>] __do_softirq+0x193/0x1ed
> kernel: [ 3501.569813] softirqs last disabled at (2654505): [<ffffffff814f755c>] call_softirq+0x1c/0x30
> kernel: [ 3501.569818]
> kernel: [ 3501.569819] other info that might help us debug this:
> kernel: [ 3501.569821] Possible unsafe locking scenario:
> kernel: [ 3501.569822]
> kernel: [ 3501.569824] CPU0
> kernel: [ 3501.569826] ----
> kernel: [ 3501.569827] lock(&sb->s_type->i_mutex_key);
> kernel: [ 3501.569831] <Interrupt>
> kernel: [ 3501.569833] lock(&sb->s_type->i_mutex_key);
> kernel: [ 3501.569836]
> kernel: [ 3501.569837] *** DEADLOCK ***
> kernel: [ 3501.569837]
> kernel: [ 3501.569840] 2 locks held by kswapd0/25:
> kernel: [ 3501.569842] #0: (shrinker_rwsem){++++..}, at: [<ffffffff81101fc9>] shrink_slab+0x3d/0x189
> kernel: [ 3501.569850] #1: (iprune_sem){++++.-}, at: [<ffffffff81158be2>] shrink_icache_memory+0x50/0x288
> kernel: [ 3501.569857]
> kernel: [ 3501.569858] stack backtrace:
> kernel: [ 3501.569861] Pid: 25, comm: kswapd0 Not tainted 3.0.4-local0.fc14.x86_64 #1
> kernel: [ 3501.569863] Call Trace:
> kernel: [ 3501.569868] [<ffffffff8108e538>] valid_state+0x215/0x227
> kernel: [ 3501.569873] [<ffffffff8108dd2e>] ? print_irq_inversion_bug+0x1c4/0x1c4
> kernel: [ 3501.569876] [<ffffffff8108e62c>] mark_lock+0xe2/0x1d8
> kernel: [ 3501.569880] [<ffffffff8108eafc>] __lock_acquire+0x3da/0xdd8
> kernel: [ 3501.569885] [<ffffffff8108fcd1>] ? mark_held_locks+0x50/0x72
> kernel: [ 3501.569889] [<ffffffff814efa54>] ? retint_restore_args+0x13/0x13
> kernel: [ 3501.569892] [<ffffffff81158869>] ? evict+0x4f/0x127
> kernel: [ 3501.569896] [<ffffffff8108fdfe>] ? trace_hardirqs_on_caller+0x10b/0x12f
> kernel: [ 3501.569900] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569904] [<ffffffff8108f9c6>] lock_acquire+0xb7/0xfb
> kernel: [ 3501.569908] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569912] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569916] [<ffffffff814edb1f>] __mutex_lock_common+0x4c/0x361
> kernel: [ 3501.569920] [<ffffffff811b08eb>] ? ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569924] [<ffffffff8108be8d>] ? trace_hardirqs_off+0xd/0xf
> kernel: [ 3501.569928] [<ffffffff810802da>] ? local_clock+0x36/0x4d
> kernel: [ 3501.569932] [<ffffffff8108c123>] ? lock_release_holdtime+0x54/0x5b
> kernel: [ 3501.569936] [<ffffffff814edf43>] mutex_lock_nested+0x40/0x45
> kernel: [ 3501.569940] [<ffffffff811b08eb>] ext4_evict_inode+0x41/0x255
> kernel: [ 3501.569944] [<ffffffff81158899>] evict+0x7f/0x127
> kernel: [ 3501.569947] [<ffffffff8115897f>] dispose_list+0x3e/0x50
> kernel: [ 3501.569951] [<ffffffff81158dea>] shrink_icache_memory+0x258/0x288
> kernel: [ 3501.569955] [<ffffffff81101fc9>] ? shrink_slab+0x3d/0x189
> kernel: [ 3501.569958] [<ffffffff8110207e>] shrink_slab+0xf2/0x189
> kernel: [ 3501.569962] [<ffffffff81104995>] balance_pgdat+0x2f7/0x5d3
> kernel: [ 3501.569967] [<ffffffff81104f3f>] kswapd+0x2ce/0x314
> kernel: [ 3501.569971] [<ffffffff8107a76a>] ? wake_up_bit+0x2a/0x2a
> kernel: [ 3501.569975] [<ffffffff81104c71>] ? balance_pgdat+0x5d3/0x5d3
> kernel: [ 3501.569978] [<ffffffff8107a25c>] kthread+0xa0/0xa8
> kernel: [ 3501.569983] [<ffffffff8108fdfe>] ? trace_hardirqs_on_caller+0x10b/0x12f
> kernel: [ 3501.569987] [<ffffffff814f7464>] kernel_thread_helper+0x4/0x10
> kernel: [ 3501.569991] [<ffffffff814efa54>] ? retint_restore_args+0x13/0x13
> kernel: [ 3501.569995] [<ffffffff8107a1bc>] ? __init_kthread_worker+0x5b/0x5b
> kernel: [ 3501.569999] [<ffffffff814f7460>] ? gs_change+0x13/0x13
Hi Paul,
The issue that you and I encountered seems to have some similarity with the one
reported in http://www.spinics.net/lists/linux-ext4/msg27273.html
I am wondering if this warning is also a false positive like that in XFS.
I am CC'ing the linux-ext4 and linux-fsdevel mailing lists.
--
Regards,
Srivatsa S. Bhat <srivatsa.bhat@linux.vnet.ibm.com>
Linux Technology Center,
IBM India Systems and Technology Lab
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 12:38 ` Zdenek Kabelac
@ 2009-01-07 12:16 ` Herbert Xu
0 siblings, 0 replies; 12+ messages in thread
From: Herbert Xu @ 2009-01-07 12:16 UTC (permalink / raw)
To: Zdenek Kabelac; +Cc: Li Zefan, David Miller, LKML, netdev
On Tue, Jan 06, 2009 at 12:38:55PM +0000, Zdenek Kabelac wrote:
>
> I've just tested the very latest build from git repository:
> (commit: 238c6d54830c624f34ac9cf123ac04aebfca5013)
You also need
commit ea319518ba3de282c13ae1cf4bf2215c5e03e67e
Author: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Fri Dec 26 15:08:55 2008 +0100
locking, percpu counters: introduce separate lock classes
Impact: fix lockdep false positives
Classify percpu_counter instances similar to regular lock objects --
that is, per instantiation site.
The networking code has increased its use of percpu_counters, which
leads to false positives if they are treated as a single class.
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Cheers,
--
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 2:34 Li Zefan
2009-01-06 10:18 ` Zdenek Kabelac
@ 2009-01-07 12:13 ` Herbert Xu
1 sibling, 0 replies; 12+ messages in thread
From: Herbert Xu @ 2009-01-07 12:13 UTC (permalink / raw)
To: Li Zefan; +Cc: davem, linux-kernel, netdev
Li Zefan <lizf@cn.fujitsu.com> wrote:
> I am using Linus' tree, and the top commit is:
>
> commit fe0bdec68b77020281dc814805edfe594ae89e0f
> Merge: 099e657... 5af75d8...
> Author: Linus Torvalds <torvalds@linux-foundation.org>
> Date: Sun Jan 4 16:32:11 2009 -0800
>
> Merge branch 'audit.b61' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>
> don't know how I triggered this, and not sure whom to CC, network related?
You need
commit ea319518ba3de282c13ae1cf4bf2215c5e03e67e
Author: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Fri Dec 26 15:08:55 2008 +0100
locking, percpu counters: introduce separate lock classes
Impact: fix lockdep false positives
Classify percpu_counter instances similar to regular lock objects --
that is, per instantiation site.
The networking code has increased its use of percpu_counters, which
leads to false positives if they are treated as a single class.
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
diff --git a/include/linux/percpu_counter.h b/include/linux/percpu_counter.h
index 9007ccd..96bdde3 100644
--- a/include/linux/percpu_counter.h
+++ b/include/linux/percpu_counter.h
@@ -30,8 +30,16 @@ struct percpu_counter {
#define FBC_BATCH (NR_CPUS*4)
#endif
-int percpu_counter_init(struct percpu_counter *fbc, s64 amount);
-int percpu_counter_init_irq(struct percpu_counter *fbc, s64 amount);
+int __percpu_counter_init(struct percpu_counter *fbc, s64 amount,
+ struct lock_class_key *key);
+
+#define percpu_counter_init(fbc, value) \
+ ({ \
+ static struct lock_class_key __key; \
+ \
+ __percpu_counter_init(fbc, value, &__key); \
+ })
+
void percpu_counter_destroy(struct percpu_counter *fbc);
void percpu_counter_set(struct percpu_counter *fbc, s64 amount);
void __percpu_counter_add(struct percpu_counter *fbc, s64 amount, s32 batch);
@@ -85,8 +93,6 @@ static inline int percpu_counter_init(struct percpu_counter *fbc, s64 amount)
return 0;
}
-#define percpu_counter_init_irq percpu_counter_init
-
static inline void percpu_counter_destroy(struct percpu_counter *fbc)
{
}
diff --git a/lib/percpu_counter.c b/lib/percpu_counter.c
index a866389..c7fe2e4 100644
--- a/lib/percpu_counter.c
+++ b/lib/percpu_counter.c
@@ -71,11 +71,11 @@ s64 __percpu_counter_sum(struct percpu_counter *fbc)
}
EXPORT_SYMBOL(__percpu_counter_sum);
-static struct lock_class_key percpu_counter_irqsafe;
-
-int percpu_counter_init(struct percpu_counter *fbc, s64 amount)
+int __percpu_counter_init(struct percpu_counter *fbc, s64 amount,
+ struct lock_class_key *key)
{
spin_lock_init(&fbc->lock);
+ lockdep_set_class(&fbc->lock, key);
fbc->count = amount;
fbc->counters = alloc_percpu(s32);
if (!fbc->counters)
@@ -87,17 +87,7 @@ int percpu_counter_init(struct percpu_counter *fbc, s64 amount)
#endif
return 0;
}
-EXPORT_SYMBOL(percpu_counter_init);
-
-int percpu_counter_init_irq(struct percpu_counter *fbc, s64 amount)
-{
- int err;
-
- err = percpu_counter_init(fbc, amount);
- if (!err)
- lockdep_set_class(&fbc->lock, &percpu_counter_irqsafe);
- return err;
-}
+EXPORT_SYMBOL(__percpu_counter_init);
void percpu_counter_destroy(struct percpu_counter *fbc)
{
diff --git a/lib/proportions.c b/lib/proportions.c
index 4f387a6..7367f2b 100644
--- a/lib/proportions.c
+++ b/lib/proportions.c
@@ -83,11 +83,11 @@ int prop_descriptor_init(struct prop_descriptor *pd, int shift)
pd->index = 0;
pd->pg[0].shift = shift;
mutex_init(&pd->mutex);
- err = percpu_counter_init_irq(&pd->pg[0].events, 0);
+ err = percpu_counter_init(&pd->pg[0].events, 0);
if (err)
goto out;
- err = percpu_counter_init_irq(&pd->pg[1].events, 0);
+ err = percpu_counter_init(&pd->pg[1].events, 0);
if (err)
percpu_counter_destroy(&pd->pg[0].events);
@@ -191,7 +191,7 @@ int prop_local_init_percpu(struct prop_local_percpu *pl)
spin_lock_init(&pl->lock);
pl->shift = 0;
pl->period = 0;
- return percpu_counter_init_irq(&pl->events, 0);
+ return percpu_counter_init(&pl->events, 0);
}
void prop_local_destroy_percpu(struct prop_local_percpu *pl)
diff --git a/mm/backing-dev.c b/mm/backing-dev.c
index f2e574d..f3b1258 100644
--- a/mm/backing-dev.c
+++ b/mm/backing-dev.c
@@ -220,7 +220,7 @@ int bdi_init(struct backing_dev_info *bdi)
bdi->max_prop_frac = PROP_FRAC_BASE;
for (i = 0; i < NR_BDI_STAT_ITEMS; i++) {
- err = percpu_counter_init_irq(&bdi->bdi_stat[i], 0);
+ err = percpu_counter_init(&bdi->bdi_stat[i], 0);
if (err)
goto err;
}
Cheers,
--
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt
^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 10:25 ` Li Zefan
2009-01-06 10:47 ` Zdenek Kabelac
2009-01-06 12:38 ` Zdenek Kabelac
@ 2009-01-06 13:53 ` Zdenek Kabelac
2 siblings, 0 replies; 12+ messages in thread
From: Zdenek Kabelac @ 2009-01-06 13:53 UTC (permalink / raw)
To: Li Zefan; +Cc: David Miller, LKML, netdev
Li Zefan napsal(a):
> Zdenek Kabelac wrote:
>> Li Zefan napsal(a):
>>> I am using Linus' tree, and the top commit is:
>>>
>>> commit fe0bdec68b77020281dc814805edfe594ae89e0f
>>> Merge: 099e657... 5af75d8...
>>> Author: Linus Torvalds <torvalds@linux-foundation.org>
>>> Date: Sun Jan 4 16:32:11 2009 -0800
>>>
>>> Merge branch 'audit.b61' of
>>> git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>>>
>>> don't know how I triggered this, and not sure whom to CC, network
>>> related?
>>>
>> I've got the similar one too: http://lkml.org/lkml/2009/1/3/55
>>
>
> So your box freezed and can do nothing but reset ?
>
> I was much luckier that this bug didn't do any harm to my box. :)
And here is another one slightly different:
=================================
[ INFO: inconsistent lock state ]
2.6.28 #103
---------------------------------
inconsistent {softirq-on-W} -> {in-softirq-W} usage.
S20sendsigs/2307 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&fbc->lock){-+..}, at: [<ffffffff803aace8>] __percpu_counter_add+0x58/0x80
{softirq-on-W} state was registered at:
[<ffffffff8026f85c>] __lock_acquire+0x3ac/0x1280
[<ffffffff802707c1>] lock_acquire+0x91/0xc0
[<ffffffff80538781>] _spin_lock+0x31/0x70
[<ffffffff803aad25>] __percpu_counter_sum+0x15/0x80
[<ffffffff80343ab1>] ext3_statfs+0x71/0x1a0
[<ffffffff802d8024>] vfs_statfs+0x74/0x90
[<ffffffff8031589b>] compat_sys_statfs64+0x7b/0xb0
[<ffffffff80231a48>] sysenter_dispatch+0x7/0x2c
[<ffffffffffffffff>] 0xffffffffffffffff
irq event stamp: 108
hardirqs last enabled at (108): [<ffffffff80538583>]
_spin_unlock_irqrestore+0x43/0x70
hardirqs last disabled at (107): [<ffffffff805388e0>]
_spin_lock_irqsave+0x20/0x90
softirqs last enabled at (0): [<ffffffff802432bd>] copy_process+0x30d/0x13d0
softirqs last disabled at (73): [<ffffffff8020d8bc>] call_softirq+0x1c/0x50
other info that might help us debug this:
6 locks held by S20sendsigs/2307:
#0: (&mm->mmap_sem){----}, at: [<ffffffff8053b3b2>] do_page_fault+0x122/0xa70
#1: (__pte_lockptr(page)){--..}, at: [<ffffffff802bc3dd>]
__do_fault+0x16d/0x420
#2: (rcu_read_lock){..--}, at: [<ffffffff804b2842>] net_rx_action+0x102/0x290
#3: (rcu_read_lock){..--}, at: [<ffffffff804ae4c0>]
netif_receive_skb+0x100/0x400
#4: (rcu_read_lock){..--}, at: [<ffffffff804d0080>]
ip_local_deliver_finish+0x40/0x260
#5: (slock-AF_INET/1){-+..}, at: [<ffffffff804f0bde>] tcp_v4_rcv+0x59e/0x840
stack backtrace:
Pid: 2307, comm: S20sendsigs Not tainted 2.6.28 #103
Call Trace:
<IRQ> [<ffffffff8026d31d>] print_usage_bug+0x17d/0x190
[<ffffffff8026ebf3>] mark_lock+0x523/0x840
[<ffffffff8026f9d5>] __lock_acquire+0x525/0x1280
[<ffffffff802707c1>] lock_acquire+0x91/0xc0
[<ffffffff803aace8>] ? __percpu_counter_add+0x58/0x80
[<ffffffff80538781>] _spin_lock+0x31/0x70
[<ffffffff803aace8>] ? __percpu_counter_add+0x58/0x80
[<ffffffff8026f25d>] ? trace_hardirqs_on+0xd/0x10
[<ffffffff803aace8>] __percpu_counter_add+0x58/0x80
[<ffffffff804f061d>] tcp_v4_destroy_sock+0x23d/0x260
[<ffffffff804d9be2>] inet_csk_destroy_sock+0x52/0x140
[<ffffffff804dd4b6>] tcp_done+0x46/0x80
[<ffffffff804f1880>] tcp_time_wait+0x70/0x230
[<ffffffff804e3ba7>] tcp_fin+0x117/0x200
[<ffffffff804e4261>] tcp_data_queue+0x261/0xd10
[<ffffffff80250c1b>] ? mod_timer+0x4b/0x60
[<ffffffff804e83f9>] tcp_rcv_state_process+0x6b9/0xa50
[<ffffffff804ef050>] tcp_v4_do_rcv+0xb0/0x240
[<ffffffff8053873b>] ? _spin_lock_nested+0x5b/0x70
[<ffffffff804f0bfe>] tcp_v4_rcv+0x5be/0x840
[<ffffffff804d0153>] ip_local_deliver_finish+0x113/0x260
[<ffffffff804d0080>] ? ip_local_deliver_finish+0x40/0x260
[<ffffffff804d032d>] ip_local_deliver+0x8d/0xa0
[<ffffffff804cf9a3>] ip_rcv_finish+0x133/0x390
[<ffffffff804cfe63>] ip_rcv+0x263/0x2f0
[<ffffffff804ae6ca>] netif_receive_skb+0x30a/0x400
[<ffffffff804ae4c0>] ? netif_receive_skb+0x100/0x400
[<ffffffff80212bb0>] ? nommu_map_single+0x0/0xa0
[<ffffffffa005f0ec>] cp_rx_poll+0x2ac/0x410 [8139cp]
[<ffffffff804b28bf>] net_rx_action+0x17f/0x290
[<ffffffff804b2842>] ? net_rx_action+0x102/0x290
[<ffffffff8024b13c>] __do_softirq+0x9c/0x180
[<ffffffff8020d8bc>] call_softirq+0x1c/0x50
[<ffffffff8020ec65>] do_softirq+0x75/0xc0
[<ffffffff8024ad95>] irq_exit+0x95/0xa0
[<ffffffff8020ef1a>] do_IRQ+0xba/0x1b0
[<ffffffff8020d113>] ret_from_intr+0x0/0xf
Zdenek
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 10:25 ` Li Zefan
2009-01-06 10:47 ` Zdenek Kabelac
@ 2009-01-06 12:38 ` Zdenek Kabelac
2009-01-07 12:16 ` Herbert Xu
2009-01-06 13:53 ` Zdenek Kabelac
2 siblings, 1 reply; 12+ messages in thread
From: Zdenek Kabelac @ 2009-01-06 12:38 UTC (permalink / raw)
To: Li Zefan; +Cc: David Miller, LKML, netdev
Li Zefan napsal(a):
> Zdenek Kabelac wrote:
>> Li Zefan napsal(a):
>>> I am using Linus' tree, and the top commit is:
>>>
>>> commit fe0bdec68b77020281dc814805edfe594ae89e0f
>>> Merge: 099e657... 5af75d8...
>>> Author: Linus Torvalds <torvalds@linux-foundation.org>
>>> Date: Sun Jan 4 16:32:11 2009 -0800
>>>
>>> Merge branch 'audit.b61' of
>>> git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>>>
>>> don't know how I triggered this, and not sure whom to CC, network
>>> related?
>>>
>> I've got the similar one too: http://lkml.org/lkml/2009/1/3/55
>>
>
> So your box freezed and can do nothing but reset ?
>
> I was much luckier that this bug didn't do any harm to my box. :)
>
I've just tested the very latest build from git repository:
(commit: 238c6d54830c624f34ac9cf123ac04aebfca5013)
And I still get this INFO trace - and this time my machine seems to be still
alive:
=================================
[ INFO: inconsistent lock state ]
2.6.28 #103
---------------------------------
inconsistent {softirq-on-W} -> {in-softirq-W} usage.
firefox/3196 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&fbc->lock){-+..}, at: [<ffffffff803aace8>] __percpu_counter_add+0x58/0x80
{softirq-on-W} state was registered at:
[<ffffffff8026f85c>] __lock_acquire+0x3ac/0x1280
[<ffffffff802707c1>] lock_acquire+0x91/0xc0
[<ffffffff80538781>] _spin_lock+0x31/0x70
[<ffffffff803aace8>] __percpu_counter_add+0x58/0x80
[<ffffffff802da20e>] get_empty_filp+0x7e/0x1a0
[<ffffffff802e4e26>] path_lookup_open+0x36/0xd0
[<ffffffff802e5ce8>] do_filp_open+0xb8/0x920
[<ffffffff802d6c98>] do_sys_open+0x78/0x100
[<ffffffff802d6d4b>] sys_open+0x1b/0x20
[<ffffffff8020c6db>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff
irq event stamp: 486132
hardirqs last enabled at (486132): [<ffffffff8026f2f2>]
debug_check_no_locks_freed+0x92/0x150
hardirqs last disabled at (486131): [<ffffffff8026f293>]
debug_check_no_locks_freed+0x33/0x150
softirqs last enabled at (486096): [<ffffffff804a25d5>] release_sock+0xd5/0xe0
softirqs last disabled at (486097): [<ffffffff8020d8bc>] call_softirq+0x1c/0x50
other info that might help us debug this:
5 locks held by firefox/3196:
#0: (rcu_read_lock){..--}, at: [<ffffffff804b2842>] net_rx_action+0x102/0x290
#1: (rcu_read_lock){..--}, at: [<ffffffff804ae4c0>]
netif_receive_skb+0x100/0x400
#2: (rcu_read_lock){..--}, at: [<ffffffff804d0080>]
ip_local_deliver_finish+0x40/0x260
#3: (slock-AF_INET/1){-+..}, at: [<ffffffff804f0bde>] tcp_v4_rcv+0x59e/0x840
#4: (slock-AF_INET){-+..}, at: [<ffffffff804a46de>] sk_clone+0xee/0x3b0
stack backtrace:
Pid: 3196, comm: firefox Not tainted 2.6.28 #103
Call Trace:
<IRQ> [<ffffffff8026d31d>] print_usage_bug+0x17d/0x190
[<ffffffff8026ebf3>] mark_lock+0x523/0x840
[<ffffffff8026f9d5>] __lock_acquire+0x525/0x1280
[<ffffffff802707c1>] lock_acquire+0x91/0xc0
[<ffffffff803aace8>] ? __percpu_counter_add+0x58/0x80
[<ffffffff80538781>] _spin_lock+0x31/0x70
[<ffffffff803aace8>] ? __percpu_counter_add+0x58/0x80
[<ffffffff803aace8>] __percpu_counter_add+0x58/0x80
[<ffffffff804a495e>] sk_clone+0x36e/0x3b0
[<ffffffff804d9ce1>] inet_csk_clone+0x11/0xa0
[<ffffffff804f140d>] tcp_create_openreq_child+0x1d/0x420
[<ffffffff804ef233>] tcp_v4_syn_recv_sock+0x53/0x1f0
[<ffffffff804f129b>] tcp_check_req+0x2ab/0x400
[<ffffffff804ef0f2>] tcp_v4_do_rcv+0x152/0x240
[<ffffffff804f0bfe>] tcp_v4_rcv+0x5be/0x840
[<ffffffff804d0153>] ip_local_deliver_finish+0x113/0x260
[<ffffffff804d0080>] ? ip_local_deliver_finish+0x40/0x260
[<ffffffff804d032d>] ip_local_deliver+0x8d/0xa0
[<ffffffff804cf9a3>] ip_rcv_finish+0x133/0x390
[<ffffffff804cfe63>] ip_rcv+0x263/0x2f0
[<ffffffff804ae6ca>] netif_receive_skb+0x30a/0x400
[<ffffffff804ae4c0>] ? netif_receive_skb+0x100/0x400
[<ffffffff804aee48>] napi_gro_receive+0x38/0x40
[<ffffffff804b15fa>] process_backlog+0x8a/0xe0
[<ffffffff804b2847>] ? net_rx_action+0x107/0x290
[<ffffffff804b28bf>] net_rx_action+0x17f/0x290
[<ffffffff804b2842>] ? net_rx_action+0x102/0x290
[<ffffffff8024b13c>] __do_softirq+0x9c/0x180
[<ffffffff8020d8bc>] call_softirq+0x1c/0x50
<EOI> [<ffffffff8020ec65>] do_softirq+0x75/0xc0
[<ffffffff804a25d5>] ? release_sock+0xd5/0xe0
[<ffffffff8024b666>] local_bh_enable_ip+0xf6/0x100
[<ffffffff805384df>] _spin_unlock_bh+0x2f/0x40
[<ffffffff804a25d5>] release_sock+0xd5/0xe0
[<ffffffff804fde14>] inet_stream_connect+0x64/0x2c0
[<ffffffff802d9f81>] ? fget_light+0x101/0x110
[<ffffffff802d9edd>] ? fget_light+0x5d/0x110
[<ffffffff804a0378>] sys_connect+0xb8/0xd0
[<ffffffff8020d1a9>] ? retint_swapgs+0xe/0x13
[<ffffffff8026f1ea>] ? trace_hardirqs_on_caller+0x16a/0x1d0
[<ffffffff802904be>] ? audit_syscall_entry+0x17e/0x1a0
[<ffffffff80538066>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[<ffffffff8020c6db>] system_call_fastpath+0x16/0x1b
Zdenek
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 10:25 ` Li Zefan
@ 2009-01-06 10:47 ` Zdenek Kabelac
2009-01-06 12:38 ` Zdenek Kabelac
2009-01-06 13:53 ` Zdenek Kabelac
2 siblings, 0 replies; 12+ messages in thread
From: Zdenek Kabelac @ 2009-01-06 10:47 UTC (permalink / raw)
To: Li Zefan; +Cc: David Miller, LKML, netdev
Li Zefan napsal(a):
> Zdenek Kabelac wrote:
>> Li Zefan napsal(a):
>>> I am using Linus' tree, and the top commit is:
>>>
>>> commit fe0bdec68b77020281dc814805edfe594ae89e0f
>>> Merge: 099e657... 5af75d8...
>>> Author: Linus Torvalds <torvalds@linux-foundation.org>
>>> Date: Sun Jan 4 16:32:11 2009 -0800
>>>
>>> Merge branch 'audit.b61' of
>>> git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>>>
>>> don't know how I triggered this, and not sure whom to CC, network
>>> related?
>>>
>> I've got the similar one too: http://lkml.org/lkml/2009/1/3/55
>>
>
> So your box freezed and can do nothing but reset ?
>
> I was much luckier that this bug didn't do any harm to my box. :)
Well the problem was that at the same time it has probably crashed my Xorg
server (with some recent rawhide version) and this might have been the reason
of hard crash as well - I'm not sure what was the exact order.
Zdenek
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 10:18 ` Zdenek Kabelac
@ 2009-01-06 10:25 ` Li Zefan
2009-01-06 10:47 ` Zdenek Kabelac
` (2 more replies)
0 siblings, 3 replies; 12+ messages in thread
From: Li Zefan @ 2009-01-06 10:25 UTC (permalink / raw)
To: Zdenek Kabelac; +Cc: David Miller, LKML, netdev
Zdenek Kabelac wrote:
> Li Zefan napsal(a):
>> I am using Linus' tree, and the top commit is:
>>
>> commit fe0bdec68b77020281dc814805edfe594ae89e0f
>> Merge: 099e657... 5af75d8...
>> Author: Linus Torvalds <torvalds@linux-foundation.org>
>> Date: Sun Jan 4 16:32:11 2009 -0800
>>
>> Merge branch 'audit.b61' of
>> git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>>
>> don't know how I triggered this, and not sure whom to CC, network
>> related?
>>
>
> I've got the similar one too: http://lkml.org/lkml/2009/1/3/55
>
So your box freezed and can do nothing but reset ?
I was much luckier that this bug didn't do any harm to my box. :)
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [BUG] INFO: inconsistent lock state
2009-01-06 2:34 Li Zefan
@ 2009-01-06 10:18 ` Zdenek Kabelac
2009-01-06 10:25 ` Li Zefan
2009-01-07 12:13 ` Herbert Xu
1 sibling, 1 reply; 12+ messages in thread
From: Zdenek Kabelac @ 2009-01-06 10:18 UTC (permalink / raw)
To: Li Zefan; +Cc: David Miller, LKML, netdev
Li Zefan napsal(a):
> I am using Linus' tree, and the top commit is:
>
> commit fe0bdec68b77020281dc814805edfe594ae89e0f
> Merge: 099e657... 5af75d8...
> Author: Linus Torvalds <torvalds@linux-foundation.org>
> Date: Sun Jan 4 16:32:11 2009 -0800
>
> Merge branch 'audit.b61' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
>
> don't know how I triggered this, and not sure whom to CC, network related?
>
I've got the similar one too: http://lkml.org/lkml/2009/1/3/55
Zdenek
^ permalink raw reply [flat|nested] 12+ messages in thread
* [BUG] INFO: inconsistent lock state
@ 2009-01-06 2:34 Li Zefan
2009-01-06 10:18 ` Zdenek Kabelac
2009-01-07 12:13 ` Herbert Xu
0 siblings, 2 replies; 12+ messages in thread
From: Li Zefan @ 2009-01-06 2:34 UTC (permalink / raw)
To: David Miller; +Cc: LKML, netdev
I am using Linus' tree, and the top commit is:
commit fe0bdec68b77020281dc814805edfe594ae89e0f
Merge: 099e657... 5af75d8...
Author: Linus Torvalds <torvalds@linux-foundation.org>
Date: Sun Jan 4 16:32:11 2009 -0800
Merge branch 'audit.b61' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/audit-current
don't know how I triggered this, and not sure whom to CC, network related?
=================================
[ INFO: inconsistent lock state ]
2.6.28 #483
---------------------------------
inconsistent {softirq-on-W} -> {in-softirq-W} usage.
swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&fbc->lock){-+..}, at: [<c05127a6>] __percpu_counter_add+0x52/0x7a
{softirq-on-W} state was registered at:
[<c044bcd2>] __lock_acquire+0x539/0x700
[<c044bef6>] lock_acquire+0x5d/0x7a
[<c061ca68>] _spin_lock+0x20/0x2f
[<c05127a6>] __percpu_counter_add+0x52/0x7a
[<c049d615>] get_empty_filp+0x97/0x135
[<c04a59c2>] path_lookup_open+0x23/0x7a
[<c04a5ac0>] do_filp_open+0xa7/0x659
[<c049af1d>] do_sys_open+0x49/0xbe
[<c049afde>] sys_open+0x23/0x2b
[<c040332a>] syscall_call+0x7/0xb
[<ffffffff>] 0xffffffff
irq event stamp: 3606392
hardirqs last enabled at (3606392): [<c061ce03>] _spin_unlock_irqrestore+0x3b/0x41
hardirqs last disabled at (3606391): [<c061cd31>] _spin_lock_irqsave+0x14/0x39
softirqs last enabled at (3606338): [<c0430aef>] __do_softirq+0x135/0x13d
softirqs last disabled at (3606369): [<c0404ab6>] do_softirq+0x6a/0xc0
other info that might help us debug this:
4 locks held by swapper/0:
#0: (rcu_read_lock){..--}, at: [<c05c3226>] net_rx_action+0x57/0x194
#1: (rcu_read_lock){..--}, at: [<c05c0a7b>] netif_receive_skb+0x123/0x2c3
#2: (rcu_read_lock){..--}, at: [<c05da9dc>] ip_local_deliver+0x4b/0x119
#3: (slock-AF_INET/1){-+..}, at: [<c05f1eec>] tcp_v4_rcv+0x237/0x50f
stack backtrace:
Pid: 0, comm: swapper Not tainted 2.6.28-mc #483
Call Trace:
[<c0449246>] print_usage_bug+0x155/0x161
[<c0449e2e>] mark_lock+0x34b/0x905
[<c044bc5a>] __lock_acquire+0x4c1/0x700
[<c044bef6>] lock_acquire+0x5d/0x7a
[<c05127a6>] ? __percpu_counter_add+0x52/0x7a
[<c061ca68>] _spin_lock+0x20/0x2f
[<c05127a6>] ? __percpu_counter_add+0x52/0x7a
[<c05127a6>] __percpu_counter_add+0x52/0x7a
[<c05f1403>] tcp_v4_destroy_sock+0x15d/0x165
[<c05e184b>] inet_csk_destroy_sock+0x8c/0xbd
[<c05e2a5d>] tcp_done+0x5e/0x61
[<c05eba12>] tcp_rcv_state_process+0x7b9/0x8ad
[<c05f1eec>] ? tcp_v4_rcv+0x237/0x50f
[<c05f0901>] tcp_v4_do_rcv+0x138/0x17d
[<c05f217d>] tcp_v4_rcv+0x4c8/0x50f
[<c05daa2d>] ip_local_deliver+0x9c/0x119
[<c05daeb5>] ip_rcv+0x40b/0x452
[<c05c0bd5>] netif_receive_skb+0x27d/0x2c3
[<f83f06f0>] rtl8169_rx_interrupt+0x2de/0x39a [r8169]
[<f83f1963>] rtl8169_poll+0x34/0x155 [r8169]
[<c05c3291>] net_rx_action+0xc2/0x194
[<c0430a44>] __do_softirq+0x8a/0x13d
[<c04309ba>] ? __do_softirq+0x0/0x13d
<IRQ> [<c046891f>] ? handle_fasteoi_irq+0x0/0xb5
[<c043098c>] ? irq_exit+0x49/0x77
[<c0404bbf>] ? do_IRQ+0xb3/0xcc
[<c04038ac>] ? common_interrupt+0x2c/0x34
[<c044007b>] ? hrtimer_get_next_event+0x55/0xc0
[<c0408541>] ? mwait_idle+0x41/0x4c
[<c0401dd0>] ? cpu_idle+0x78/0x91
[<c0617ad4>] ? start_secondary+0x193/0x198
^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2011-09-26 9:51 UTC | newest]
Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2011-09-20 9:16 [BUG] INFO: inconsistent lock state Srivatsa S. Bhat
2011-09-26 8:40 ` Paul Bolle
2011-09-26 9:34 ` Paul Bolle
2011-09-26 9:51 ` Srivatsa S. Bhat
-- strict thread matches above, loose matches on Subject: below --
2009-01-06 2:34 Li Zefan
2009-01-06 10:18 ` Zdenek Kabelac
2009-01-06 10:25 ` Li Zefan
2009-01-06 10:47 ` Zdenek Kabelac
2009-01-06 12:38 ` Zdenek Kabelac
2009-01-07 12:16 ` Herbert Xu
2009-01-06 13:53 ` Zdenek Kabelac
2009-01-07 12:13 ` Herbert Xu
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.