Re: [Jfs-discussion] jfs: mangled lockdep splat

From: Dave Kleikamp
Date: Mon Dec 05 2016 - 17:45:14 EST

Next message: David Woodhouse: "Re: [PATCH] iommu/intel: disable DMAR for Q35 integrated gfx"
Previous message: Shuah Khan: "Re: [PATCH v6 3/3] sound/usb: Use Media Controller API to share media resources"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 11/22/2016 06:05 PM, Christian Kujau wrote:
> For some time now, I always[0] receive a lockdep warning when there's some
> disk I/O on the system. But recently the warning looks kinda mangled,
> I suspect the recent printk change (4bcc595ccd80, "printk: reinstate
> KERN_CONT for printing continuation lines") to be the reason for that.
> In previous versions, the warning looked like this:
>
> http://nerdbynature.de/bits/4.6.0-rc7/dmesg.txt
>
> Below is the new warning, which is barely readable anymore. Of course,
> best would be for the warning to vanish (hehe) but maybe the printout
> could be fixed too?

Dmitry Vyukov has a fix for the lockdep formatting. I haven't tested it,
but none of this output is specific to jfs.

Maybe I should figure out how to get rid of the warning altogether.

Thanks for reporting this.

Shaggy

>
> Thanks,
> Christian.
>
> [ 2401.254353] =========================================================
> [ 2401.254410] [ INFO: possible irq lock inversion dependency detected ]
> [ 2401.254469] 4.9.0-rc6 #1 Not tainted
> [ 2401.254506] ---------------------------------------------------------
> [ 2401.254560] kswapd0/282 just changed the state of lock:
> [ 2401.254620] (
> [ 2401.254647] &jfs_ip->rdwrlock
> [ 2401.254685] #2
> [ 2401.254698] ){++++-.}
> [ 2401.254730] , at:
> [ 2401.254764] [<c01f9c38>] jfs_get_block+0x50/0x370
> [ 2401.254812] but this lock took another, RECLAIM_FS-unsafe lock in the past:
> [ 2401.254868] (
> [ 2401.254890] &jfs_ip->commit_mutex
> [ 2401.254927] ){+.+.+.}
> [ 2401.254945]
>
> and interrupts could create inverse lock ordering between them.
>
> [ 2401.255041]
> other info that might help us debug this:
> [ 2401.255097] Possible interrupt unsafe locking scenario:
>
> [ 2401.255160] CPU0 CPU1
> [ 2401.255203] ---- ----
> [ 2401.255243] lock(
> [ 2401.255273] &jfs_ip->commit_mutex
> [ 2401.255310] );
> [ 2401.255334] local_irq_disable();
> [ 2401.255381] lock(
> [ 2401.255420] &jfs_ip->rdwrlock
> [ 2401.255454] #2
> [ 2401.255467] );
> [ 2401.255494] lock(
> [ 2401.255536] &jfs_ip->commit_mutex
> [ 2401.255573] );
> [ 2401.255596] <Interrupt>
> [ 2401.255623] lock(
> [ 2401.255648] &jfs_ip->rdwrlock
> [ 2401.256059] #2
> [ 2401.256071] );
> [ 2401.256446]
> *** DEADLOCK ***
>
> [ 2401.257522] no locks held by kswapd0/282.
> [ 2401.257888]
> the shortest dependencies between 2nd lock and 1st lock:
> [ 2401.258622] ->
> [ 2401.258645] (
> [ 2401.259014] &jfs_ip->commit_mutex
> [ 2401.259047] ){+.+.+.}
> [ 2401.259418] ops: 31698
> [ 2401.259435] {
> [ 2401.259800] HARDIRQ-ON-W
> [ 2401.259829] at:
> [ 2401.260192]
> [ 2401.260236] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.260619]
> [ 2401.260657] [<c0652780>] mutex_lock_nested+0x38/0x2f8
> [ 2401.261048]
> [ 2401.261108] [<c01fafd0>] jfs_create+0x88/0x2c4
> [ 2401.261839]
> [ 2401.261996] [<c00ffe24>] path_openat+0xc1c/0x100c
> [ 2401.262689]
> [ 2401.262860] [<c0101224>] do_filp_open+0xb0/0x100
> [ 2401.263639]
> [ 2401.263678] [<c00ee44c>] do_sys_open+0x154/0x21c
> [ 2401.264368]
> [ 2401.264411] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.265070] SOFTIRQ-ON-W
> [ 2401.265099] at:
> [ 2401.265579]
> [ 2401.265751] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.266268]
> [ 2401.266437] [<c0652780>] mutex_lock_nested+0x38/0x2f8
> [ 2401.266975]
> [ 2401.267135] [<c01fafd0>] jfs_create+0x88/0x2c4
> [ 2401.267679]
> [ 2401.267837] [<c00ffe24>] path_openat+0xc1c/0x100c
> [ 2401.268394]
> [ 2401.268560] [<c0101224>] do_filp_open+0xb0/0x100
> [ 2401.269104]
> [ 2401.269273] [<c00ee44c>] do_sys_open+0x154/0x21c
> [ 2401.269969]
> [ 2401.270040] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.270727] RECLAIM_FS-ON-W
> [ 2401.270761] at:
> [ 2401.271279]
> [ 2401.271418] [<c0063960>] lockdep_trace_alloc+0x8c/0xe4
> [ 2401.272017]
> [ 2401.272122] [<c00e7f64>] __kmalloc+0x40/0x14c
> [ 2401.272706]
> [ 2401.272839] [<c021b638>] __jfs_set_acl+0xa0/0x1a4
> [ 2401.273428]
> [ 2401.273541] [<c021b898>] jfs_set_acl+0x50/0x9c
> [ 2401.274135]
> [ 2401.274267] [<c014bd20>] posix_acl_chmod+0xf0/0x130
> [ 2401.274824]
> [ 2401.274991] [<c0110a48>] notify_change+0x1c4/0x42c
> [ 2401.275690]
> [ 2401.275727] [<c00ecb00>] chmod_common+0x74/0x10c
> [ 2401.276382]
> [ 2401.276419] [<c00edc60>] SyS_fchmod+0x30/0x64
> [ 2401.277090]
> [ 2401.277129] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.277805] INITIAL USE
> [ 2401.277834] at:
> [ 2401.278352]
> [ 2401.278525] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.279054]
> [ 2401.279224] [<c0652780>] mutex_lock_nested+0x38/0x2f8
> [ 2401.279783]
> [ 2401.279944] [<c01fafd0>] jfs_create+0x88/0x2c4
> [ 2401.280528]
> [ 2401.280645] [<c00ffe24>] path_openat+0xc1c/0x100c
> [ 2401.281287]
> [ 2401.281358] [<c0101224>] do_filp_open+0xb0/0x100
> [ 2401.282048]
> [ 2401.282084] [<c00ee44c>] do_sys_open+0x154/0x21c
> [ 2401.282840]
> [ 2401.282880] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.283590] }
> [ 2401.284175] ... key at:
> [ 2401.284247] [<c105a23c>] __key.33791+0x0/0x8
> [ 2401.284978] ... acquired at:
> [ 2401.285526]
> [ 2401.285621] [<c0652780>] mutex_lock_nested+0x38/0x2f8
> [ 2401.286280]
> [ 2401.286378] [<c0210f78>] extAlloc+0x4c/0x650
> [ 2401.287025]
> [ 2401.287118] [<c01f9dc0>] jfs_get_block+0x1d8/0x370
> [ 2401.287787]
> [ 2401.287889] [<c012bf1c>] nobh_write_begin+0x174/0x48c
> [ 2401.288820]
> [ 2401.288855] [<c01fa6ac>] jfs_write_begin+0x34/0x94
> [ 2401.289605]
> [ 2401.289633] [<c00a6810>] generic_perform_write+0xb0/0x1bc
> [ 2401.290481]
> [ 2401.290508] [<c00a8258>] __generic_file_write_iter+0x1a4/0x1f8
> [ 2401.291290]
> [ 2401.291317] [<c00a8398>] generic_file_write_iter+0xec/0x240
> [ 2401.292110]
> [ 2401.292137] [<c00eec78>] __vfs_write+0xd8/0x188
> [ 2401.292905]
> [ 2401.292931] [<c00ef0bc>] vfs_write+0xc4/0x244
> [ 2401.293703]
> [ 2401.293731] [<c00f0f0c>] SyS_write+0x4c/0xc4
> [ 2401.294506]
> [ 2401.294533] [<c00107e8>] ret_from_syscall+0x0/0x38
>
> [ 2401.295992] ->
> [ 2401.296014] (
> [ 2401.296631] &jfs_ip->rdwrlock
> [ 2401.296745] #2
> [ 2401.297340] ){++++-.}
> [ 2401.297410] ops: 63559
> [ 2401.298054] {
> [ 2401.298663] HARDIRQ-ON-W
> [ 2401.298786] at:
> [ 2401.299442]
> [ 2401.299520] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.300438]
> [ 2401.300578] [<c005d548>] down_write_nested+0x30/0x7c
> [ 2401.301402]
> [ 2401.301554] [<c01f9c38>] jfs_get_block+0x50/0x370
> [ 2401.302369]
> [ 2401.302453] [<c012bf1c>] nobh_write_begin+0x174/0x48c
> [ 2401.303301]
> [ 2401.303367] [<c01fa6ac>] jfs_write_begin+0x34/0x94
> [ 2401.304219]
> [ 2401.304294] [<c00a6810>] generic_perform_write+0xb0/0x1bc
> [ 2401.305087]
> [ 2401.305141] [<c00a8258>] __generic_file_write_iter+0x1a4/0x1f8
> [ 2401.305913]
> [ 2401.305984] [<c00a8398>] generic_file_write_iter+0xec/0x240
> [ 2401.306728]
> [ 2401.306831] [<c00eec78>] __vfs_write+0xd8/0x188
> [ 2401.307532]
> [ 2401.307617] [<c00ef0bc>] vfs_write+0xc4/0x244
> [ 2401.308334]
> [ 2401.308394] [<c00f0f0c>] SyS_write+0x4c/0xc4
> [ 2401.309135]
> [ 2401.309172] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.309924] HARDIRQ-ON-R
> [ 2401.309953] at:
> [ 2401.310662]
> [ 2401.310698] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.311456]
> [ 2401.311491] [<c005d454>] down_read_nested+0x30/0x74
> [ 2401.312277]
> [ 2401.312318] [<c01f9d00>] jfs_get_block+0x118/0x370
> [ 2401.313107]
> [ 2401.313173] [<c0134484>] do_mpage_readpage+0x444/0x814
> [ 2401.313959]
> [ 2401.314007] [<c0134954>] mpage_readpages+0x100/0x190
> [ 2401.314827]
> [ 2401.314975] [<c00b3e50>] __do_page_cache_readahead+0x260/0x32c
> [ 2401.315716]
> [ 2401.315853] [<c00a8be0>] generic_file_read_iter+0x638/0x898
> [ 2401.316569]
> [ 2401.316709] [<c00eeaf8>] __vfs_read+0xd8/0x180
> [ 2401.317374]
> [ 2401.317517] [<c00eeecc>] vfs_read+0x98/0x1c4
> [ 2401.318144]
> [ 2401.318266] [<c00f74dc>] prepare_binprm+0xd0/0x158
> [ 2401.318964]
> [ 2401.319081] [<c00f7d4c>] do_execveat_common+0x4d4/0x76c
> [ 2401.319791]
> [ 2401.319859] [<c00f8010>] do_execve+0x2c/0x3c
> [ 2401.320582]
> [ 2401.320620] [<c0003fa0>] try_to_run_init_process+0x18/0x58
> [ 2401.321398]
> [ 2401.321451] [<c00048b8>] kernel_init+0xc0/0x128
> [ 2401.322210]
> [ 2401.322259] [<c0010924>] ret_from_kernel_thread+0x5c/0x64
> [ 2401.323030] SOFTIRQ-ON-W
> [ 2401.323059] at:
> [ 2401.323764]
> [ 2401.323805] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.324553]
> [ 2401.324588] [<c005d548>] down_write_nested+0x30/0x7c
> [ 2401.325364]
> [ 2401.325400] [<c01f9c38>] jfs_get_block+0x50/0x370
> [ 2401.326149]
> [ 2401.326187] [<c012bf1c>] nobh_write_begin+0x174/0x48c
> [ 2401.326945]
> [ 2401.326981] [<c01fa6ac>] jfs_write_begin+0x34/0x94
> [ 2401.327737]
> [ 2401.327773] [<c00a6810>] generic_perform_write+0xb0/0x1bc
> [ 2401.328593]
> [ 2401.328628] [<c00a8258>] __generic_file_write_iter+0x1a4/0x1f8
> [ 2401.329415]
> [ 2401.329451] [<c00a8398>] generic_file_write_iter+0xec/0x240
> [ 2401.330214]
> [ 2401.330276] [<c00eec78>] __vfs_write+0xd8/0x188
> [ 2401.331014]
> [ 2401.331071] [<c00ef0bc>] vfs_write+0xc4/0x244
> [ 2401.331805]
> [ 2401.331847] [<c00f0f0c>] SyS_write+0x4c/0xc4
> [ 2401.332602]
> [ 2401.332639] [<c00107e8>] ret_from_syscall+0x0/0x38
> [ 2401.333385] SOFTIRQ-ON-R
> [ 2401.333414] at:
> [ 2401.334113]
> [ 2401.334149] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.334899]
> [ 2401.334934] [<c005d454>] down_read_nested+0x30/0x74
> [ 2401.335715]
> [ 2401.335755] [<c01f9d00>] jfs_get_block+0x118/0x370
> [ 2401.336541]
> [ 2401.336576] [<c0134484>] do_mpage_readpage+0x444/0x814
> [ 2401.337370]
> [ 2401.337405] [<c0134954>] mpage_readpages+0x100/0x190
> [ 2401.338181]
> [ 2401.338302] [<c00b3e50>] __do_page_cache_readahead+0x260/0x32c
> [ 2401.339068]
> [ 2401.339192] [<c00a8be0>] generic_file_read_iter+0x638/0x898
> [ 2401.339901]
> [ 2401.340042] [<c00eeaf8>] __vfs_read+0xd8/0x180
> [ 2401.340710]
> [ 2401.340844] [<c00eeecc>] vfs_read+0x98/0x1c4
> [ 2401.341513]
> [ 2401.341612] [<c00f74dc>] prepare_binprm+0xd0/0x158
> [ 2401.342326]
> [ 2401.342421] [<c00f7d4c>] do_execveat_common+0x4d4/0x76c
> [ 2401.343154]
> [ 2401.343202] [<c00f8010>] do_execve+0x2c/0x3c
> [ 2401.343949]
> [ 2401.344052] [<c0003fa0>] try_to_run_init_process+0x18/0x58
> [ 2401.344805]
> [ 2401.344883] [<c00048b8>] kernel_init+0xc0/0x128
> [ 2401.345615]
> [ 2401.345714] [<c0010924>] ret_from_kernel_thread+0x5c/0x64
> [ 2401.346442] IN-RECLAIM_FS-W
> [ 2401.346524] at:
> [ 2401.347190]
> [ 2401.347228] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.347984]
> [ 2401.348024] [<c005d548>] down_write_nested+0x30/0x7c
> [ 2401.348760]
> [ 2401.348798] [<c01f9c38>] jfs_get_block+0x50/0x370
> [ 2401.349559]
> [ 2401.349599] [<c012a10c>] __block_write_full_page+0x31c/0x4a0
> [ 2401.350372]
> [ 2401.350410] [<c00b9be4>] shrink_page_list+0x868/0xdc8
> [ 2401.351166]
> [ 2401.351248] [<c00ba920>] shrink_inactive_list+0x22c/0x404
> [ 2401.352021]
> [ 2401.352058] [<c00bb1e8>] shrink_node+0x388/0x67c
> [ 2401.352812]
> [ 2401.352851] [<c00bbdf0>] kswapd+0x3c4/0x560
> [ 2401.353582]
> [ 2401.353620] [<c004bd54>] kthread+0xbc/0xd0
> [ 2401.354361]
> [ 2401.354400] [<c0010924>] ret_from_kernel_thread+0x5c/0x64
> [ 2401.355140] INITIAL USE
> [ 2401.355169] at:
> [ 2401.355858]
> [ 2401.355898] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.356627]
> [ 2401.356662] [<c005d454>] down_read_nested+0x30/0x74
> [ 2401.357414]
> [ 2401.357456] [<c01f9d00>] jfs_get_block+0x118/0x370
> [ 2401.358208]
> [ 2401.358244] [<c0134484>] do_mpage_readpage+0x444/0x814
> [ 2401.359013]
> [ 2401.359051] [<c0134954>] mpage_readpages+0x100/0x190
> [ 2401.359789]
> [ 2401.359842] [<c00b3e50>] __do_page_cache_readahead+0x260/0x32c
> [ 2401.360659]
> [ 2401.360703] [<c00a8be0>] generic_file_read_iter+0x638/0x898
> [ 2401.361475]
> [ 2401.361616] [<c00eeaf8>] __vfs_read+0xd8/0x180
> [ 2401.362308]
> [ 2401.362413] [<c00eeecc>] vfs_read+0x98/0x1c4
> [ 2401.363099]
> [ 2401.363173] [<c00f74dc>] prepare_binprm+0xd0/0x158
> [ 2401.363895]
> [ 2401.363976] [<c00f7d4c>] do_execveat_common+0x4d4/0x76c
> [ 2401.364704]
> [ 2401.364744] [<c00f8010>] do_execve+0x2c/0x3c
> [ 2401.365478]
> [ 2401.365518] [<c0003fa0>] try_to_run_init_process+0x18/0x58
> [ 2401.366253]
> [ 2401.366289] [<c00048b8>] kernel_init+0xc0/0x128
> [ 2401.367046]
> [ 2401.367083] [<c0010924>] ret_from_kernel_thread+0x5c/0x64
> [ 2401.367865] }
> [ 2401.368531] ... key at:
> [ 2401.368566] [<c105a234>] __key.33790+0x0/0x8
> [ 2401.369316] ... acquired at:
> [ 2401.370021]
> [ 2401.370049] [<c0061108>] mark_lock+0x3dc/0x72c
> [ 2401.370682]
> [ 2401.370814] [<c0061ba0>] __lock_acquire+0x204/0x16b4
> [ 2401.371433]
> [ 2401.371540] [<c00633c8>] lock_acquire+0x4c/0x68
> [ 2401.372155]
> [ 2401.372249] [<c005d548>] down_write_nested+0x30/0x7c
> [ 2401.373188]
> [ 2401.373216] [<c01f9c38>] jfs_get_block+0x50/0x370
> [ 2401.373939]
> [ 2401.374003] [<c012a10c>] __block_write_full_page+0x31c/0x4a0
> [ 2401.374869]
> [ 2401.374901] [<c00b9be4>] shrink_page_list+0x868/0xdc8
> [ 2401.375675]
> [ 2401.375701] [<c00ba920>] shrink_inactive_list+0x22c/0x404
> [ 2401.376477]
> [ 2401.376504] [<c00bb1e8>] shrink_node+0x388/0x67c
> [ 2401.377262]
> [ 2401.377288] [<c00bbdf0>] kswapd+0x3c4/0x560
> [ 2401.378039]
> [ 2401.378065] [<c004bd54>] kthread+0xbc/0xd0
> [ 2401.378829]
> [ 2401.378857] [<c0010924>] ret_from_kernel_thread+0x5c/0x64
>
> [ 2401.380201]
> stack backtrace:
> [ 2401.381394] CPU: 0 PID: 282 Comm: kswapd0 Not tainted 4.9.0-rc6 #1
> [ 2401.382155] Call Trace:
> [ 2401.382873] [ef281a30] [c0657468] print_irq_inversion_bug.part.21+0x1d4/0x1f0 (unreliable)
> [ 2401.383704] [ef281a60] [c00603d8] check_usage_forwards+0x150/0x154
> [ 2401.384542] [ef281ab0] [c0061108] mark_lock+0x3dc/0x72c
> [ 2401.385482] [ef281ae0] [c0061ba0] __lock_acquire+0x204/0x16b4
> [ 2401.386399] [ef281b80] [c00633c8] lock_acquire+0x4c/0x68
> [ 2401.387158] [ef281ba0] [c005d548] down_write_nested+0x30/0x7c
> [ 2401.388085] [ef281bb0] [c01f9c38] jfs_get_block+0x50/0x370
> [ 2401.388747] [ef281c00] [c012a10c] __block_write_full_page+0x31c/0x4a0
> [ 2401.389539] [ef281c50] [c00b9be4] shrink_page_list+0x868/0xdc8
> [ 2401.390358] [ef281d10] [c00ba920] shrink_inactive_list+0x22c/0x404
> [ 2401.391171] [ef281d70] [c00bb1e8] shrink_node+0x388/0x67c
> [ 2401.391952] [ef281e10] [c00bbdf0] kswapd+0x3c4/0x560
> [ 2401.392709] [ef281eb0] [c004bd54] kthread+0xbc/0xd0
> [ 2401.393468] [ef281f40] [c0010924] ret_from_kernel_thread+0x5c/0x64
>
>
>
> [0] https://sourceforge.net/p/jfs/mailman/message/35093141/
>

Next message: David Woodhouse: "Re: [PATCH] iommu/intel: disable DMAR for Q35 integrated gfx"
Previous message: Shuah Khan: "Re: [PATCH v6 3/3] sound/usb: Use Media Controller API to share media resources"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]