Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756311AbcKWAMf (ORCPT ); Tue, 22 Nov 2016 19:12:35 -0500 Received: from trent.utfs.org ([94.185.90.103]:51012 "EHLO trent.utfs.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756246AbcKWAMc (ORCPT ); Tue, 22 Nov 2016 19:12:32 -0500 Date: Tue, 22 Nov 2016 16:05:24 -0800 (PST) From: Christian Kujau To: jfs-discussion@lists.sourceforge.net cc: linux-kernel@vger.kernel.org Subject: jfs: mangled lockdep splat Message-ID: User-Agent: Alpine 2.20.16 (DEB 170 2016-09-19) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 16199 Lines: 397 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] [] 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] [ 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] [] lock_acquire+0x4c/0x68 [ 2401.260619] [ 2401.260657] [] mutex_lock_nested+0x38/0x2f8 [ 2401.261048] [ 2401.261108] [] jfs_create+0x88/0x2c4 [ 2401.261839] [ 2401.261996] [] path_openat+0xc1c/0x100c [ 2401.262689] [ 2401.262860] [] do_filp_open+0xb0/0x100 [ 2401.263639] [ 2401.263678] [] do_sys_open+0x154/0x21c [ 2401.264368] [ 2401.264411] [] ret_from_syscall+0x0/0x38 [ 2401.265070] SOFTIRQ-ON-W [ 2401.265099] at: [ 2401.265579] [ 2401.265751] [] lock_acquire+0x4c/0x68 [ 2401.266268] [ 2401.266437] [] mutex_lock_nested+0x38/0x2f8 [ 2401.266975] [ 2401.267135] [] jfs_create+0x88/0x2c4 [ 2401.267679] [ 2401.267837] [] path_openat+0xc1c/0x100c [ 2401.268394] [ 2401.268560] [] do_filp_open+0xb0/0x100 [ 2401.269104] [ 2401.269273] [] do_sys_open+0x154/0x21c [ 2401.269969] [ 2401.270040] [] ret_from_syscall+0x0/0x38 [ 2401.270727] RECLAIM_FS-ON-W [ 2401.270761] at: [ 2401.271279] [ 2401.271418] [] lockdep_trace_alloc+0x8c/0xe4 [ 2401.272017] [ 2401.272122] [] __kmalloc+0x40/0x14c [ 2401.272706] [ 2401.272839] [] __jfs_set_acl+0xa0/0x1a4 [ 2401.273428] [ 2401.273541] [] jfs_set_acl+0x50/0x9c [ 2401.274135] [ 2401.274267] [] posix_acl_chmod+0xf0/0x130 [ 2401.274824] [ 2401.274991] [] notify_change+0x1c4/0x42c [ 2401.275690] [ 2401.275727] [] chmod_common+0x74/0x10c [ 2401.276382] [ 2401.276419] [] SyS_fchmod+0x30/0x64 [ 2401.277090] [ 2401.277129] [] ret_from_syscall+0x0/0x38 [ 2401.277805] INITIAL USE [ 2401.277834] at: [ 2401.278352] [ 2401.278525] [] lock_acquire+0x4c/0x68 [ 2401.279054] [ 2401.279224] [] mutex_lock_nested+0x38/0x2f8 [ 2401.279783] [ 2401.279944] [] jfs_create+0x88/0x2c4 [ 2401.280528] [ 2401.280645] [] path_openat+0xc1c/0x100c [ 2401.281287] [ 2401.281358] [] do_filp_open+0xb0/0x100 [ 2401.282048] [ 2401.282084] [] do_sys_open+0x154/0x21c [ 2401.282840] [ 2401.282880] [] ret_from_syscall+0x0/0x38 [ 2401.283590] } [ 2401.284175] ... key at: [ 2401.284247] [] __key.33791+0x0/0x8 [ 2401.284978] ... acquired at: [ 2401.285526] [ 2401.285621] [] mutex_lock_nested+0x38/0x2f8 [ 2401.286280] [ 2401.286378] [] extAlloc+0x4c/0x650 [ 2401.287025] [ 2401.287118] [] jfs_get_block+0x1d8/0x370 [ 2401.287787] [ 2401.287889] [] nobh_write_begin+0x174/0x48c [ 2401.288820] [ 2401.288855] [] jfs_write_begin+0x34/0x94 [ 2401.289605] [ 2401.289633] [] generic_perform_write+0xb0/0x1bc [ 2401.290481] [ 2401.290508] [] __generic_file_write_iter+0x1a4/0x1f8 [ 2401.291290] [ 2401.291317] [] generic_file_write_iter+0xec/0x240 [ 2401.292110] [ 2401.292137] [] __vfs_write+0xd8/0x188 [ 2401.292905] [ 2401.292931] [] vfs_write+0xc4/0x244 [ 2401.293703] [ 2401.293731] [] SyS_write+0x4c/0xc4 [ 2401.294506] [ 2401.294533] [] 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] [] lock_acquire+0x4c/0x68 [ 2401.300438] [ 2401.300578] [] down_write_nested+0x30/0x7c [ 2401.301402] [ 2401.301554] [] jfs_get_block+0x50/0x370 [ 2401.302369] [ 2401.302453] [] nobh_write_begin+0x174/0x48c [ 2401.303301] [ 2401.303367] [] jfs_write_begin+0x34/0x94 [ 2401.304219] [ 2401.304294] [] generic_perform_write+0xb0/0x1bc [ 2401.305087] [ 2401.305141] [] __generic_file_write_iter+0x1a4/0x1f8 [ 2401.305913] [ 2401.305984] [] generic_file_write_iter+0xec/0x240 [ 2401.306728] [ 2401.306831] [] __vfs_write+0xd8/0x188 [ 2401.307532] [ 2401.307617] [] vfs_write+0xc4/0x244 [ 2401.308334] [ 2401.308394] [] SyS_write+0x4c/0xc4 [ 2401.309135] [ 2401.309172] [] ret_from_syscall+0x0/0x38 [ 2401.309924] HARDIRQ-ON-R [ 2401.309953] at: [ 2401.310662] [ 2401.310698] [] lock_acquire+0x4c/0x68 [ 2401.311456] [ 2401.311491] [] down_read_nested+0x30/0x74 [ 2401.312277] [ 2401.312318] [] jfs_get_block+0x118/0x370 [ 2401.313107] [ 2401.313173] [] do_mpage_readpage+0x444/0x814 [ 2401.313959] [ 2401.314007] [] mpage_readpages+0x100/0x190 [ 2401.314827] [ 2401.314975] [] __do_page_cache_readahead+0x260/0x32c [ 2401.315716] [ 2401.315853] [] generic_file_read_iter+0x638/0x898 [ 2401.316569] [ 2401.316709] [] __vfs_read+0xd8/0x180 [ 2401.317374] [ 2401.317517] [] vfs_read+0x98/0x1c4 [ 2401.318144] [ 2401.318266] [] prepare_binprm+0xd0/0x158 [ 2401.318964] [ 2401.319081] [] do_execveat_common+0x4d4/0x76c [ 2401.319791] [ 2401.319859] [] do_execve+0x2c/0x3c [ 2401.320582] [ 2401.320620] [] try_to_run_init_process+0x18/0x58 [ 2401.321398] [ 2401.321451] [] kernel_init+0xc0/0x128 [ 2401.322210] [ 2401.322259] [] ret_from_kernel_thread+0x5c/0x64 [ 2401.323030] SOFTIRQ-ON-W [ 2401.323059] at: [ 2401.323764] [ 2401.323805] [] lock_acquire+0x4c/0x68 [ 2401.324553] [ 2401.324588] [] down_write_nested+0x30/0x7c [ 2401.325364] [ 2401.325400] [] jfs_get_block+0x50/0x370 [ 2401.326149] [ 2401.326187] [] nobh_write_begin+0x174/0x48c [ 2401.326945] [ 2401.326981] [] jfs_write_begin+0x34/0x94 [ 2401.327737] [ 2401.327773] [] generic_perform_write+0xb0/0x1bc [ 2401.328593] [ 2401.328628] [] __generic_file_write_iter+0x1a4/0x1f8 [ 2401.329415] [ 2401.329451] [] generic_file_write_iter+0xec/0x240 [ 2401.330214] [ 2401.330276] [] __vfs_write+0xd8/0x188 [ 2401.331014] [ 2401.331071] [] vfs_write+0xc4/0x244 [ 2401.331805] [ 2401.331847] [] SyS_write+0x4c/0xc4 [ 2401.332602] [ 2401.332639] [] ret_from_syscall+0x0/0x38 [ 2401.333385] SOFTIRQ-ON-R [ 2401.333414] at: [ 2401.334113] [ 2401.334149] [] lock_acquire+0x4c/0x68 [ 2401.334899] [ 2401.334934] [] down_read_nested+0x30/0x74 [ 2401.335715] [ 2401.335755] [] jfs_get_block+0x118/0x370 [ 2401.336541] [ 2401.336576] [] do_mpage_readpage+0x444/0x814 [ 2401.337370] [ 2401.337405] [] mpage_readpages+0x100/0x190 [ 2401.338181] [ 2401.338302] [] __do_page_cache_readahead+0x260/0x32c [ 2401.339068] [ 2401.339192] [] generic_file_read_iter+0x638/0x898 [ 2401.339901] [ 2401.340042] [] __vfs_read+0xd8/0x180 [ 2401.340710] [ 2401.340844] [] vfs_read+0x98/0x1c4 [ 2401.341513] [ 2401.341612] [] prepare_binprm+0xd0/0x158 [ 2401.342326] [ 2401.342421] [] do_execveat_common+0x4d4/0x76c [ 2401.343154] [ 2401.343202] [] do_execve+0x2c/0x3c [ 2401.343949] [ 2401.344052] [] try_to_run_init_process+0x18/0x58 [ 2401.344805] [ 2401.344883] [] kernel_init+0xc0/0x128 [ 2401.345615] [ 2401.345714] [] ret_from_kernel_thread+0x5c/0x64 [ 2401.346442] IN-RECLAIM_FS-W [ 2401.346524] at: [ 2401.347190] [ 2401.347228] [] lock_acquire+0x4c/0x68 [ 2401.347984] [ 2401.348024] [] down_write_nested+0x30/0x7c [ 2401.348760] [ 2401.348798] [] jfs_get_block+0x50/0x370 [ 2401.349559] [ 2401.349599] [] __block_write_full_page+0x31c/0x4a0 [ 2401.350372] [ 2401.350410] [] shrink_page_list+0x868/0xdc8 [ 2401.351166] [ 2401.351248] [] shrink_inactive_list+0x22c/0x404 [ 2401.352021] [ 2401.352058] [] shrink_node+0x388/0x67c [ 2401.352812] [ 2401.352851] [] kswapd+0x3c4/0x560 [ 2401.353582] [ 2401.353620] [] kthread+0xbc/0xd0 [ 2401.354361] [ 2401.354400] [] ret_from_kernel_thread+0x5c/0x64 [ 2401.355140] INITIAL USE [ 2401.355169] at: [ 2401.355858] [ 2401.355898] [] lock_acquire+0x4c/0x68 [ 2401.356627] [ 2401.356662] [] down_read_nested+0x30/0x74 [ 2401.357414] [ 2401.357456] [] jfs_get_block+0x118/0x370 [ 2401.358208] [ 2401.358244] [] do_mpage_readpage+0x444/0x814 [ 2401.359013] [ 2401.359051] [] mpage_readpages+0x100/0x190 [ 2401.359789] [ 2401.359842] [] __do_page_cache_readahead+0x260/0x32c [ 2401.360659] [ 2401.360703] [] generic_file_read_iter+0x638/0x898 [ 2401.361475] [ 2401.361616] [] __vfs_read+0xd8/0x180 [ 2401.362308] [ 2401.362413] [] vfs_read+0x98/0x1c4 [ 2401.363099] [ 2401.363173] [] prepare_binprm+0xd0/0x158 [ 2401.363895] [ 2401.363976] [] do_execveat_common+0x4d4/0x76c [ 2401.364704] [ 2401.364744] [] do_execve+0x2c/0x3c [ 2401.365478] [ 2401.365518] [] try_to_run_init_process+0x18/0x58 [ 2401.366253] [ 2401.366289] [] kernel_init+0xc0/0x128 [ 2401.367046] [ 2401.367083] [] ret_from_kernel_thread+0x5c/0x64 [ 2401.367865] } [ 2401.368531] ... key at: [ 2401.368566] [] __key.33790+0x0/0x8 [ 2401.369316] ... acquired at: [ 2401.370021] [ 2401.370049] [] mark_lock+0x3dc/0x72c [ 2401.370682] [ 2401.370814] [] __lock_acquire+0x204/0x16b4 [ 2401.371433] [ 2401.371540] [] lock_acquire+0x4c/0x68 [ 2401.372155] [ 2401.372249] [] down_write_nested+0x30/0x7c [ 2401.373188] [ 2401.373216] [] jfs_get_block+0x50/0x370 [ 2401.373939] [ 2401.374003] [] __block_write_full_page+0x31c/0x4a0 [ 2401.374869] [ 2401.374901] [] shrink_page_list+0x868/0xdc8 [ 2401.375675] [ 2401.375701] [] shrink_inactive_list+0x22c/0x404 [ 2401.376477] [ 2401.376504] [] shrink_node+0x388/0x67c [ 2401.377262] [ 2401.377288] [] kswapd+0x3c4/0x560 [ 2401.378039] [ 2401.378065] [] kthread+0xbc/0xd0 [ 2401.378829] [ 2401.378857] [] 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