From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932651AbbLGTTO (ORCPT ); Mon, 7 Dec 2015 14:19:14 -0500 Received: from mail-ob0-f172.google.com ([209.85.214.172]:32780 "EHLO mail-ob0-f172.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932307AbbLGTTM (ORCPT ); Mon, 7 Dec 2015 14:19:12 -0500 MIME-Version: 1.0 In-Reply-To: References: From: Andy Lutomirski Date: Mon, 7 Dec 2015 11:18:51 -0800 Message-ID: Subject: Re: Hang triggered by udev coldplug, looks like a race To: "linux-kernel@vger.kernel.org" , V9FS Developers , Linux FS Devel Content-Type: text/plain; charset=UTF-8 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu, Dec 3, 2015 at 9:52 PM, Andy Lutomirski wrote: > Sometimes udevadm trigger --action=add hangs the system, and the splat > below happens. This seems to be timing dependent, and I haven't been > able to trigger it yet with lockdep enabled, sadly. > > Any ideas? I not, I'll try to instrument it better tomorrow. More details: this is caused by a storm of /sbin/hotplug UMH calls (yes, misconfigured kernel, but still). /sbin is a symlink to /usr/sbin, /usr/sbin/hotplug doesn't exist, and all of the above is on rootfs, which is 9p over virtio. Pointing uevent_helper at /usr/sbin/hotplug (which still doesn't exist) seems to work around it. > > This is 4.4-rc3 plus some patches that I don't think are related. The > rootfs is 9p. > > --Andy > > [ 60.048359] INFO: task kworker/u2:1:980 blocked for more than 30 seconds. > [ 60.051673] Not tainted 4.3.0-rc4+ #3 > [ 60.052149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.053013] kworker/u2:1 D ffff880006823bc8 14152 980 14 0x00000000 > [ 60.053786] ffff880006823bc8 ffff8800072e4740 ffff8800072e63c0 > ffff880006824000 > [ 60.054637] ffff88000613cfd0 ffff8800072e63c0 00000000ffffffff > 0000000000000246 > [ 60.055447] ffff880006823be0 ffffffff818d2bfe ffff88000613cfc8 > ffff880006823bf0 > [ 60.056250] Call Trace: > [ 60.056513] [] schedule+0x2e/0x70 > [ 60.057017] [] schedule_preempt_disabled+0x9/0x10 > [ 60.057632] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.058242] [] ? lookup_fast+0x133/0x2e0 > [ 60.058790] [] mutex_lock+0x15/0x30 > [ 60.059272] [] path_openat+0x63f/0x1220 > [ 60.059805] [] do_filp_open+0x79/0xd0 > [ 60.060352] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.060966] [] ? security_prepare_creds+0x3e/0x60 > [ 60.061805] [] do_open_execat+0x5f/0x150 > [ 60.062316] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.062916] [] do_execve+0x27/0x30 > [ 60.063355] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.063951] [] ret_from_fork+0x22/0x40 > [ 60.064416] [] ? umh_complete+0x40/0x40 > [ 60.064889] INFO: task kworker/u2:1:981 blocked for more than 30 seconds. > [ 60.065473] Not tainted 4.3.0-rc4+ #3 > [ 60.065834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.066507] kworker/u2:1 D ffff880006827bc8 14152 981 14 0x00000000 > [ 60.067135] ffff880006827bc8 ffff880006965580 ffff8800072e0e40 > ffff880006828000 > [ 60.067810] ffff88000613cfd0 ffff8800072e0e40 00000000ffffffff > 0000000000000246 > [ 60.068491] ffff880006827be0 ffffffff818d2bfe ffff88000613cfc8 > ffff880006827bf0 > [ 60.069169] Call Trace: > [ 60.069386] [] schedule+0x2e/0x70 > [ 60.069814] [] schedule_preempt_disabled+0x9/0x10 > [ 60.070361] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.070898] [] ? lookup_fast+0x133/0x2e0 > [ 60.071381] [] mutex_lock+0x15/0x30 > [ 60.071825] [] path_openat+0x63f/0x1220 > [ 60.072299] [] do_filp_open+0x79/0xd0 > [ 60.072756] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.073289] [] ? security_prepare_creds+0x3e/0x60 > [ 60.073832] [] do_open_execat+0x5f/0x150 > [ 60.074316] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.075083] [] do_execve+0x27/0x30 > [ 60.075736] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.076648] [] ret_from_fork+0x22/0x40 > [ 60.077235] [] ? umh_complete+0x40/0x40 > [ 60.077805] INFO: task kworker/u2:1:982 blocked for more than 30 seconds. > [ 60.078529] Not tainted 4.3.0-rc4+ #3 > [ 60.078969] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.079891] kworker/u2:1 D ffff88000682bbc8 14584 982 14 0x00000000 > [ 60.080658] ffff88000682bbc8 ffff8800064cb900 ffff880006bc0e40 > ffff88000682c000 > [ 60.081474] ffff88000613cfd0 ffff880006bc0e40 00000000ffffffff > 0000000000000246 > [ 60.082282] ffff88000682bbe0 ffffffff818d2bfe ffff88000613cfc8 > ffff88000682bbf0 > [ 60.083095] Call Trace: > [ 60.083357] [] schedule+0x2e/0x70 > [ 60.083871] [] schedule_preempt_disabled+0x9/0x10 > [ 60.084533] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.085181] [] ? lookup_fast+0x133/0x2e0 > [ 60.085761] [] mutex_lock+0x15/0x30 > [ 60.086300] [] path_openat+0x63f/0x1220 > [ 60.086869] [] do_filp_open+0x79/0xd0 > [ 60.087422] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.088067] [] ? security_prepare_creds+0x3e/0x60 > [ 60.088722] [] do_open_execat+0x5f/0x150 > [ 60.089301] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.089991] [] do_execve+0x27/0x30 > [ 60.090552] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.091274] [] ret_from_fork+0x22/0x40 > [ 60.091832] [] ? umh_complete+0x40/0x40 > [ 60.092401] INFO: task kworker/u2:1:983 blocked for more than 30 seconds. > [ 60.093138] Not tainted 4.3.0-rc4+ #3 > [ 60.093574] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.094379] kworker/u2:1 D ffff88000682fbc8 14544 983 14 0x00000000 > [ 60.095139] ffff88000682fbc8 ffff880006bc0e40 ffff88000644c740 > ffff880006830000 > [ 60.095973] ffff88000613cfd0 ffff88000644c740 00000000ffffffff > 0000000000000246 > [ 60.096871] ffff88000682fbe0 ffffffff818d2bfe ffff88000613cfc8 > ffff88000682fbf0 > [ 60.097686] Call Trace: > [ 60.097945] [] schedule+0x2e/0x70 > [ 60.098472] [] schedule_preempt_disabled+0x9/0x10 > [ 60.099136] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.099786] [] ? lookup_fast+0x133/0x2e0 > [ 60.100368] [] mutex_lock+0x15/0x30 > [ 60.100902] [] path_openat+0x63f/0x1220 > [ 60.101478] [] do_filp_open+0x79/0xd0 > [ 60.102060] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.102706] [] ? security_prepare_creds+0x3e/0x60 > [ 60.103366] [] do_open_execat+0x5f/0x150 > [ 60.103947] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.104647] [] do_execve+0x27/0x30 > [ 60.105205] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.105923] [] ret_from_fork+0x22/0x40 > [ 60.106494] [] ? umh_complete+0x40/0x40 > [ 60.107065] INFO: task kworker/u2:1:984 blocked for more than 30 seconds. > [ 60.107795] Not tainted 4.3.0-rc4+ #3 > [ 60.108248] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.109115] kworker/u2:1 D ffff8800068e3bc8 14152 984 14 0x00000000 > [ 60.109881] ffff8800068e3bc8 ffff880006a25580 ffff880006b65580 > ffff8800068e4000 > [ 60.110737] ffff88000613cfd0 ffff880006b65580 00000000ffffffff > 0000000000000246 > [ 60.111577] ffff8800068e3be0 ffffffff818d2bfe ffff88000613cfc8 > ffff8800068e3bf0 > [ 60.112533] Call Trace: > [ 60.112798] [] schedule+0x2e/0x70 > [ 60.113325] [] schedule_preempt_disabled+0x9/0x10 > [ 60.113990] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.114652] [] ? lookup_fast+0x133/0x2e0 > [ 60.115240] [] mutex_lock+0x15/0x30 > [ 60.115807] [] path_openat+0x63f/0x1220 > [ 60.116385] [] do_filp_open+0x79/0xd0 > [ 60.116942] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.117595] [] ? security_prepare_creds+0x3e/0x60 > [ 60.118261] [] do_open_execat+0x5f/0x150 > [ 60.118845] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.119548] [] do_execve+0x27/0x30 > [ 60.120110] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.120836] [] ret_from_fork+0x22/0x40 > [ 60.121406] [] ? umh_complete+0x40/0x40 > [ 60.121981] INFO: task kworker/u2:1:985 blocked for more than 30 seconds. > [ 60.122732] Not tainted 4.3.0-rc4+ #3 > [ 60.123177] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.123992] kworker/u2:1 D ffff8800068e7bc8 14152 985 14 0x00000000 > [ 60.124759] ffff8800068e7bc8 ffff8800073c0000 ffff880006b61c80 > ffff8800068e8000 > [ 60.125579] ffff88000613cfd0 ffff880006b61c80 00000000ffffffff > 0000000000000246 > [ 60.126389] ffff8800068e7be0 ffffffff818d2bfe ffff88000613cfc8 > ffff8800068e7bf0 > [ 60.127258] Call Trace: > [ 60.127525] [] schedule+0x2e/0x70 > [ 60.128052] [] schedule_preempt_disabled+0x9/0x10 > [ 60.128720] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.129380] [] ? lookup_fast+0x133/0x2e0 > [ 60.129995] [] mutex_lock+0x15/0x30 > [ 60.130570] [] path_openat+0x63f/0x1220 > [ 60.131150] [] do_filp_open+0x79/0xd0 > [ 60.131733] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.132410] [] ? security_prepare_creds+0x3e/0x60 > [ 60.133106] [] do_open_execat+0x5f/0x150 > [ 60.133692] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.134393] [] do_execve+0x27/0x30 > [ 60.134951] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.135711] [] ret_from_fork+0x22/0x40 > [ 60.136280] [] ? umh_complete+0x40/0x40 > [ 60.136856] INFO: task kworker/u2:1:986 blocked for more than 30 seconds. > [ 60.137600] Not tainted 4.3.0-rc4+ #3 > [ 60.138073] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.138881] kworker/u2:1 D ffff8800068ebbc8 14152 986 14 0x00000000 > [ 60.139672] ffff8800068ebbc8 ffff8800066bc740 ffff880006b663c0 > ffff8800068ec000 > [ 60.140545] ffff88000613cfd0 ffff880006b663c0 00000000ffffffff > 0000000000000246 > [ 60.141356] ffff8800068ebbe0 ffffffff818d2bfe ffff88000613cfc8 > ffff8800068ebbf0 > [ 60.142209] Call Trace: > [ 60.142487] [] schedule+0x2e/0x70 > [ 60.142998] [] schedule_preempt_disabled+0x9/0x10 > [ 60.143657] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.144307] [] ? lookup_fast+0x133/0x2e0 > [ 60.144895] [] mutex_lock+0x15/0x30 > [ 60.145455] [] path_openat+0x63f/0x1220 > [ 60.146117] [] do_filp_open+0x79/0xd0 > [ 60.146715] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.147391] [] ? security_prepare_creds+0x3e/0x60 > [ 60.148081] [] do_open_execat+0x5f/0x150 > [ 60.148660] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.149380] [] do_execve+0x27/0x30 > [ 60.149905] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.150629] [] ret_from_fork+0x22/0x40 > [ 60.151189] [] ? umh_complete+0x40/0x40 > [ 60.151787] INFO: task kworker/u2:1:987 blocked for more than 30 seconds. > [ 60.152497] Not tainted 4.3.0-rc4+ #3 > [ 60.152927] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.153735] kworker/u2:1 D ffff8800068efbc8 14152 987 14 0x00000000 > [ 60.154524] ffff8800068efbc8 ffff880007234740 ffff880006bf9c80 > ffff8800068f0000 > [ 60.155389] ffff88000613cfd0 ffff880006bf9c80 00000000ffffffff > 0000000000000246 > [ 60.156227] ffff8800068efbe0 ffffffff818d2bfe ffff88000613cfc8 > ffff8800068efbf0 > [ 60.157040] Call Trace: > [ 60.157299] [] schedule+0x2e/0x70 > [ 60.157813] [] schedule_preempt_disabled+0x9/0x10 > [ 60.158478] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.159125] [] ? lookup_fast+0x133/0x2e0 > [ 60.159731] [] mutex_lock+0x15/0x30 > [ 60.160294] [] path_openat+0x63f/0x1220 > [ 60.160864] [] do_filp_open+0x79/0xd0 > [ 60.161414] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.162058] [] ? security_prepare_creds+0x3e/0x60 > [ 60.162711] [] do_open_execat+0x5f/0x150 > [ 60.163315] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.164038] [] do_execve+0x27/0x30 > [ 60.164586] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.165305] [] ret_from_fork+0x22/0x40 > [ 60.165890] [] ? umh_complete+0x40/0x40 > [ 60.166490] INFO: task kworker/u2:1:988 blocked for more than 30 seconds. > [ 60.167220] Not tainted 4.3.0-rc4+ #3 > [ 60.167682] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.168515] kworker/u2:1 D ffff880006913bc8 14152 988 14 0x00000000 > [ 60.169270] ffff880006913bc8 ffff8800001663c0 ffff880006bfc740 > ffff880006914000 > [ 60.170081] ffff88000613cfd0 ffff880006bfc740 00000000ffffffff > 0000000000000246 > [ 60.170884] ffff880006913be0 ffffffff818d2bfe ffff88000613cfc8 > ffff880006913bf0 > [ 60.171742] Call Trace: > [ 60.172037] [] schedule+0x2e/0x70 > [ 60.172587] [] schedule_preempt_disabled+0x9/0x10 > [ 60.173263] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.173928] [] ? lookup_fast+0x133/0x2e0 > [ 60.174550] [] mutex_lock+0x15/0x30 > [ 60.175097] [] path_openat+0x63f/0x1220 > [ 60.175703] [] ? alloc_pages_current+0x8c/0x100 > [ 60.176354] [] do_filp_open+0x79/0xd0 > [ 60.176955] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.177630] [] ? security_prepare_creds+0x3e/0x60 > [ 60.178303] [] do_open_execat+0x5f/0x150 > [ 60.178984] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.179701] [] do_execve+0x27/0x30 > [ 60.180268] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.181057] [] ret_from_fork+0x22/0x40 > [ 60.181625] [] ? umh_complete+0x40/0x40 > [ 60.182233] INFO: task kworker/u2:1:989 blocked for more than 30 seconds. > [ 60.182972] Not tainted 4.3.0-rc4+ #3 > [ 60.183420] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 60.184268] kworker/u2:1 D ffff880006917bc8 14152 989 14 0x00000000 > [ 60.185063] ffff880006917bc8 ffff880000149c80 ffff880006bf8e40 > ffff880006918000 > [ 60.185954] ffff88000613cfd0 ffff880006bf8e40 00000000ffffffff > 0000000000000246 > [ 60.186806] ffff880006917be0 ffffffff818d2bfe ffff88000613cfc8 > ffff880006917bf0 > [ 60.187672] Call Trace: > [ 60.187937] [] schedule+0x2e/0x70 > [ 60.188495] [] schedule_preempt_disabled+0x9/0x10 > [ 60.189193] [] __mutex_lock_slowpath+0x107/0x2f0 > [ 60.189851] [] ? lookup_fast+0x133/0x2e0 > [ 60.190472] [] mutex_lock+0x15/0x30 > [ 60.191043] [] path_openat+0x63f/0x1220 > [ 60.191649] [] do_filp_open+0x79/0xd0 > [ 60.192112] [] ? selinux_cred_prepare+0x16/0x30 > [ 60.192678] [] ? security_prepare_creds+0x3e/0x60 > [ 60.193248] [] do_open_execat+0x5f/0x150 > [ 60.193722] [] do_execveat_common.isra.33+0x1a3/0x6c0 > [ 60.194291] [] do_execve+0x27/0x30 > [ 60.194724] [] call_usermodehelper_exec_async+0xeb/0x140 > [ 60.195318] [] ret_from_fork+0x22/0x40 > [ 60.195781] [] ? umh_complete+0x40/0x40 -- Andy Lutomirski AMA Capital Management, LLC