Re: [PATCH] blk-mq: don't fail driver tag allocation because of inactive hctx

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

On Thu, Jun 04, 2020 at 11:24:29AM +0100, John Garry wrote:
> > > > > 
> > > > > diff --git a/block/blk-mq-tag.c b/block/blk-mq-tag.c
> > > > > index 96a39d0724a29..cded7fdcad8ef 100644
> > > > > --- a/block/blk-mq-tag.c
> > > > > +++ b/block/blk-mq-tag.c
> > > > > @@ -191,6 +191,33 @@ unsigned int blk_mq_get_tag(struct blk_mq_alloc_data *data)
> > > > >        return tag + tag_offset;
> > > > >    }
> > > > >    +bool __blk_mq_get_driver_tag(struct request *rq)
> > > > > +{
> > > > > +    struct sbitmap_queue *bt = &rq->mq_hctx->tags->bitmap_tags;
> > > > > +    unsigned int tag_offset = rq->mq_hctx->tags->nr_reserved_tags;
> > > > > +    bool shared = blk_mq_tag_busy(rq->mq_hctx);
> > > > 
> > > > Not necessary to add 'shared' which is just used once.
> > > > 
> > > > > +    int tag;
> > > > > +
> > > > > +    if (blk_mq_tag_is_reserved(rq->mq_hctx->sched_tags, rq->internal_tag)) {
> > > > > +        bt = &rq->mq_hctx->tags->breserved_tags;
> > > > 
> > > > Too many rq->mq_hctx->tags, you can add one local variable to store it.
> > > > 
> > > > Otherwise, looks fine:
> > > > 
> > > > Reviewed-by: Ming Lei <ming.lei@redhat.com>
> 
> Unfortunately this looks to still have problems. So, for a start, this
> stackframe is pumped out a lot (which I removed, for below):
> 
> [  697.464058] Workqueue: kblockd blk_mq_run_work_fn
> [  697.468749] Call trace:
> [  697.471184]  dump_backtrace+0x0/0x1c0
> [  697.474833]  show_stack+0x18/0x28
> [  697.478136]  dump_stack+0xc8/0x114
> [  697.481524]  __blk_mq_run_hw_queue+0x124/0x130
> [  697.485954]  blk_mq_run_work_fn+0x20/0x30
> [  697.489951]  process_one_work+0x1e8/0x360
> [  697.493947]  worker_thread+0x238/0x478
> [  697.497683]  kthread+0x150/0x158
> [  697.500898]  ret_from_fork+0x10/0x1c
> [  697.504480] run queue from wrong CPU 32, hctx active
> [  697.509444] CPU: 32 PID: 1477 Comm: kworker/21:2H Not tainted 5.7.0-
> 
> And then other time I get SCSI timeouts:
> 
> [95.170616] psci: CPU21 killed (polled 0 ms)
> [95.419832] CPU22: shutdown
> [95.422630] psci: CPU22 killed (polled 0 ms)
> [95.683772] irq_shutdown irq1384MiB/s,w=0KiB/s][r=380k,w=0 IOPS][eta
> 00m:50s]
> [95.687013] CPU23: shutdown
> [95.689829] psci: CPU23 killed (polled 0 ms)
> [96.379817] CPU24: shutdown
> [96.382617] psci: CPU24 killed (polled 0 ms)
> [96.703823] CPU25: shutdown=1902MiB/s,w=0KiB/s][r=487k,w=0 IOPS][eta
> 00m:49s]
> [96.706667] psci: CPU25 killed (polled 0 ms)
> [97.299845] CPU26: shutdown
> [97.302647] psci: CPU26 killed (polled 0 ms)
> [97.331737] irq_shutdown irq139
> [97.334969] CPU27: shutdown
> [97.337774] psci: CPU27 killed (polled 0 ms)
> [  102.308329] CPU28: shutdown=1954MiB/s,w=0KiB/s][r=500k,w=0 IOPS][eta
> 00m:44s]
> [  102.311137] psci: CPU28 killed (polled 0 ms)
> [  102.663877] CPU29: shutdown=1755MiB/s,w=0KiB/s][r=449k,w=0 IOPS][eta
> 00m:43s]
> [  102.666679] psci: CPU29 killed (polled 0 ms)
> [  104.459867] CPU30: shutdown=1552MiB/s,w=0KiB/s][r=397k,w=0 IOPS][eta
> 00m:42s]
> [  104.462668] psci: CPU30 killed (polled 0 ms)
> [  106.259909] IRQ 43: no longer affine to CPU31s][r=414k,w=0 IOPS][eta
> 00m:40s]
> [  106.264273] IRQ 114: no longer affine to CPU31
> [  106.268707] IRQ 118: no longer affine to CPU31
> [  106.273141] IRQ 123: no longer affine to CPU31
> [  106.277579] irq_shutdown irq140
> [  106.280757] IRQ 332: no longer affine to CPU31
> [  106.285190] IRQ 336: no longer affine to CPU31
> [  106.289623] IRQ 338: no longer affine to CPU31
> [  106.294056] IRQ 340: no longer affine to CPU31
> [  106.298489] IRQ 344: no longer affine to CPU31
> [  106.302922] IRQ 348: no longer affine to CPU31
> [  106.307450] CPU31: shutdown
> [  106.310251] psci: CPU31 killed (polled 0 ms)
> [  108.367884] CPU32: shutdown=1693MiB/s,w=0KiB/s][r=434k,w=0 IOPS][eta
> 00m:38s]
> [  108.370683] psci: CPU32 killed (polled 0 ms)
> [  110.808471] CPU33: shutdown=1747MiB/s,w=0KiB/s][r=447k,w=0 IOPS][eta
> 00m:35s]
> [  110.811269] psci: CPU33 killed (polled 0 ms)
> [  110.871804] CPU34: shutdown
> [  110.874598] psci: CPU34 killed (polled 0 ms)
> [  111.767879] irq_shutdown irq1412MiB/s,w=0KiB/s][r=418k,w=0 IOPS][eta
> 00m:34s]
> [  111.771171] CPU35: shutdown
> [  111.773975] psci: CPU35 killed (polled 0 ms)
> [  113.167866] CPU36: shutdown=1680MiB/s,w=0KiB/s][r=430k,w=0 IOPS][eta
> 00m:33s]
> [  113.170673] psci: CPU36 killed (polled 0 ms)
> [  115.783879] CPU37: shutdown=1839MiB/s,w=0KiB/s][r=471k,w=0 IOPS][eta
> 00m:30s]
> [  115.786675] psci: CPU37 killed (polled 0 ms)
> [  117.111877] CPU38: shutdown=2032MiB/s,w=0KiB/s][r=520k,w=0 IOPS][eta
> 00m:29s]
> [  117.114670] psci: CPU38 killed (polled 0 ms)
> [  121.263701] irq_shutdown irq1423MiB/s,w=0KiB/s][r=428k,w=0 IOPS][eta
> 00m:25s]
> [  121.266996] CPU39: shutdown
> [  121.269797] psci: CPU39 killed (polled 0 ms)
> [  121.364122] CPU40: shutdown
> [  121.366918] psci: CPU40 killed (polled 0 ms)
> [  121.448256] CPU41: shutdown
> [  121.451058] psci: CPU41 killed (polled 0 ms)
> [  121.515785] CPU42: shutdown=1711MiB/s,w=0KiB/s][r=438k,w=0 IOPS][eta
> 00m:24s]
> [  121.518586] psci: CPU42 killed (polled 0 ms)
> [  121.563659] irq_shutdown irq143
> [  121.566922] CPU43: shutdown
> [  121.569732] psci: CPU43 killed (polled 0 ms)
> [  122.619423] scsi_times_out req=0xffff001faf906900=371k,w=0 IOPS][eta
> 00m:23s]
> [  122.624131] scsi_times_out req=0xffff001faf90ed00
> [  122.628842] scsi_times_out req=0xffff001faf90fc00
> [  122.633547] scsi_times_out req=0xffff001faf906000
> [  122.638259] scsi_times_out req=0xffff001faf906300
> [  122.642969] scsi_times_out req=0xffff001faf906600
> [  122.647676] scsi_times_out req=0xffff001faf906c00
> [  122.652381] scsi_times_out req=0xffff001faf906f00
> [  122.657086] scsi_times_out req=0xffff001faf907200
> [  122.661791] scsi_times_out req=0xffff001faf907500
> [  122.666498] scsi_times_out req=0xffff001faf907800
> [  122.671203] scsi_times_out req=0xffff001faf907b00
> [  122.675909] scsi_times_out req=0xffff001faf907e00
> [  122.680615] scsi_times_out req=0xffff001faf908100
> [  122.685319] scsi_times_out req=0xffff001faf908400
> [  122.690025] scsi_times_out req=0xffff001faf908700
> [  122.694731] scsi_times_out req=0xffff001faf908a00
> [  122.699439] scsi_times_out req=0xffff001faf908d00
> [  122.704145] scsi_times_out req=0xffff001faf909000
> [  122.708849] scsi_times_out req=0xffff001faf909300
> 
> 
> And another:
> 
> 51.336698] CPU53: shutdown
> [  251.336737] run queue from wrong CPU 0, hctx active
> [  251.339545] run queue from wrong CPU 0, hctx active
> [  251.344695] psci: CPU53 killed (polled 0 ms)
> [  251.349302] run queue from wrong CPU 0, hctx active
> [  251.358447] run queue from wrong CPU 0, hctx active
> [  251.363336] run queue from wrong CPU 0, hctx active
> [  251.368222] run queue from wrong CPU 0, hctx active
> [  251.373108] run queue from wrong CPU 0, hctx active
> [  252.488831] CPU54: shutdown=1094MiB/s,w=0KiB/s][r=280k,w=0 IOPS][eta
> 00m:04s]
> [  252.491629] psci: CPU54 killed (polled 0 ms)
> [  252.536533] irq_shutdown irq146
> [  252.540007] CPU55: shutdown
> [  252.543273] psci: CPU55 killed (polled 0 ms)
> [  252.656656] CPU56: shutdown
> [  252.659446] psci: CPU56 killed (polled 0 ms)
> [  252.704576] CPU57: shutdown=947MiB/s,w=0KiB/s][r=242k,w=0 IOPS][eta
> 00m:02s]
> [  252.707369] psci: CPU57 killed (polled 0 ms)
> [  254.352646] CPU58: shutdown=677MiB/s,w=0KiB/s][r=173k,w=0 IOPS][eta
> 00m:02s]
> [  254.355442] psci: CPU58 killed (polled 0 ms)
> long sleep 1
> [  279.288227] scsi_times_out req=0xffff041fa10b6600[r=0,w=0 IOPS][eta
> 04m:37s]
> [  279.320281] sas: Enter sas_scsi_recover_host busy: 1 failed: 1
> [  279.326144] sas: trying to find task 0x00000000e8dca422
> [  279.331379] sas: sas_scsi_find_task: aborting task 0x00000000e8dca422
> 
> none scheduler seems ok.

Can you reproduce it by just applying the patch of 'blk-mq: don't fail driver tag
allocation because of inactive hctx'?

If yes, can you collect debugfs log after the timeout is triggered?


Thanks,
Ming