Re: rq pointer in tags->rqs[] is not cleared in time and make SCSI error handle can not be triggered

[Ming Lei <ming.lei@redhat.com>]

On Thu, Aug 26, 2021 at 11:00:34AM +0800, luojiaxing wrote:
> Dear all:
> 
> 
> I meet some problem when test hisi_sas driver(under SCSI) based on 5.14-rc4
> kernel, it's found that error handle can not be triggered after
> 
> abnormal IO occur in some test with a low probability. For example,
> circularly run disk hardreset or disable all local phy of expander when
> running fio.
> 
> 
> We add some tracepoint and print to see what happen, and we got the
> following information:
> 
> (1).print rq and rq_state at bt_tags_iter() to confirm how many IOs is
> running now.
> 
> <4>[  897.431182] bt_tags_iter: rqs[2808]: 0xffff202007bd3000; rq_state: 1
> <4>[  897.437514] bt_tags_iter: rqs[3185]: 0xffff0020c5261e00; rq_state: 1
> <4>[  897.443841] bt_tags_iter: rqs[3612]: 0xffff00212f242a00; rq_state: 1
> <4>[  897.450167] bt_tags_iter: rqs[2808]: 0xffff00211d208100; rq_state: 1
> <4>[  897.456492] bt_tags_iter: rqs[2921]: 0xffff00211d208100; rq_state: 1
> <4>[  897.462818] bt_tags_iter: rqs[1214]: 0xffff002151d21b00; rq_state: 1
> <4>[  897.469143] bt_tags_iter: rqs[2648]: 0xffff0020c4bfa200; rq_state: 1
> 
> The preceding information show that rq with tag[2808] is found in different
> hctx by bt_tags_iter() and with different pointer saved in tags->rqs[].
> 
> And tag[2808] own the same pointer value saved in rqs[] with tag[2921]. It's
> wrong because our driver share tag between all hctx, so it's not possible

What is your io scheduler? I guess it is deadline, and can you observe
such issue by switching to none?

The tricky thing is that one request dumped may be re-allocated to other tag
after returning from bt_tags_iter().

> 
> to allocate one tag to different rq.
> 
> 
> (2).check tracepoints(temporarily add) in blk_mq_get_driver_tag() and
> blk_mq_put_tag() to see where this tag is come from.
> 
>     Line 1322969:            <...>-20189   [013] .... 893.427707:
> blk_mq_get_driver_tag: rqs[2808]: 0xffff00211d208100
>     Line 1322997:  irq/1161-hisi_s-7602    [012] d..1 893.427814:
> blk_mq_put_tag_in_free_request: rqs[2808]: 0xffff00211d208100
>     Line 1331257:            <...>-20189   [013] .... 893.462663:
> blk_mq_get_driver_tag: rqs[2860]: 0xffff00211d208100
>     Line 1331289:  irq/1161-hisi_s-7602    [012] d..1 893.462785:
> blk_mq_put_tag_in_free_request: rqs[2860]: 0xffff00211d208100
>     Line 1338493:            <...>-20189   [013] .... 893.493519:
> blk_mq_get_driver_tag: rqs[2921]: 0xffff00211d208100
> 
> As we can see this rq is allocated to tag[2808] once, and finially come to
> tag[2921], but rqs[2808] still save the pointer.

Yeah, we know this kind of handling, but not see it as issue.

> 
> There will be no problem until we encounter a rare situation.
> 
> For example, tag[2808] is reassigned to another hctx for execution, then
> some IO meet some error.

I guess the race is triggered when 2808 is just assigned, meantime
->rqs[] isn't updated.

> 
> Before waking up the error handle thread, SCSI compares the values of
> scsi_host_busy() and shost->host_failed.
> 
> If the values are different, SCSI waits for the completion of some I/Os.
> According to the print provided by (1), the return value of scsi_host_busy()
> should be 7 for tag [2808] is calculated twice,
> 
> and the value of shost->host_failed is 6. As a result, this two values are
> never equal, and error handle cannot be triggered.
> 
> 
> A temporary workaround is provided and can solve the problem as:
> 
> diff --git a/block/blk-mq-tag.c b/block/blk-mq-tag.c
> index 2a37731..e3dc773 100644
> --- a/block/blk-mq-tag.c
> +++ b/block/blk-mq-tag.c
> @@ -190,6 +190,7 @@ void blk_mq_put_tag(struct blk_mq_tags *tags, struct
> blk_mq_ctx *ctx,
>                 BUG_ON(tag >= tags->nr_reserved_tags);
>                 sbitmap_queue_clear(tags->breserved_tags, tag, ctx->cpu);
>         }
> +       tags->rqs[tag] = NULL;
>  }
> 
> 
> Since we did not encounter this problem in some previous kernel versions, we
> wondered if the community already knew about the problem or could provide
> some solutions.

Can you try the following patch?

diff --git a/block/blk-mq-tag.c b/block/blk-mq-tag.c
index 86f87346232a..97557ba0737f 100644
--- a/block/blk-mq-tag.c
+++ b/block/blk-mq-tag.c
@@ -301,7 +301,7 @@ static bool bt_tags_iter(struct sbitmap *bitmap, unsigned int bitnr, void *data)
 		return true;
 
 	if (!(iter_data->flags & BT_TAG_ITER_STARTED) ||
-	    blk_mq_request_started(rq))
+	    (blk_mq_request_started(rq) && rq->tag == bitnr))
 		ret = iter_data->fn(rq, iter_data->data, reserved);
 	if (!iter_static_rqs)
 		blk_mq_put_rq_ref(rq);



Thanks,
Ming