Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753113AbcLEWpL (ORCPT ); Mon, 5 Dec 2016 17:45:11 -0500 Received: from aserp1040.oracle.com ([141.146.126.69]:38993 "EHLO aserp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751501AbcLEWpJ (ORCPT ); Mon, 5 Dec 2016 17:45:09 -0500 Subject: Re: [Jfs-discussion] jfs: mangled lockdep splat To: Christian Kujau , jfs-discussion@lists.sourceforge.net References: Cc: linux-kernel@vger.kernel.org, Dmitry Vyukov From: Dave Kleikamp Message-ID: Date: Mon, 5 Dec 2016 16:44:48 -0600 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.5.1 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit X-Source-IP: userv0021.oracle.com [156.151.31.71] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 17195 Lines: 405 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] [] 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/ >