Re: jfs: possible irq lock inversion dependency detected

On Mon, 16 May 2016, Christian Kujau wrote:
> This just happend on a PowerPC (32 bit) box running Debian/stable and a 
> vanilla 4.6.0-rc7 kernel:
> 
> =========================================================
> [ INFO: possible irq lock inversion dependency detected ]
> 4.6.0-rc7 #2 Not tainted
> ---------------------------------------------------------
> kswapd0/272 just changed the state of lock:
>  (&jfs_ip->rdwrlock#2){++++-.}, at: [<c01f0840>] jfs_get_block+0x50/0x370
> but this lock took another, RECLAIM_FS-unsafe lock in the past:
>  (&jfs_ip->commit_mutex){+.+.+.}

This just happened again, while the machine was kinda busy with disk I/O, 
this time with 4.7-rc1. I take it this is just a warning and nothing to 
worry about?

Thanks,
Christian.

=========================================================
[ INFO: possible irq lock inversion dependency detected ]
4.7.0-rc1 #2 Not tainted
---------------------------------------------------------
snmpd/1903 just changed the state of lock:
 (&(imap->im_aglock[index])){+.+.-.}, at: [<c01fb150>] diFree+0x74/0x9f4
but this lock took another, RECLAIM_FS-unsafe lock in the past:
 (&jfs_ip->commit_mutex){+.+.+.}

and interrupts could create inverse lock ordering between them.


other info that might help us debug this:
 Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&jfs_ip->commit_mutex);
                               local_irq_disable();
                               lock(&(imap->im_aglock[index]));
                               lock(&jfs_ip->commit_mutex);
  <Interrupt>
    lock(&(imap->im_aglock[index]));

 *** DEADLOCK ***

3 locks held by snmpd/1903:
 #0:  (rtnl_mutex){+.+.+.}, at: [<c054503c>] netlink_dump+0x20/0x2e4
 #1:  (shrinker_rwsem){++++..}, at: [<c00b3b70>] shrink_slab.part.54.constprop.66+0x3c/0x28c
 #2:  (&type->s_umount_key#23){+++++.}, at: [<c00ec860>] trylock_super+0x20/0x88

the shortest dependencies between 2nd lock and 1st lock:
 -> (&jfs_ip->commit_mutex){+.+.+.} ops: 1167483 {
    HARDIRQ-ON-W at:
                      [<c0060da8>] lock_acquire+0x4c/0x68
                      [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                      [<c01f1864>] jfs_create+0x88/0x300
                      [<c00f8aec>] path_openat+0xce4/0x1234
                      [<c00fa6bc>] do_filp_open+0xac/0xfc
                      [<c00e81dc>] do_sys_open+0x160/0x22c
                      [<c001063c>] ret_from_syscall+0x0/0x38
    SOFTIRQ-ON-W at:
                      [<c0060da8>] lock_acquire+0x4c/0x68
                      [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                      [<c01f1864>] jfs_create+0x88/0x300
                      [<c00f8aec>] path_openat+0xce4/0x1234
                      [<c00fa6bc>] do_filp_open+0xac/0xfc
                      [<c00e81dc>] do_sys_open+0x160/0x22c
                      [<c001063c>] ret_from_syscall+0x0/0x38
    RECLAIM_FS-ON-W at:
                         [<c005e5ec>] lockdep_trace_alloc+0x8c/0xe4
                         [<c00e2388>] __kmalloc+0x40/0x150
                         [<c0213074>] __jfs_set_acl+0xe4/0x1a8
                         [<c0213294>] jfs_set_acl+0x50/0x9c
                         [<c01442e0>] posix_acl_chmod+0xdc/0x11c
                         [<c010a0b0>] notify_change+0x158/0x3a0
                         [<c00e684c>] chmod_common+0x74/0x10c
                         [<c00e78ec>] SyS_fchmod+0x30/0x64
                         [<c001063c>] ret_from_syscall+0x0/0x38
    INITIAL USE at:
                     [<c0060da8>] lock_acquire+0x4c/0x68
                     [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                     [<c01f1864>] jfs_create+0x88/0x300
                     [<c00f8aec>] path_openat+0xce4/0x1234
                     [<c00fa6bc>] do_filp_open+0xac/0xfc
                     [<c00e81dc>] do_sys_open+0x160/0x22c
                     [<c001063c>] ret_from_syscall+0x0/0x38
  }
  ... key      at: [<c0fdf178>] __key.33051+0x0/0x8
  ... acquired at:
   [<c06298b0>] mutex_lock_nested+0x38/0x2e8
   [<c01fb704>] diFree+0x628/0x9f4
   [<c01f0b90>] jfs_evict_inode+0x7c/0x80
   [<c0108a00>] evict+0xbc/0x194
   [<c020f0e8>] txUpdateMap+0x22c/0x2c4
   [<c02107e4>] jfs_lazycommit+0x164/0x214
   [<c0049b64>] kthread+0xbc/0xd0
   [<c0010778>] ret_from_kernel_thread+0x5c/0x64

-> (&(imap->im_aglock[index])){+.+.-.} ops: 177579 {
   HARDIRQ-ON-W at:
                    [<c0060da8>] lock_acquire+0x4c/0x68
                    [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                    [<c01fbdb4>] diAlloc+0x2e4/0x6e0
                    [<c0207fcc>] ialloc+0x4c/0x1d0
                    [<c01f182c>] jfs_create+0x50/0x300
                    [<c00f8aec>] path_openat+0xce4/0x1234
                    [<c00fa6bc>] do_filp_open+0xac/0xfc
                    [<c00e81dc>] do_sys_open+0x160/0x22c
                    [<c001063c>] ret_from_syscall+0x0/0x38
   SOFTIRQ-ON-W at:
                    [<c0060da8>] lock_acquire+0x4c/0x68
                    [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                    [<c01fbdb4>] diAlloc+0x2e4/0x6e0
                    [<c0207fcc>] ialloc+0x4c/0x1d0
                    [<c01f182c>] jfs_create+0x50/0x300
                    [<c00f8aec>] path_openat+0xce4/0x1234
                    [<c00fa6bc>] do_filp_open+0xac/0xfc
                    [<c00e81dc>] do_sys_open+0x160/0x22c
                    [<c001063c>] ret_from_syscall+0x0/0x38
   IN-RECLAIM_FS-W at:
                       [<c0060da8>] lock_acquire+0x4c/0x68
                       [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                       [<c01fb150>] diFree+0x74/0x9f4
                       [<c01f0b90>] jfs_evict_inode+0x7c/0x80
                       [<c0108a00>] evict+0xbc/0x194
                       [<c0103374>] __dentry_kill+0x1cc/0x234
                       [<c0103c00>] shrink_dentry_list+0x134/0x4c8
                       [<c0104b74>] prune_dcache_sb+0x4c/0x64
                       [<c00ec9c8>] super_cache_scan+0x100/0x17c
                       [<c00b3ce0>] shrink_slab.part.54.constprop.66+0x1ac/0x28c
                       [<c00b689c>] shrink_zone+0x5b8/0x600
                       [<c00b6b4c>] try_to_free_pages+0x268/0x560
                       [<c00aa534>] __alloc_pages_nodemask+0x3e8/0x924
                       [<c00c1690>] kmalloc_order+0x18/0x40
                       [<c0506220>] __kmalloc_reserve.isra.49+0x30/0x90
                       [<c05062f4>] __alloc_skb+0x74/0x1d0
                       [<c0545188>] netlink_dump+0x16c/0x2e4
                       [<c054556c>] netlink_recvmsg+0x26c/0x398
                       [<c04fe094>] SyS_recvfrom+0xa8/0x134
                       [<c04feb98>] SyS_socketcall+0x1e8/0x228
                       [<c001063c>] ret_from_syscall+0x0/0x38
   INITIAL USE at:
                   [<c0060da8>] lock_acquire+0x4c/0x68
                   [<c06298b0>] mutex_lock_nested+0x38/0x2e8
                   [<c01fbdb4>] diAlloc+0x2e4/0x6e0
                   [<c0207fcc>] ialloc+0x4c/0x1d0
                   [<c01f182c>] jfs_create+0x50/0x300
                   [<c00f8aec>] path_openat+0xce4/0x1234
                   [<c00fa6bc>] do_filp_open+0xac/0xfc
                   [<c00e81dc>] do_sys_open+0x160/0x22c
                   [<c001063c>] ret_from_syscall+0x0/0x38
 }
 ... key      at: [<c0fdf1a4>] __key.28661+0x0/0x8
 ... acquired at:
   [<c005db88>] mark_lock+0x3dc/0x724
   [<c005f428>] __lock_acquire+0x250/0x1870
   [<c0060da8>] lock_acquire+0x4c/0x68
   [<c06298b0>] mutex_lock_nested+0x38/0x2e8
   [<c01fb150>] diFree+0x74/0x9f4
   [<c01f0b90>] jfs_evict_inode+0x7c/0x80
   [<c0108a00>] evict+0xbc/0x194
   [<c0103374>] __dentry_kill+0x1cc/0x234
   [<c0103c00>] shrink_dentry_list+0x134/0x4c8
   [<c0104b74>] prune_dcache_sb+0x4c/0x64
   [<c00ec9c8>] super_cache_scan+0x100/0x17c
   [<c00b3ce0>] shrink_slab.part.54.constprop.66+0x1ac/0x28c
   [<c00b689c>] shrink_zone+0x5b8/0x600
   [<c00b6b4c>] try_to_free_pages+0x268/0x560
   [<c00aa534>] __alloc_pages_nodemask+0x3e8/0x924
   [<c00c1690>] kmalloc_order+0x18/0x40
   [<c0506220>] __kmalloc_reserve.isra.49+0x30/0x90
   [<c05062f4>] __alloc_skb+0x74/0x1d0
   [<c0545188>] netlink_dump+0x16c/0x2e4
   [<c054556c>] netlink_recvmsg+0x26c/0x398
   [<c04fe094>] SyS_recvfrom+0xa8/0x134
   [<c04feb98>] SyS_socketcall+0x1e8/0x228
   [<c001063c>] ret_from_syscall+0x0/0x38


stack backtrace:
CPU: 0 PID: 1903 Comm: snmpd Not tainted 4.7.0-rc1 #2
Call Trace:
[ee1617c0] [c062e798] print_irq_inversion_bug.part.32+0x1d8/0x1f4 (unreliable)
[ee1617f0] [c005cf18] check_usage_forwards+0x15c/0x160
[ee161850] [c005db88] mark_lock+0x3dc/0x724
[ee161880] [c005f428] __lock_acquire+0x250/0x1870
[ee161930] [c0060da8] lock_acquire+0x4c/0x68
[ee161950] [c06298b0] mutex_lock_nested+0x38/0x2e8
[ee1619b0] [c01fb150] diFree+0x74/0x9f4
[ee161a30] [c01f0b90] jfs_evict_inode+0x7c/0x80
[ee161a40] [c0108a00] evict+0xbc/0x194
[ee161a60] [c0103374] __dentry_kill+0x1cc/0x234
[ee161a80] [c0103c00] shrink_dentry_list+0x134/0x4c8
[ee161ac0] [c0104b74] prune_dcache_sb+0x4c/0x64
[ee161ae0] [c00ec9c8] super_cache_scan+0x100/0x17c
[ee161b10] [c00b3ce0] shrink_slab.part.54.constprop.66+0x1ac/0x28c
[ee161b80] [c00b689c] shrink_zone+0x5b8/0x600
[ee161c20] [c00b6b4c] try_to_free_pages+0x268/0x560
[ee161cb0] [c00aa534] __alloc_pages_nodemask+0x3e8/0x924
[ee161d40] [c00c1690] kmalloc_order+0x18/0x40
[ee161d50] [c0506220] __kmalloc_reserve.isra.49+0x30/0x90
[ee161d70] [c05062f4] __alloc_skb+0x74/0x1d0
[ee161da0] [c0545188] netlink_dump+0x16c/0x2e4
[ee161dc0] [c054556c] netlink_recvmsg+0x26c/0x398
[ee161e20] [c04fe094] SyS_recvfrom+0xa8/0x134
[ee161f10] [c04feb98] SyS_socketcall+0x1e8/0x228
[ee161f40] [c001063c] ret_from_syscall+0x0/0x38
--- interrupt: c01 at 0xfa8f410
    LR = 0xfe06de8

-- 
BOFH excuse #420:

Feature was not beta tested

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are 
consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
J-Flow, sFlow and other flows. Make informed decisions using capacity 
planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e