Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1283590 > unrolled thread

Hang triggered by udev coldplug, looks like a race

Started byAndy Lutomirski <luto@amacapital.net>
First post2015-12-04 07:00 +0100
Last post2015-12-09 07:50 +0100
Articles 8 — 3 participants

Back to article view | Back to linux.kernel

Contents

  Hang triggered by udev coldplug, looks like a race Andy Lutomirski <luto@amacapital.net> - 2015-12-04 07:00 +0100
    Re: Hang triggered by udev coldplug, looks like a race Andy Lutomirski <luto@amacapital.net> - 2015-12-07 20:20 +0100
      Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a  race Dominique Martinet <dominique.martinet@cea.fr> - 2015-12-08 00:00 +0100
        Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a  race Al Viro <viro@ZenIV.linux.org.uk> - 2015-12-08 03:40 +0100
          Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race Andy Lutomirski <luto@amacapital.net> - 2015-12-08 23:50 +0100
            Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a  race Dominique Martinet <dominique.martinet@cea.fr> - 2015-12-09 07:30 +0100
              Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a  race Dominique Martinet <dominique.martinet@cea.fr> - 2015-12-09 07:50 +0100
              Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a  race Al Viro <viro@ZenIV.linux.org.uk> - 2015-12-09 07:50 +0100

#1283590 — Hang triggered by udev coldplug, looks like a race

FromAndy Lutomirski <luto@amacapital.net>
Date2015-12-04 07:00 +0100
SubjectHang triggered by udev coldplug, looks like a race
Message-ID<qBRzs-76c-9@gated-at.bofh.it>
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.

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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1285866

FromAndy Lutomirski <luto@amacapital.net>
Date2015-12-07 20:20 +0100
Message-ID<qD9ui-eC-9@gated-at.bofh.it>
In reply to#1283590
On Thu, Dec 3, 2015 at 9:52 PM, Andy Lutomirski <luto@amacapital.net> 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@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1286075 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromDominique Martinet <dominique.martinet@cea.fr>
Date2015-12-08 00:00 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDcVc-2rG-9@gated-at.bofh.it>
In reply to#1285866
Andy Lutomirski wrote on Mon, Dec 07, 2015:
> On Thu, Dec 3, 2015 at 9:52 PM, Andy Lutomirski <luto@amacapital.net> 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.

Can you reproduce it on a booted system with something like
`seq 1 1000000 | xargs -P 1024 -I{} cat /sbin/foo >&/dev/null` ?

(trying execs might be closer to your workload, not sure how much this
or using umh might change)


Also, what qemu version please just to try to match your environment ?

-- 
Dominique Martinet
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1286169 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2015-12-08 03:40 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDgm5-4Et-13@gated-at.bofh.it>
In reply to#1286075
On Mon, Dec 07, 2015 at 05:59:41PM -0800, Andy Lutomirski wrote:

> If I dump all task states (see attached typescript), I see a bunch of
> things blocked in 9p rpc.  This makes me think it could be a QEMU bug,
> not a kernel bug.

Maybe, maybe not - I'd suggest dumping the 9p traffic and checking the
request and response IDs; at least one bug in that area got fixed
(see commit a84b69 for gory details).

Really, check if something gets screwed with IDs.  They should be unique
among outstanding requests and never reused until either a response
with the matching ID arrives, *or* TFLUSH on that ID is sent and reply
has arrived.   If those rules get buggered, it's very easy to get hangs
like that.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1286903 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromAndy Lutomirski <luto@amacapital.net>
Date2015-12-08 23:50 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDzf3-8k5-1@gated-at.bofh.it>
In reply to#1286169

[Multipart message — attachments visible in raw view] — view raw

On Mon, Dec 7, 2015 at 6:33 PM, Al Viro <viro@zeniv.linux.org.uk> wrote:
> On Mon, Dec 07, 2015 at 05:59:41PM -0800, Andy Lutomirski wrote:
>
>> If I dump all task states (see attached typescript), I see a bunch of
>> things blocked in 9p rpc.  This makes me think it could be a QEMU bug,
>> not a kernel bug.
>
> Maybe, maybe not - I'd suggest dumping the 9p traffic and checking the
> request and response IDs; at least one bug in that area got fixed
> (see commit a84b69 for gory details).
>
> Really, check if something gets screwed with IDs.  They should be unique
> among outstanding requests and never reused until either a response
> with the matching ID arrives, *or* TFLUSH on that ID is sent and reply
> has arrived.   If those rules get buggered, it's very easy to get hangs
> like that.

Trace attached.  I don't see anything wrong, but I also don't know
what I'm looking for.

--Andy

-- 
Andy Lutomirski
AMA Capital Management, LLC

[toc] | [prev] | [next] | [standalone]

#1287140 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromDominique Martinet <dominique.martinet@cea.fr>
Date2015-12-09 07:30 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDGqd-4EB-5@gated-at.bofh.it>
In reply to#1286903

[Multipart message — attachments visible in raw view] — view raw

Andy Lutomirski wrote on Tue, Dec 08, 2015:
> Trace attached.  I don't see anything wrong, but I also don't know
> what I'm looking for.

Actually doesn't look good, not sure if trace could be missing messages
but it looks like tags get reused...

Quick and dirty parse script (attached output, it doesn't handle TFLUSH
but there are none in his message):

awk '{print NR " " $0}' 9ptrace.txt | \
awk '/^[0-9]* T/ {
	if ($5 in tag) {
		print "DOUBLETAG " $0 " || had " tag[$5];
    } else {
		tag[$5] = $0;
	}
}
/^[0-9]* R/ {
	if (! $5 in tag ) {
		print "MISSTAG " $0;
	} else {
		delete tag[$5];
	}
}'


-- 
Dominique Martinet

[toc] | [prev] | [next] | [standalone]

#1287155 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromDominique Martinet <dominique.martinet@cea.fr>
Date2015-12-09 07:50 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDGJz-4OU-15@gated-at.bofh.it>
In reply to#1287140
Dominique Martinet wrote on Wed, Dec 09, 2015:
> Andy Lutomirski wrote on Tue, Dec 08, 2015:
> > Trace attached.  I don't see anything wrong, but I also don't know
> > what I'm looking for.
> 
> Actually doesn't look good, not sure if trace could be missing messages
> but it looks like tags get reused...

talked too fast as usual, it looks like traces are just missing RCLUNKS
so *from what I can see* there's no overlap

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

[toc] | [prev] | [next] | [standalone]

#1287157 — Re: [V9fs-developer] Hang triggered by udev coldplug, looks like a race

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2015-12-09 07:50 +0100
SubjectRe: [V9fs-developer] Hang triggered by udev coldplug, looks like a race
Message-ID<qDGJz-4OU-21@gated-at.bofh.it>
In reply to#1287140
On Wed, Dec 09, 2015 at 07:23:16AM +0100, Dominique Martinet wrote:
> Andy Lutomirski wrote on Tue, Dec 08, 2015:
> > Trace attached.  I don't see anything wrong, but I also don't know
> > what I'm looking for.
> 
> Actually doesn't look good, not sure if trace could be missing messages
> but it looks like tags get reused...
> 
> Quick and dirty parse script (attached output, it doesn't handle TFLUSH
> but there are none in his message):

There's also not a single RCLUNK in there, which looks like missing packets.
AFAICS, all (apparent) tag reuses caught by your awk script are of that nature.
And all RERROR are plain "no such file" in response to TWALK; all those
TCLUNK in there get no reply whatsoever - neither success nor failure...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web