inconsistent lock state (xfs)

inconsistent lock state (xfs)

[Chuck Lever]

Seen during a Linux kernel build (make -s -j3 all) on a two-processor VMware guest.

Dec 10 14:28:40 matisse kernel: =================================
Dec 10 14:28:40 matisse kernel: [ INFO: inconsistent lock state ]
Dec 10 14:28:40 matisse kernel: 2.6.37-rc5-00052-g7c30118 #2
Dec 10 14:28:40 matisse kernel: ---------------------------------
Dec 10 14:28:40 matisse kernel: inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.
Dec 10 14:28:40 matisse kernel: kswapd0/26 [HC0[0]:SC0[0]:HE1:SE1] takes:
Dec 10 14:28:40 matisse kernel: (&(&ip->i_iolock)->mr_lock#2){++++?+}, at: [<ffffffffa0086ffd>] xfs_ilock+0x30/0xb9 [xfs]
Dec 10 14:28:40 matisse kernel: {RECLAIM_FS-ON-W} state was registered at:
Dec 10 14:28:40 matisse kernel:  [<ffffffff8107cc42>] mark_held_locks+0x52/0x70
Dec 10 14:28:40 matisse kernel:  [<ffffffff8107ccf9>] lockdep_trace_alloc+0x99/0xbb
Dec 10 14:28:40 matisse kernel:  [<ffffffff8110fbdc>] slab_pre_alloc_hook+0x1d/0x40
Dec 10 14:28:40 matisse kernel:  [<ffffffff81110d0b>] kmem_cache_alloc+0x28/0x111
Dec 10 14:28:40 matisse kernel:  [<ffffffffa00a1d75>] kmem_zone_alloc+0x69/0xb1 [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffffa00a1dd1>] kmem_zone_zalloc+0x14/0x35 [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffffa009bb93>] _xfs_trans_alloc+0x27/0x64 [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffffa009c98b>] xfs_trans_alloc+0x9f/0xac [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffffa00a1018>] xfs_setattr+0x3a0/0x7e7 [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffffa00aa9b0>] xfs_vn_setattr+0x1b/0x1f [xfs]
Dec 10 14:28:40 matisse kernel:  [<ffffffff811329a6>] notify_change+0x1a2/0x29d
Dec 10 14:28:40 matisse kernel:  [<ffffffff8111d20e>] do_truncate+0x6c/0x89
Dec 10 14:28:40 matisse kernel:  [<ffffffff81128640>] do_last+0x57e/0x583
Dec 10 14:28:40 matisse kernel:  [<ffffffff8112a128>] do_filp_open+0x215/0x5ae
Dec 10 14:28:40 matisse kernel:  [<ffffffff8111c388>] do_sys_open+0x60/0xfd
Dec 10 14:28:40 matisse kernel:  [<ffffffff8111c458>] sys_open+0x20/0x22
Dec 10 14:28:40 matisse kernel:  [<ffffffff8100ac42>] system_call_fastpath+0x16/0x1b
Dec 10 14:28:40 matisse kernel: irq event stamp: 2527153
Dec 10 14:28:40 matisse kernel: hardirqs last  enabled at (2527153): [<ffffffff810ace1e>] __call_rcu+0x142/0x155
Dec 10 14:28:40 matisse kernel: hardirqs last disabled at (2527152): [<ffffffff810acd16>] __call_rcu+0x3a/0x155
Dec 10 14:28:40 matisse kernel: softirqs last  enabled at (2527144): [<ffffffff810568e7>] __do_softirq+0x1c0/0x1e9
Dec 10 14:28:40 matisse kernel: softirqs last disabled at (2527085): [<ffffffff8100bbdc>] call_softirq+0x1c/0x30
Dec 10 14:28:40 matisse kernel:
Dec 10 14:28:40 matisse kernel: other info that might help us debug this:
Dec 10 14:28:40 matisse kernel: 2 locks held by kswapd0/26:
Dec 10 14:28:40 matisse kernel: #0:  (shrinker_rwsem){++++..}, at: [<ffffffff810e34de>] shrink_slab+0x3d/0x164
Dec 10 14:28:40 matisse kernel: #1:  (&pag->pag_ici_reclaim_lock){+.+...}, at: [<ffffffffa00ad335>] xfs_reclaim_inodes_ag+0x65/0x28e [xfs]
Dec 10 14:28:40 matisse kernel:
Dec 10 14:28:40 matisse kernel: stack backtrace:
Dec 10 14:28:40 matisse kernel: Pid: 26, comm: kswapd0 Not tainted 2.6.37-rc5-00052-g7c30118 #2
Dec 10 14:28:40 matisse kernel: Call Trace:
Dec 10 14:28:40 matisse kernel: [<ffffffff8107c9a8>] valid_state+0x17f/0x192
Dec 10 14:28:40 matisse kernel: [<ffffffff81016587>] ? save_stack_trace+0x2f/0x4c
Dec 10 14:28:40 matisse kernel: [<ffffffff8107d295>] ? check_usage_forwards+0x0/0x87
Dec 10 14:28:40 matisse kernel: [<ffffffff8107cad5>] mark_lock+0x11a/0x235
Dec 10 14:28:40 matisse kernel: [<ffffffff8107defb>] __lock_acquire+0x37f/0xd0b
Dec 10 14:28:40 matisse kernel: [<ffffffff8107cc42>] ? mark_held_locks+0x52/0x70
Dec 10 14:28:40 matisse kernel: [<ffffffff8107cef3>] ? trace_hardirqs_on+0xd/0xf
Dec 10 14:28:40 matisse kernel: [<ffffffff8107e96a>] lock_acquire+0xe3/0x110
Dec 10 14:28:40 matisse kernel: [<ffffffffa0086ffd>] ? xfs_ilock+0x30/0xb9 [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffff810704a3>] down_write_nested+0x4f/0x72
Dec 10 14:28:40 matisse kernel: [<ffffffffa0086ffd>] ? xfs_ilock+0x30/0xb9 [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffffa0086ffd>] xfs_ilock+0x30/0xb9 [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffffa00ad284>] xfs_reclaim_inode+0x1f5/0x241 [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffffa00ad48c>] xfs_reclaim_inodes_ag+0x1bc/0x28e [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffffa00ad59a>] xfs_reclaim_inode_shrink+0x3c/0x7d [xfs]
Dec 10 14:28:40 matisse kernel: [<ffffffff810e3581>] shrink_slab+0xe0/0x164
Dec 10 14:28:40 matisse kernel: [<ffffffff810e4edf>] balance_pgdat+0x2e8/0x521
Dec 10 14:28:40 matisse kernel: [<ffffffff810e53ef>] kswapd+0x2d7/0x316
Dec 10 14:28:40 matisse kernel: [<ffffffff8106c45e>] ? autoremove_wake_function+0x0/0x39
Dec 10 14:28:40 matisse kernel: [<ffffffff810e5118>] ? kswapd+0x0/0x316
Dec 10 14:28:40 matisse kernel: [<ffffffff8106bf99>] kthread+0x9d/0xa5
Dec 10 14:28:40 matisse kernel: [<ffffffff8107cec2>] ? trace_hardirqs_on_caller+0x111/0x135
Dec 10 14:28:40 matisse kernel: [<ffffffff8100bae4>] kernel_thread_helper+0x4/0x10
Dec 10 14:28:40 matisse kernel: [<ffffffff81479f90>] ? restore_args+0x0/0x30
Dec 10 14:28:40 matisse kernel: [<ffffffff8106befc>] ? kthread+0x0/0xa5
Dec 10 14:28:40 matisse kernel: [<ffffffff8100bae0>] ? kernel_thread_helper+0x0/0x10

-- 
Chuck Lever
chuck[dot]lever[at]oracle[dot]com

Re: inconsistent lock state (xfs)

[Christoph Hellwig]

On Fri, Dec 10, 2010 at 02:40:06PM -0500, Chuck Lever wrote:
> Seen during a Linux kernel build (make -s -j3 all) on a two-processor VMware guest.

Yes, it's pretty common.  Except for an obscure ioctl it's a false
positive.  The patch titled:

	[PATCH, RFC] prune back iprune_sem

I sent a while ago fixes it.