jfs: mangled lockdep splat

From: Christian Kujau
Date: Tue Nov 22 2016 - 19:12:38 EST

Next message: David Howells: "[PATCH 1/6] x86/efi: Allow invocation of arbitrary runtime services [ver #2]"
Previous message: Christian Kujau: "Locking API testsuite output mangled"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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?

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/
--
BOFH excuse #185:

system consumed all the paper for paging

Next message: David Howells: "[PATCH 1/6] x86/efi: Allow invocation of arbitrary runtime services [ver #2]"
Previous message: Christian Kujau: "Locking API testsuite output mangled"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]