Bug 13068

On Sunday 19 April 2009, Sachin Sant wrote:
> Rafael J. Wysocki wrote:
> > Bug-Entry   : http://bugzilla.kernel.org/show_bug.cgi?id=13068
> > Subject             : Lockdep warining in inotify_dev_queue_event
> > Submitter   : Sachin Sant <sachinp@in.ibm.com>
> > Date                : 2009-04-05 12:37 (12 days old)
> > References  : http://marc.info/?l=linux-kernel&m=123893439229272&w=4
> >   
> I can recreate this with latest kernel. Easiest way is to use the LTP mm 
> tests (runltp -f mm )
> 
> =================================
> [ INFO: inconsistent lock state ]
> 2.6.30-rc2-git4 #4
> ---------------------------------
> inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
> kswapd0/334 [HC0[0]:SC0[0]:HE1:SE1] takes:
>  (&inode->inotify_mutex){+.+.?.}, at: [<c000000000166cc0>] 
> .inotify_inode_is_dead+0x38/0xc8
> {RECLAIM_FS-ON-W} state was registered at:
>   [<c000000000098d74>] .lockdep_trace_alloc+0xc4/0xf4
>   [<c000000000122128>] .__kmalloc+0x100/0x274
>   [<c0000000001682fc>] .kernel_event+0xb8/0x154
>   [<c0000000001684b8>] .inotify_dev_queue_event+0x120/0x1cc
>   [<c000000000166b2c>] .inotify_inode_queue_event+0xf0/0x160
>   [<c000000000139c08>] .vfs_create+0x170/0x1dc
>   [<c00000000013d5c0>] .do_filp_open+0x25c/0x964
>   [<c00000000012b414>] .do_sys_open+0x80/0x140
>   [<c00000000012b2f0>] .SyS_creat+0x18/0x2c
>   [<c000000000008554>] syscall_exit+0x0/0x40
> irq event stamp: 75815
> hardirqs last  enabled at (75815): [<c0000000000cb824>] 
> .__call_rcu+0x128/0x15c
> hardirqs last disabled at (75814): [<c0000000000cb748>] 
> .__call_rcu+0x4c/0x15c
> softirqs last  enabled at (73084): [<c00000000002be8c>] 
> .call_do_softirq+0x14/0x24
> softirqs last disabled at (73071): [<c00000000002be8c>] 
> .call_do_softirq+0x14/0x24
> 
> other info that might help us debug this:
> 2 locks held by kswapd0/334:
>  #0:  (shrinker_rwsem){++++..}, at: [<c0000000000f57c8>] 
> .shrink_slab+0x5c/0x228
>  #1:  (&type->s_umount_key#15){++++..}, at: [<c000000000142f00>] 
> .shrink_dcache_memory+0xfc/0x244
> 
> stack backtrace:
> Call Trace:
> [c00000004473b440] [c000000000011a54] .show_stack+0x6c/0x16c (unreliable)
> [c00000004473b4f0] [c0000000000984d8] .print_usage_bug+0x1c0/0x1f4
> [c00000004473b5b0] [c00000000009888c] .mark_lock+0x380/0x6e4
> [c00000004473b660] [c00000000009a99c] .__lock_acquire+0x7a8/0x17b4
> [c00000004473b760] [c00000000009bab0] .lock_acquire+0x108/0x154
> [c00000004473b820] [c0000000005a8bac] .mutex_lock_nested+0x88/0x460
> [c00000004473b920] [c000000000166cc0] .inotify_inode_is_dead+0x38/0xc8
> [c00000004473b9d0] [c0000000001427f4] .dentry_iput+0xa0/0x128
> [c00000004473ba60] [c0000000001429f0] .d_kill+0x5c/0xa0
> [c00000004473baf0] [c000000000142d38] .__shrink_dcache_sb+0x304/0x3d0
> [c00000004473bbd0] [c000000000142f48] .shrink_dcache_memory+0x144/0x244
> [c00000004473bcb0] [c0000000000f58c8] .shrink_slab+0x15c/0x228
> [c00000004473bd70] [c0000000000f61a4] .kswapd+0x4c0/0x678
> [c00000004473bf00] [c000000000088ba4] .kthread+0x80/0xcc
> [c00000004473bf90] [c00000000002c194] .kernel_thread+0x54/0x70

On Wednesday 22 April 2009, you wrote:
> Rafael J. Wysocki wrote:
> > This message has been generated automatically as a part of a report
> > of recent regressions.
> >
> > The following bug entry is on the current list of known regressions
> > from 2.6.29.  Please verify if it still should be listed and let me know
> > (either way).
> >
> >
> > Bug-Entry   : http://bugzilla.kernel.org/show_bug.cgi?id=13068
> > Subject             : Lockdep warining in inotify_dev_queue_event
> > Submitter   : Sachin Sant <sachinp@in.ibm.com>
> > Date                : 2009-04-05 12:37 (12 days old)
> > References  : http://marc.info/?l=linux-kernel&m=123893439229272&w=4
> I can recreate this with 2.6.30-rc3 as well.
> 
> =================================
> [ INFO: inconsistent lock state ]
> 2.6.30-rc3 #1
> ---------------------------------
> inconsistent {IN-RECLAIM_FS-W} -> {RECLAIM_FS-ON-W} usage.
> inotify02/31550 [HC0[0]:SC0[0]:HE1:SE1] takes:
>  (&inode->inotify_mutex){+.+.?.}, at: [<c0000000001668ec>] 
> .inotify_inode_queue_event+0x6c/0x160
> {IN-RECLAIM_FS-W} state was registered at:
>   [<c00000000009bb1c>] .lock_acquire+0x108/0x154
>   [<c0000000005a8be4>] .mutex_lock_nested+0x88/0x460
>   [<c000000000166b04>] .inotify_inode_is_dead+0x38/0xc8
>   [<c000000000142708>] .dentry_iput+0xa0/0x128
>   [<c000000000142904>] .d_kill+0x5c/0xa0
>   [<c000000000142c4c>] .__shrink_dcache_sb+0x304/0x3d0
>   [<c000000000142e5c>] .shrink_dcache_memory+0x144/0x244
>   [<c0000000000f580c>] .shrink_slab+0x15c/0x228
>   [<c0000000000f60f8>] .kswapd+0x4c4/0x67c
>   [<c000000000088ba4>] .kthread+0x80/0xcc
>   [<c00000000002c194>] .kernel_thread+0x54/0x70
> irq event stamp: 2267
> hardirqs last  enabled at (2267): [<c000000000120490>] 
> .kmem_cache_alloc+0xec/0x1b4
> hardirqs last disabled at (2266): [<c000000000120418>] 
> .kmem_cache_alloc+0x74/0x1b4
> softirqs last  enabled at (1654): [<c00000000002be8c>] 
> .call_do_softirq+0x14/0x24
> softirqs last disabled at (1639): [<c00000000002be8c>] 
> .call_do_softirq+0x14/0x24
> 
> other info that might help us debug this:
> 4 locks held by inotify02/31550:
>  #0:  (&type->i_mutex_dir_key#4){+.+.+.}, at: [<c00000000013d41c>] 
> .do_filp_open+0x1a4/0x964
>  #1:  (&inode->inotify_mutex){+.+.?.}, at: [<c0000000001668ec>] 
> .inotify_inode_queue_event+0x6c/0x160
>  #2:  (&ih->mutex){+.+...}, at: [<c000000000166920>] 
> .inotify_inode_queue_event+0xa0/0x160
>  #3:  (&dev->ev_mutex){+.+...}, at: [<c00000000016822c>] 
> .inotify_dev_queue_event+0x50/0x1cc
> 
> stack backtrace:
> Call Trace:
> [c00000001816b4b0] [c000000000011a54] .show_stack+0x6c/0x16c (unreliable)
> [c00000001816b560] [c000000000098544] .print_usage_bug+0x1c0/0x1f4
> [c00000001816b620] [c0000000000988f8] .mark_lock+0x380/0x6e4
> [c00000001816b6d0] [c000000000098cd0] .mark_held_locks+0x74/0xc0
> [c00000001816b770] [c000000000098de0] .lockdep_trace_alloc+0xc4/0xf4
> [c00000001816b7f0] [c000000000122090] .__kmalloc+0x100/0x274
> [c00000001816b8a0] [c000000000168140] .kernel_event+0xb8/0x154
> [c00000001816b940] [c0000000001682fc] .inotify_dev_queue_event+0x120/0x1cc
> [c00000001816b9f0] [c000000000166970] .inotify_inode_queue_event+0xf0/0x160
> [c00000001816bac0] [c000000000139acc] .vfs_create+0x170/0x1dc
> [c00000001816bb60] [c00000000013d4d4] .do_filp_open+0x25c/0x964
> [c00000001816bd10] [c00000000012b37c] .do_sys_open+0x80/0x140
> [c00000001816bdc0] [c00000000012b258] .SyS_creat+0x18/0x2c
> [c00000001816be30] [c000000000008554] syscall_exit+0x0/0x40

On Wednesday 29 April 2009, Sachin Sant wrote:
> Rafael J. Wysocki wrote:
> > This message has been generated automatically as a part of a report
> > of recent regressions.
> >
> > The following bug entry is on the current list of known regressions
> > from 2.6.29.  Please verify if it still should be listed and let me know
> > (either way).
> >
> >
> > Bug-Entry   : http://bugzilla.kernel.org/show_bug.cgi?id=13068
> > Subject             : Lockdep warining in inotify_dev_queue_event
> > Submitter   : Sachin Sant <sachinp@in.ibm.com>
> > Date                : 2009-04-05 12:37 (21 days old)
> > References  : http://marc.info/?l=linux-kernel&m=123893439229272&w=4
> >
> >
> >   
> I have not been able to recreate this problem with recent 
> kernels(rc3-git's).

On Wednesday 29 April 2009, you wrote:
> Rafael J. Wysocki pisze:
> > On Wednesday 29 April 2009, Sachin Sant wrote:
> >> Rafael J. Wysocki wrote:
> >>> This message has been generated automatically as a part of a report
> >>> of recent regressions.
> >>>
> >>> The following bug entry is on the current list of known regressions
> >>> from 2.6.29.  Please verify if it still should be listed and let me know
> >>> (either way).
> >>>
> >>>
> >>> Bug-Entry : http://bugzilla.kernel.org/show_bug.cgi?id=13068
> >>> Subject           : Lockdep warining in inotify_dev_queue_event
> >>> Submitter : Sachin Sant <sachinp@in.ibm.com>
> >>> Date              : 2009-04-05 12:37 (21 days old)
> >>> References        :
> http://marc.info/?l=linux-kernel&m=123893439229272&w=4
> >>>
> >>>
> >>>   
> >> I have not been able to recreate this problem with recent 
> >> kernels(rc3-git's).
> > 
> > Thanks, I've closed the bug.
> 
> Was it really fixed? I'm on 56a50adda49b2020156616c4eb15353e0f9ad7de and
> still seeing this warning.
> 
> [ 2771.164306]
> [ 2771.164309] =================================
> [ 2771.164323] [ INFO: inconsistent lock state ]
> [ 2771.164329] 2.6.30-rc3-mod-56a50adda #121
> [ 2771.164333] ---------------------------------
> [ 2771.164338] inconsistent {IN-RECLAIM_FS-W} -> {RECLAIM_FS-ON-W} usage.
> [ 2771.164344] emerge/14418 [HC0[0]:SC0[0]:HE1:SE1] takes:
> [ 2771.164349]  (&inode->inotify_mutex){+.+.?.}, at: [<ffffffff802c2d25>]
> inotify_inode_queue_event+0x4f/0xe0
> [ 2771.164367] {IN-RECLAIM_FS-W} state was registered at:
> [ 2771.164371]   [<ffffffff80254f5f>] __lock_acquire+0x618/0x7b1
> [ 2771.164382]   [<ffffffff802551e7>] lock_acquire+0xef/0x111
> [ 2771.164390]   [<ffffffff805beef7>] mutex_lock_nested+0x5a/0x2da
> [ 2771.164399]   [<ffffffff802c2e19>] inotify_inode_is_dead+0x29/0x8f
> [ 2771.164407]   [<ffffffff802a9bdd>] dentry_iput+0x7c/0xbb
> [ 2771.164416]   [<ffffffff802a9d01>] d_kill+0x41/0x62
> [ 2771.164423]   [<ffffffff802a9f2e>] __shrink_dcache_sb+0x20c/0x2af
> [ 2771.164433]   [<ffffffff802aa0de>] shrink_dcache_memory+0xfe/0x18e
> [ 2771.164440]   [<ffffffff8027db03>] shrink_slab+0xe2/0x176
> [ 2771.164448]   [<ffffffff8027e2e5>] kswapd+0x35c/0x542
> [ 2771.164455]   [<ffffffff80245550>] kthread+0x50/0x7c
> [ 2771.164465]   [<ffffffff8020bd6a>] child_rip+0xa/0x20
> [ 2771.164473]   [<ffffffffffffffff>] 0xffffffffffffffff
> [ 2771.164481] irq event stamp: 5964095
> [ 2771.164484] hardirqs last  enabled at (5964095): [<ffffffff80296ef7>]
> kmem_cache_alloc+0x9a/0x138
> [ 2771.164495] hardirqs last disabled at (5964094): [<ffffffff80296a30>]
> __slab_alloc+0x349/0x5c6
> [ 2771.164504] softirqs last  enabled at (5962724): [<ffffffff80236ac6>]
> __do_softirq+0x1be/0x1ca
> [ 2771.164514] softirqs last disabled at (5962715): [<ffffffff8020be6a>]
> call_softirq+0x1a/0x24
> [ 2771.164522]
> [ 2771.164523] other info that might help us debug this:
> [ 2771.164529] 4 locks held by emerge/14418:
> [ 2771.164533]  #0:  (&type->i_mutex_dir_key#2){+.+.+.}, at:
> [<ffffffff802a60ce>] do_filp_open+0x183/0x7d0
> [ 2771.164550]  #1:  (&inode->inotify_mutex){+.+.?.}, at:
> [<ffffffff802c2d25>] inotify_inode_queue_event+0x4f/0xe0
> [ 2771.164567]  #2:  (&ih->mutex){+.+...}, at: [<ffffffff802c2d53>]
> inotify_inode_queue_event+0x7d/0xe0
> [ 2771.164582]  #3:  (&dev->ev_mutex){+.+...}, at: [<ffffffff802c3d7c>]
> inotify_dev_queue_event+0x36/0x15b
> [ 2771.164598]
> [ 2771.164599] stack backtrace:
> [ 2771.164606] Pid: 14418, comm: emerge Not tainted 2.6.30-rc3-mod-56a50adda
> #121
> [ 2771.164611] Call Trace:
> [ 2771.164617]  [<ffffffff8025233e>] print_usage_bug+0x1b8/0x1c9
> [ 2771.164623]  [<ffffffff80253574>] ? check_usage_backwards+0x0/0x9f
> [ 2771.164629]  [<ffffffff80252632>] mark_lock+0x2e3/0x546
> [ 2771.164635]  [<ffffffff802528e2>] mark_held_locks+0x4d/0x6a
> [ 2771.164641]  [<ffffffff80252df6>] lockdep_trace_alloc+0xa6/0xbf
> [ 2771.164647]  [<ffffffff802c3cdc>] ? kernel_event+0xa9/0x113
> [ 2771.164653]  [<ffffffff8029826a>] __kmalloc+0xc2/0x1db
> [ 2771.164660]  [<ffffffff802c3cdc>] kernel_event+0xa9/0x113
> [ 2771.164666]  [<ffffffff802c3e26>] inotify_dev_queue_event+0xe0/0x15b
> [ 2771.164673]  [<ffffffff802c2d81>] inotify_inode_queue_event+0xab/0xe0
> [ 2771.164679]  [<ffffffff802a3655>] vfs_create+0xf6/0x119
> [ 2771.164685]  [<ffffffff802b1fca>] ? mnt_want_write+0x26/0xa4
> [ 2771.164691]  [<ffffffff802a618c>] do_filp_open+0x241/0x7d0
> [ 2771.164697]  [<ffffffff802aeaa6>] ? alloc_fd+0xfe/0x10d
> [ 2771.164704]  [<ffffffff8022c2bf>] ? sub_preempt_count+0xa0/0xbd
> [ 2771.164710]  [<ffffffff805c0f03>] ? _spin_unlock+0x30/0x49
> [ 2771.164716]  [<ffffffff80299282>] do_sys_open+0x53/0xda
> [ 2771.164722]  [<ffffffff80299332>] sys_open+0x1b/0x1d
> [ 2771.164728]  [<ffffffff8020ae68>] system_call_fastpath+0x16/0x1b

Notify-Also : Marcin Slusarz <marcin.slusarz@gmail.com>

On Wednesday 06 May 2009, Németh Márton wrote:
> Hi,
> 
> I get this error recently while I was compiling kernel on ext3 fs. The kernel
> was running on a Clevo D410J laptop.
> 
> I don't know whether this is reproducible or not, but maybe this info is
> enough
> for somebody. I can send the full dmesg/.config or anything which is needed.
> 
> [ 1771.878353]
> [ 1771.878358] =================================
> [ 1771.878364] [ INFO: inconsistent lock state ]
> [ 1771.878369] 2.6.30-rc4 #1
> [ 1771.878372] ---------------------------------
> [ 1771.878376] inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
> [ 1771.878381] kswapd0/183 [HC0[0]:SC0[0]:HE1:SE1] takes:
> [ 1771.878385]  (&inode->inotify_mutex){+.+.?.}, at: [<c01cc03b>]
> inotify_inode_is_dead+0x1b/0x80
> [ 1771.878399] {RECLAIM_FS-ON-W} state was registered at:
> [ 1771.878402]   [<c014b7d2>] mark_held_locks+0x62/0x80
> [ 1771.878410]   [<c014b8b5>] lockdep_trace_alloc+0xc5/0xd0
> [ 1771.878415]   [<c019caf0>] __kmalloc+0x70/0x230
> [ 1771.878422]   [<c01ccfa7>] kernel_event+0x87/0x130
> [ 1771.878427]   [<c01cd0cf>] inotify_dev_queue_event+0x7f/0x180
> [ 1771.878432]   [<c01cbf53>] inotify_inode_queue_event+0xa3/0xe0
> [ 1771.878437]   [<c01a900a>] vfs_create+0xba/0x100
> [ 1771.878443]   [<c01ac14d>] do_filp_open+0x6dd/0x810
> [ 1771.878449]   [<c019e339>] do_sys_open+0x59/0xf0
> [ 1771.878454]   [<c019e439>] sys_open+0x29/0x40
> [ 1771.878459]   [<c0102e84>] sysenter_do_call+0x12/0x32
> [ 1771.878465]   [<ffffffff>] 0xffffffff
> [ 1771.878490] irq event stamp: 315803
> [ 1771.878493] hardirqs last  enabled at (315803): [<c016ae34>]
> call_rcu+0xb4/0xe0
> [ 1771.878501] hardirqs last disabled at (315802): [<c016ad9e>]
> call_rcu+0x1e/0xe0
> [ 1771.878508] softirqs last  enabled at (315442): [<c012b80f>]
> __do_softirq+0x15f/0x1e0
> [ 1771.878516] softirqs last disabled at (315435): [<c012b8ed>]
> do_softirq+0x5d/0x70
> [ 1771.878522]
> [ 1771.878523] other info that might help us debug this:
> [ 1771.878527] 2 locks held by kswapd0/183:
> [ 1771.878530]  #0:  (shrinker_rwsem){++++..}, at: [<c0182bf4>]
> shrink_slab+0x24/0x1a0
> [ 1771.878540]  #1:  (&type->s_umount_key#16){++++..}, at: [<c01b0553>]
> shrink_dcache_memory+0x103/0x1b0
> [ 1771.878551]
> [ 1771.878552] stack backtrace:
> [ 1771.878556] Pid: 183, comm: kswapd0 Not tainted 2.6.30-rc4 #1
> [ 1771.878559] Call Trace:
> [ 1771.878566]  [<c0364305>] ? printk+0x18/0x1b
> [ 1771.878570]  [<c014b0c7>] print_usage_bug+0x167/0x1c0
> [ 1771.878576]  [<c014b570>] mark_lock+0x450/0x650
> [ 1771.878580]  [<c014bef0>] ? check_usage_forwards+0x0/0xb0
> [ 1771.878586]  [<c014cc5a>] __lock_acquire+0x3ca/0x18a0
> [ 1771.878591]  [<c014c9dc>] ? __lock_acquire+0x14c/0x18a0
> [ 1771.878596]  [<c01cc03b>] ? inotify_inode_is_dead+0x1b/0x80
> [ 1771.878601]  [<c014e1ff>] lock_acquire+0xcf/0xf0
> [ 1771.878606]  [<c01cc03b>] ? inotify_inode_is_dead+0x1b/0x80
> [ 1771.878611]  [<c01cc03b>] ? inotify_inode_is_dead+0x1b/0x80
> [ 1771.878616]  [<c0365968>] mutex_lock_nested+0x58/0x350
> [ 1771.878621]  [<c01cc03b>] ? inotify_inode_is_dead+0x1b/0x80
> [ 1771.878626]  [<c01cc03b>] inotify_inode_is_dead+0x1b/0x80
> [ 1771.878632]  [<c01b003c>] dentry_iput+0x9c/0xc0
> [ 1771.878637]  [<c01b0146>] d_kill+0x36/0x60
> [ 1771.878643]  [<c01b0385>] __shrink_dcache_sb+0x215/0x2e0
> [ 1771.878649]  [<c01b0585>] shrink_dcache_memory+0x135/0x1b0
> [ 1771.878654]  [<c0182cd5>] shrink_slab+0x105/0x1a0
> [ 1771.878660]  [<c0183213>] kswapd+0x4a3/0x5d0
> [ 1771.878666]  [<c0180c20>] ? isolate_pages_global+0x0/0x200
> [ 1771.878672]  [<c013b6c0>] ? autoremove_wake_function+0x0/0x50
> [ 1771.878678]  [<c0182d70>] ? kswapd+0x0/0x5d0
> [ 1771.878683]  [<c013b373>] kthread+0x43/0x80
> [ 1771.878687]  [<c013b330>] ? kthread+0x0/0x80
> [ 1771.878692]  [<c010372b>] kernel_thread_helper+0x7/0x1c
> 
> Maybe related to http://bugzilla.kernel.org/show_bug.cgi?id=13068 ?

On Sunday 17 May 2009, Sachin Sant wrote:
> Ingo Molnar wrote:
> > i think this might be fixed by:
> >
> > 381a80e: inotify: use GFP_NOFS in kernel_event() to work around a lockdep
> false-positive
> >
> > already in -rc6.
> >   
> Haven't seen this issue with rc6.