[BUG] INFO: inconsistent lock state

["Srivatsa S. Bhat" <srivatsa.bhat@linux.vnet.ibm.com>]

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