Re: Hang triggered by udev coldplug, looks like a race

[Andy Lutomirski]

On Thu, Dec 3, 2015 at 9:52 PM, Andy Lutomirski <luto@xxxxxxxxxxxxxx> 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.057017]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.057632]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.058242]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.058790]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.059272]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.059805]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.060352]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.060966]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.061805]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.062316]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.062916]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.063355]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.063951]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.064416]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.069814]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.070361]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.070898]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.071381]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.071825]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.072299]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.072756]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.073289]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.073832]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.074316]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.075083]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.075736]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.076648]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.077235]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.083871]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.084533]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.085181]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.085761]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.086300]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.086869]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.087422]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.088067]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.088722]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.089301]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.089991]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.090552]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.091274]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.091832]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.098472]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.099136]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.099786]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.100368]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.100902]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.101478]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.102060]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.102706]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.103366]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.103947]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.104647]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.105205]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.105923]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.106494]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.113325]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.113990]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.114652]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.115240]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.115807]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.116385]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.116942]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.117595]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.118261]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.118845]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.119548]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.120110]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.120836]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.121406]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.128052]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.128720]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.129380]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.129995]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.130570]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.131150]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.131733]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.132410]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.133106]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.133692]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.134393]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.134951]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.135711]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.136280]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.142998]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.143657]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.144307]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.144895]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.145455]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.146117]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.146715]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.147391]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.148081]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.148660]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.149380]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.149905]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.150629]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.151189]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.157813]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.158478]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.159125]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.159731]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.160294]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.160864]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.161414]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.162058]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.162711]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.163315]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.164038]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.164586]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.165305]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.165890]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.172587]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.173263]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.173928]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.174550]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.175097]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.175703]  [<ffffffff811afa1c>] ? alloc_pages_current+0x8c/0x100
> [   60.176354]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.176955]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.177630]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.178303]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.178984]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.179701]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.180268]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.181057]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.181625]  [<ffffffff810b8c40>] ? 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]  [<ffffffff818d2bfe>] schedule+0x2e/0x70
> [   60.188495]  [<ffffffff818d2f29>] schedule_preempt_disabled+0x9/0x10
> [   60.189193]  [<ffffffff818d5457>] __mutex_lock_slowpath+0x107/0x2f0
> [   60.189851]  [<ffffffff811c9123>] ? lookup_fast+0x133/0x2e0
> [   60.190472]  [<ffffffff818d5655>] mutex_lock+0x15/0x30
> [   60.191043]  [<ffffffff811cc76f>] path_openat+0x63f/0x1220
> [   60.191649]  [<ffffffff811ce339>] do_filp_open+0x79/0xd0
> [   60.192112]  [<ffffffff8130a136>] ? selinux_cred_prepare+0x16/0x30
> [   60.192678]  [<ffffffff8130449e>] ? security_prepare_creds+0x3e/0x60
> [   60.193248]  [<ffffffff811c403f>] do_open_execat+0x5f/0x150
> [   60.193722]  [<ffffffff811c5d53>] do_execveat_common.isra.33+0x1a3/0x6c0
> [   60.194291]  [<ffffffff811c6297>] do_execve+0x27/0x30
> [   60.194724]  [<ffffffff810b8d2b>] call_usermodehelper_exec_async+0xeb/0x140
> [   60.195318]  [<ffffffff818d7712>] ret_from_fork+0x22/0x40
> [   60.195781]  [<ffffffff810b8c40>] ? umh_complete+0x40/0x40



-- 
Andy Lutomirski
AMA Capital Management, LLC
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/