[PATCH 0/1] block: don't inject fake timeouts on quiesced queues

[PATCH 0/1] block: don't inject fake timeouts on quiesced queues

[Alan Adamson]

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

Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues

[Ming Lei]

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

Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues

[Alan Adamson]

> 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
> 

Re: [PATCH 0/1] block: don't inject fake timeouts on quiesced queues

[Ming Lei]

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