Re: commit 01e99aeca397 causes longer runtime of block/004

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

On Tue, Mar 10, 2020 at 05:54:18AM +0000, Shinichiro Kawasaki wrote:
> Ming, thank you for sharing the log files and analysis.
> 
> On Mar 10, 2020 / 03:07, Damien Le Moal wrote:
> > On 2020/03/10 1:14, Ming Lei wrote:
> > > On Mon, Mar 09, 2020 at 12:07:16AM +0000, Shinichiro Kawasaki wrote:
> > >> On Mar 07, 2020 / 12:13, Ming Lei wrote:
> > >>> On Sat, Mar 07, 2020 at 01:02:23AM +0000, Shinichiro Kawasaki wrote:
> > >>>> On Mar 06, 2020 / 16:13, Ming Lei wrote:
> > >>>>> On Fri, Mar 06, 2020 at 06:06:23AM +0000, Shinichiro Kawasaki wrote:
> > >>>>>> On Mar 05, 2020 / 10:48, Ming Lei wrote:
> > >>>>>>> Hi Shinichiro,
> > >>>>>>>
> > >>>>>>> On Thu, Mar 05, 2020 at 01:19:02AM +0000, Shinichiro Kawasaki wrote:
> > >>>>>>>> On Mar 04, 2020 / 17:53, Ming Lei wrote:
> > >>>>>>>>> On Wed, Mar 04, 2020 at 06:11:37AM +0000, Shinichiro Kawasaki wrote:
> > >>>>>>>>>> On Mar 04, 2020 / 11:46, Ming Lei wrote:
> > >>>>>>>>>>> On Wed, Mar 04, 2020 at 02:38:43AM +0000, Shinichiro Kawasaki wrote:
> > >>>>>>>>>>>> I noticed that blktests block/004 takes longer runtime with 5.6-rc4 than
> > >>>>>>>>>>>> 5.6-rc3, and found that the commit 01e99aeca397 ("blk-mq: insert passthrough
> > >>>>>>>>>>>> request into hctx->dispatch directly") triggers it.
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> The longer runtime was observed with dm-linear device which maps SATA SMR HDD
> > >>>>>>>>>>>> connected via AHCI. It was not observed with dm-linear on SAS/SATA SMR HDDs
> > >>>>>>>>>>>> connected via SAS-HBA. Not observed with dm-linear on non-SMR HDDs either.
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> Before the commit, block/004 took around 130 seconds. After the commit, it takes
> > >>>>>>>>>>>> around 300 seconds. I need to dig in further details to understand why the
> > >>>>>>>>>>>> commit makes the test case longer.
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> The test case block/004 does "flush intensive workload". Is this longer runtime
> > >>>>>>>>>>>> expected?
> > >>>>>>>>>>>
> > >>>>>>>>>>> The following patch might address this issue:
> > >>>>>>>>>>>
> > >>>>>>>>>>> https://lore.kernel.org/linux-block/20200207190416.99928-1-sqazi@google.com/#t
> > >>>>>>>>>>>
> > >>>>>>>>>>> Please test and provide us the result.
> > >>>>>>>>>>>
> > >>>>>>>>>>> thanks,
> > >>>>>>>>>>> Ming
> > >>>>>>>>>>>
> > >>>>>>>>>>
> > >>>>>>>>>> Hi Ming,
> > >>>>>>>>>>
> > >>>>>>>>>> I applied the patch to 5.6-rc4 but I observed the longer runtime of block/004.
> > >>>>>>>>>> Still it takes around 300 seconds.
> > >>>>>>>>>
> > >>>>>>>>> Hello Shinichiro,
> > >>>>>>>>>
> > >>>>>>>>> block/004 only sends 1564 sync randwrite, and seems 130s has been slow
> > >>>>>>>>> enough.
> > >>>>>>>>>
> > >>>>>>>>> There are two related effect in that commit for your issue:
> > >>>>>>>>>
> > >>>>>>>>> 1) 'at_head' is applied in blk_mq_sched_insert_request() for flush
> > >>>>>>>>> request
> > >>>>>>>>>
> > >>>>>>>>> 2) all IO is added back to tail of hctx->dispatch after .queue_rq()
> > >>>>>>>>> returns STS_RESOURCE
> > >>>>>>>>>
> > >>>>>>>>> Seems it is more related with 2) given you can't reproduce the issue on 
> > >>>>>>>>> SAS.
> > >>>>>>>>>
> > >>>>>>>>> So please test the following two patches, and see which one makes a
> > >>>>>>>>> difference for you.
> > >>>>>>>>>
> > >>>>>>>>> BTW, both two looks not reasonable, just for narrowing down the issue.
> > >>>>>>>>>
> > >>>>>>>>> 1) patch 1
> > >>>>>>>>>
> > >>>>>>>>> diff --git a/block/blk-mq-sched.c b/block/blk-mq-sched.c
> > >>>>>>>>> index 856356b1619e..86137c75283c 100644
> > >>>>>>>>> --- a/block/blk-mq-sched.c
> > >>>>>>>>> +++ b/block/blk-mq-sched.c
> > >>>>>>>>> @@ -398,7 +398,7 @@ void blk_mq_sched_insert_request(struct request *rq, bool at_head,
> > >>>>>>>>>  	WARN_ON(e && (rq->tag != -1));
> > >>>>>>>>>  
> > >>>>>>>>>  	if (blk_mq_sched_bypass_insert(hctx, !!e, rq)) {
> > >>>>>>>>> -		blk_mq_request_bypass_insert(rq, at_head, false);
> > >>>>>>>>> +		blk_mq_request_bypass_insert(rq, true, false);
> > >>>>>>>>>  		goto run;
> > >>>>>>>>>  	}
> > >>>>>>>>
> > >>>>>>>> Ming, thank you for the trial patches.
> > >>>>>>>> This "patch 1" reduced the runtime, as short as rc3.
> > >>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>> 2) patch 2
> > >>>>>>>>> diff --git a/block/blk-mq.c b/block/blk-mq.c
> > >>>>>>>>> index d92088dec6c3..447d5cb39832 100644
> > >>>>>>>>> --- a/block/blk-mq.c
> > >>>>>>>>> +++ b/block/blk-mq.c
> > >>>>>>>>> @@ -1286,7 +1286,7 @@ bool blk_mq_dispatch_rq_list(struct request_queue *q, struct list_head *list,
> > >>>>>>>>>  			q->mq_ops->commit_rqs(hctx);
> > >>>>>>>>>  
> > >>>>>>>>>  		spin_lock(&hctx->lock);
> > >>>>>>>>> -		list_splice_tail_init(list, &hctx->dispatch);
> > >>>>>>>>> +		list_splice_init(list, &hctx->dispatch);
> > >>>>>>>>>  		spin_unlock(&hctx->lock);
> > >>>>>>>>>  
> > >>>>>>>>>  		/*
> > >>>>>>>>
> > >>>>>>>> This patch 2 didn't reduce the runtime.
> > >>>>>>>>
> > >>>>>>>> Wish this report helps.
> > >>>>>>>
> > >>>>>>> Your feedback does help, then please test the following patch:
> > >>>>>>
> > >>>>>> Hi Ming, thank you for the patch. I applied it on top of rc4 and confirmed
> > >>>>>> it reduces the runtime as short as rc3. Good.
> > >>>>>
> > >>>>> Hi Shinichiro,
> > >>>>>
> > >>>>> Thanks for your test!
> > >>>>>
> > >>>>> Then I think the following change should make the difference actually,
> > >>>>> you may double check that and confirm if it is that.
> > >>>>>
> > >>>>>> @@ -334,7 +334,7 @@ static void blk_kick_flush(struct request_queue *q, struct blk_flush_queue *fq,
> > >>>>>>  	flush_rq->rq_disk = first_rq->rq_disk;
> > >>>>>>  	flush_rq->end_io = flush_end_io;
> > >>>>>>  
> > >>>>>> -	blk_flush_queue_rq(flush_rq, false);
> > >>>>>> +	blk_flush_queue_rq(flush_rq, true);
> > >>>>
> > >>>> Yes, with this the one line change above only, the runtime was reduced.
> > >>>>
> > >>>>>
> > >>>>> However, the flush request is added to tail of dispatch queue[1] for long time.
> > >>>>> 0cacba6cf825 ("blk-mq-sched: bypass the scheduler for flushes entirely")
> > >>>>> and its predecessor(all mq scheduler start patches) changed to add flush request
> > >>>>> to front of dispatch queue for blk-mq by ignoring 'add_queue' parameter of
> > >>>>> blk_mq_sched_insert_flush(). That change may be by accident, and not sure it is
> > >>>>> correct.
> > >>>>>
> > >>>>> I guess once flush rq is added to tail of dispatch queue in block/004,
> > >>>>> in which lots of FS request may stay in hctx->dispatch because of low
> > >>>>> AHCI queue depth, then we may take a bit long for flush rq to be
> > >>>>> submitted to LLD.
> > >>>>>
> > >>>>> I'd suggest to root cause/understand the issue given it isn't obvious
> > >>>>> correct to queue flush rq at front of dispatch queue, so could you collect
> > >>>>> the following trace via the following script with/without the single line
> > >>>>> patch?
> > >>>>
> > >>>> Thank you for the thoughts for the correct design. I have taken the two traces,
> > >>>> with and without the one liner patch above. The gzip archived trace files have
> > >>>> 1.6MB size. It looks too large to post to the list. Please let me know how you
> > >>>> want the trace files shared.
> > >>>
> > >>> I didn't thought the trace can be so big given the ios should be just
> > >>> 256 * 64(1564).
> > >>>
> > >>> You may put the log somewhere in Internet, cloud storage, web, or
> > >>> whatever. Then just provides us the link.
> > >>>
> > >>> Or if you can't find a place to hold it, just send to me, and I will put
> > >>> it in my RH people web link.
> > >>
> > >> I have sent another e-mail only to you attaching the log files gziped.
> > >> Your confirmation will be appreciated.
> > > 
> > > Yeah, I got the log, and it has been put in the following link:
> > > 
> > > http://people.redhat.com/minlei/tests/logs/blktests_block_004_perf_degrade.tar.gz
> > > 
> > > Also I have run some analysis, and block/004 basically call pwrite() &
> > > fsync() in each job.
> > > 
> > > 1) v5.6-rc kernel
> > > - write rq average latency: 0.091s 
> > > - flush rq average latency: 0.018s
> > > - average issue times of write request: 1.978  //how many trace_block_rq_issue() is called for one rq
> > > - average issue times of flush request: 1.052
> > > 
> > > 2) v5.6-rc patched kernel
> > > - write rq average latency: 0.031
> > > - flush rq average latency: 0.035
> > > - average issue times of write request: 1.466
> > > - average issue times of flush request: 1.610
> > > 
> > > 
> > > block/004 starts 64 jobs and AHCI's queue can become saturated easily,
> > > then BLK_MQ_S_SCHED_RESTART should be set, so write request in dispatch
> > > queue can only move on after one request is completed.
> > > 
> > > Looks the flush request takes shorter time than normal write IO.
> > > If flush request is added to front of dispatch queue, the next normal
> > > write IO could be queued to lld quicker than adding to tail of dispatch
> > > queue.
> > > trace_block_rq_issue() is called more than one time is because of
> > > AHCI or the drive's implementation. It usually means that
> > > host->hostt->queuecommand() fails for several times when queuing one
> > > single request. For AHCI, I understand it shouldn't fail normally given
> > > we guarantee that the actual queue depth is <= either LUN or host's
> > > queue depth. Maybe it depends on your SMR's implementation about handling
> > > flush/write IO. Could you check why .queuecommand() fails in block/004?
> 
> I put some debug prints and confirmed that the .queuecommand function is
> ata_scsi_queuecmd() and it returns SCSI_MLQUEUE_DEVICE_BUSY because
> ata_std_qc_defer() returns ATA_DEFER_LINK. The comment of ata_std_qc_defer()
> notes that "Non-NCQ commands cannot run with any other command, NCQ or not.  As
> upper layer only knows the queue depth, we are responsible for maintaining
> exclusion.  This function checks whether a new command @qc can be issued." Then
> I guess .queuecommand() fails because is that Non-NCQ flush command and NCQ
> write command are waiting the completion each other.

OK, got it.

> 
> > 
> > Indeed, that is weird that queuecommand fails. There is nothing SMR specific in
> > the AHCI code beside disk probe checks. So write & flush handling does not
> > differ between SMR and regular disks. The same applies to the drive side. write
> > and flush commands are the normal commands, no change at all. The only
> > difference being the sequential write constraint which the drive honors by not
> > executing the queued write command out of order. But there are no constraint for
> > flush on SMR, so we get whatever the drive does, that is, totally drive dependent.
> > 
> > I wonder if the issue may be with the particular AHCI chipset used for this test.
> > 
> > > 
> > > Also can you provide queue flags via the following command?
> > > 
> > > 	cat /sys/kernel/debug/block/sdN/state
> 
> The state sysfs attribute was as follows:
> 
> SAME_COMP|IO_STAT|ADD_RANDOM|INIT_DONE|WC|STATS|REGISTERED|SCSI_PASSTHROUGH|26
> 
> It didn't change before and after the block/004 run.
> 
> 
> > > 
> > > I understand flush request should be slower than normal write, however
> > > looks not true in this hardware.
> > 
> > Probably due to the fact that since the writes are sequential, there is a lot of
> > drive internal optimization that can be done to minimize the cost of flush
> > (internal data streaming from cache to media, media-cache use, etc) That is true
> > for regular disks too. And all of this is highly dependent on the hardware
> > implementation.
> 
> This discussion tempted me to take closer look in the traces. And I noticed that
> number of flush commands issued is different with and without the patch.
> 
>                         | without patch | with patch
> ------------------------+---------------+------------
> block_getrq: rwbs=FWS   |      32640    |   32640
> block_rq_issue: rwbs=FF |      32101    |    7593

Looks issued flush request is too many given the flush machinery
should avoid to queue duplicated flush requests.

I will investigate the flush code a bit.

> 
> Without the patch, flush command is issued between two write commands. With the
> patch, some write commands are executed without flush between them.
> 
> I wonder how the requeue list position of flush command (head vs tail) changes
> the number of flush commands to issue.
> 
> Another weird thing is number of block_getrq traces of flush (rwds=FWS). It
> doubles number of writes (256 * 64 = 16320). I will chase this further.

Indeed, not see such issue when I run the test on kvm ahci.


Thanks,
Ming