[BUG] INFO: inconsistent lock state

linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed

* [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

* [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

* 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

* 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 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: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 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 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  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

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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).