* [PATCH 0/1] block: don't inject fake timeouts on quiesced queues @ 2020-05-08 21:46 Alan Adamson 2020-05-08 22:05 ` Ming Lei 0 siblings, 1 reply; 4+ messages in thread From: Alan Adamson @ 2020-05-08 21:46 UTC (permalink / raw) To: axboe, linux-block; +Cc: alan.adamson, martin.petersen, himanshu.madhani While using the block fake timeout injector to reproduce a nvme error handling hang, a hang was observed when the following script was run: echo 100 > /sys/kernel/debug/fail_io_timeout/probability echo 1000 > /sys/kernel/debug/fail_io_timeout/times echo 1 > /sys/block/nvme0n1/io-timeout-fail dd if=/dev/nvme0n1 of=/dev/null bs=512 count=1 dmesg: [ 370.018164] INFO: task kworker/u113:9:1191 blocked for more than 122 seconds. [ 370.018849] Not tainted 5.7.0-rc4 #1 [ 370.019251] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 370.019653] kworker/u113:9 D 0 1191 2 0x80004000 [ 370.019660] Workqueue: nvme-reset-wq nvme_reset_work [nvme] [ 370.019661] Call Trace: [ 370.019667] __schedule+0x2dc/0x710 [ 370.019668] schedule+0x44/0xb0 [ 370.019671] blk_mq_freeze_queue_wait+0x4b/0xb0 [ 370.019675] ? finish_wait+0x80/0x80 [ 370.019681] nvme_wait_freeze+0x36/0x50 [nvme_core] [ 370.019683] nvme_reset_work+0xb65/0xf2b [nvme] [ 370.019688] process_one_work+0x1ab/0x380 [ 370.019689] worker_thread+0x37/0x3b0 [ 370.019691] kthread+0x120/0x140 [ 370.019692] ? create_worker+0x1b0/0x1b0 [ 370.019693] ? kthread_park+0x90/0x90 [ 370.019696] ret_from_fork+0x35/0x40 This occurs when a fake timeout is scheduled on a request that is in he process of being cancelled due to the previous fake timeout. Alan Adamson (1): block: don't inject fake timeouts on quiesced queues block/blk-timeout.c | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) -- 1.8.3.1 ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues 2020-05-08 21:46 [PATCH 0/1] block: don't inject fake timeouts on quiesced queues Alan Adamson @ 2020-05-08 22:05 ` Ming Lei 2020-05-08 22:23 ` Alan Adamson 0 siblings, 1 reply; 4+ messages in thread From: Ming Lei @ 2020-05-08 22:05 UTC (permalink / raw) To: Alan Adamson; +Cc: axboe, linux-block, martin.petersen, himanshu.madhani On Fri, May 08, 2020 at 02:46:34PM -0700, Alan Adamson wrote: > While using the block fake timeout injector to reproduce a nvme error handling hang, a hang was > observed when the following script was run: > > echo 100 > /sys/kernel/debug/fail_io_timeout/probability > echo 1000 > /sys/kernel/debug/fail_io_timeout/times > echo 1 > /sys/block/nvme0n1/io-timeout-fail > dd if=/dev/nvme0n1 of=/dev/null bs=512 count=1 > > > dmesg: > > [ 370.018164] INFO: task kworker/u113:9:1191 blocked for more than 122 seconds. > [ 370.018849] Not tainted 5.7.0-rc4 #1 > [ 370.019251] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 370.019653] kworker/u113:9 D 0 1191 2 0x80004000 > [ 370.019660] Workqueue: nvme-reset-wq nvme_reset_work [nvme] > [ 370.019661] Call Trace: > [ 370.019667] __schedule+0x2dc/0x710 > [ 370.019668] schedule+0x44/0xb0 > [ 370.019671] blk_mq_freeze_queue_wait+0x4b/0xb0 > [ 370.019675] ? finish_wait+0x80/0x80 > [ 370.019681] nvme_wait_freeze+0x36/0x50 [nvme_core] > [ 370.019683] nvme_reset_work+0xb65/0xf2b [nvme] > [ 370.019688] process_one_work+0x1ab/0x380 > [ 370.019689] worker_thread+0x37/0x3b0 > [ 370.019691] kthread+0x120/0x140 > [ 370.019692] ? create_worker+0x1b0/0x1b0 > [ 370.019693] ? kthread_park+0x90/0x90 > [ 370.019696] ret_from_fork+0x35/0x40 > > This occurs when a fake timeout is scheduled on a request that is in he process > of being cancelled due to the previous fake timeout. Not sure root cause is timeout injection, and in theory request queue shouldn't have been quiesced before freezing, otherwise it is easy to cause deadlock. BTW, could you share us how you conclude it is related with queue quiesce? Thanks, Ming ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues 2020-05-08 22:05 ` Ming Lei @ 2020-05-08 22:23 ` Alan Adamson 2020-05-09 2:28 ` Ming Lei 0 siblings, 1 reply; 4+ messages in thread From: Alan Adamson @ 2020-05-08 22:23 UTC (permalink / raw) To: Ming Lei; +Cc: axboe, linux-block, martin.petersen, himanshu.madhani > On May 8, 2020, at 3:05 PM, Ming Lei <ming.lei@redhat.com> wrote: > > On Fri, May 08, 2020 at 02:46:34PM -0700, Alan Adamson wrote: >> While using the block fake timeout injector to reproduce a nvme error handling hang, a hang was >> observed when the following script was run: >> >> echo 100 > /sys/kernel/debug/fail_io_timeout/probability >> echo 1000 > /sys/kernel/debug/fail_io_timeout/times >> echo 1 > /sys/block/nvme0n1/io-timeout-fail >> dd if=/dev/nvme0n1 of=/dev/null bs=512 count=1 >> >> >> dmesg: >> >> [ 370.018164] INFO: task kworker/u113:9:1191 blocked for more than 122 seconds. >> [ 370.018849] Not tainted 5.7.0-rc4 #1 >> [ 370.019251] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> [ 370.019653] kworker/u113:9 D 0 1191 2 0x80004000 >> [ 370.019660] Workqueue: nvme-reset-wq nvme_reset_work [nvme] >> [ 370.019661] Call Trace: >> [ 370.019667] __schedule+0x2dc/0x710 >> [ 370.019668] schedule+0x44/0xb0 >> [ 370.019671] blk_mq_freeze_queue_wait+0x4b/0xb0 >> [ 370.019675] ? finish_wait+0x80/0x80 >> [ 370.019681] nvme_wait_freeze+0x36/0x50 [nvme_core] >> [ 370.019683] nvme_reset_work+0xb65/0xf2b [nvme] >> [ 370.019688] process_one_work+0x1ab/0x380 >> [ 370.019689] worker_thread+0x37/0x3b0 >> [ 370.019691] kthread+0x120/0x140 >> [ 370.019692] ? create_worker+0x1b0/0x1b0 >> [ 370.019693] ? kthread_park+0x90/0x90 >> [ 370.019696] ret_from_fork+0x35/0x40 >> >> This occurs when a fake timeout is scheduled on a request that is in he process >> of being cancelled due to the previous fake timeout. > > Not sure root cause is timeout injection, and in theory request queue shouldn't > have been quiesced before freezing, otherwise it is easy to cause deadlock. It's the handling of the previously injected timeout that causes the queue to the quiesed. When the request is attempted to be canceled (as part of the nvme reset) the request is setup for another timeout and doesn’t get cancelled and the hang then occurs. Alan > > BTW, could you share us how you conclude it is related with queue quiesce? > > Thanks, > Ming > ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues 2020-05-08 22:23 ` Alan Adamson @ 2020-05-09 2:28 ` Ming Lei 0 siblings, 0 replies; 4+ messages in thread From: Ming Lei @ 2020-05-09 2:28 UTC (permalink / raw) To: Alan Adamson; +Cc: axboe, linux-block, martin.petersen, himanshu.madhani On Fri, May 08, 2020 at 03:23:32PM -0700, Alan Adamson wrote: > > > > On May 8, 2020, at 3:05 PM, Ming Lei <ming.lei@redhat.com> wrote: > > > > On Fri, May 08, 2020 at 02:46:34PM -0700, Alan Adamson wrote: > >> While using the block fake timeout injector to reproduce a nvme error handling hang, a hang was > >> observed when the following script was run: > >> > >> echo 100 > /sys/kernel/debug/fail_io_timeout/probability > >> echo 1000 > /sys/kernel/debug/fail_io_timeout/times > >> echo 1 > /sys/block/nvme0n1/io-timeout-fail > >> dd if=/dev/nvme0n1 of=/dev/null bs=512 count=1 > >> > >> > >> dmesg: > >> > >> [ 370.018164] INFO: task kworker/u113:9:1191 blocked for more than 122 seconds. > >> [ 370.018849] Not tainted 5.7.0-rc4 #1 > >> [ 370.019251] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > >> [ 370.019653] kworker/u113:9 D 0 1191 2 0x80004000 > >> [ 370.019660] Workqueue: nvme-reset-wq nvme_reset_work [nvme] > >> [ 370.019661] Call Trace: > >> [ 370.019667] __schedule+0x2dc/0x710 > >> [ 370.019668] schedule+0x44/0xb0 > >> [ 370.019671] blk_mq_freeze_queue_wait+0x4b/0xb0 > >> [ 370.019675] ? finish_wait+0x80/0x80 > >> [ 370.019681] nvme_wait_freeze+0x36/0x50 [nvme_core] > >> [ 370.019683] nvme_reset_work+0xb65/0xf2b [nvme] > >> [ 370.019688] process_one_work+0x1ab/0x380 > >> [ 370.019689] worker_thread+0x37/0x3b0 > >> [ 370.019691] kthread+0x120/0x140 > >> [ 370.019692] ? create_worker+0x1b0/0x1b0 > >> [ 370.019693] ? kthread_park+0x90/0x90 > >> [ 370.019696] ret_from_fork+0x35/0x40 > >> > >> This occurs when a fake timeout is scheduled on a request that is in he process > >> of being cancelled due to the previous fake timeout. > > > > Not sure root cause is timeout injection, and in theory request queue shouldn't > > have been quiesced before freezing, otherwise it is easy to cause deadlock. > > It's the handling of the previously injected timeout that causes the queue to the quiesed. When the request is attempted to be canceled (as part of the > nvme reset) the request is setup for another timeout and doesn’t get cancelled and the hang then occurs. Got it, that is exactly the fragile nvme EH handling, and nvme timeout handling should be fixed instead of error injection code. The value of fault injection is exactly for finding issue, instead of avoiding issue, so NAK this patch. I remember that block/011 of blktests can trigger similar issue too, unfortunately it is still not fixed after years. Thanks, Ming ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2020-05-09 2:29 UTC | newest] Thread overview: 4+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2020-05-08 21:46 [PATCH 0/1] block: don't inject fake timeouts on quiesced queues Alan Adamson 2020-05-08 22:05 ` Ming Lei 2020-05-08 22:23 ` Alan Adamson 2020-05-09 2:28 ` Ming Lei
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).