Re: Large latency on blk_queue_enter

[Jens Axboe <axboe@fb.com>]

On 05/08/2017 09:02 AM, Javier González wrote:
>> On 8 May 2017, at 16.52, Jens Axboe <axboe@fb.com> wrote:
>>
>> On 05/08/2017 08:46 AM, Javier González wrote:
>>>> On 8 May 2017, at 16.23, Jens Axboe <axboe@fb.com> wrote:
>>>>
>>>> On 05/08/2017 08:20 AM, Javier González wrote:
>>>>>> On 8 May 2017, at 16.13, Jens Axboe <axboe@fb.com> wrote:
>>>>>>
>>>>>> On 05/08/2017 07:44 AM, Javier González wrote:
>>>>>>>> On 8 May 2017, at 14.27, Ming Lei <ming.lei@redhat.com> wrote:
>>>>>>>>
>>>>>>>> On Mon, May 08, 2017 at 01:54:58PM +0200, Javier González wrote:
>>>>>>>>> Hi,
>>>>>>>>>
>>>>>>>>> I find an unusual added latency(~20-30ms) on blk_queue_enter when
>>>>>>>>> allocating a request directly from the NVMe driver through
>>>>>>>>> nvme_alloc_request. I could use some help confirming that this is a bug
>>>>>>>>> and not an expected side effect due to something else.
>>>>>>>>>
>>>>>>>>> I can reproduce this latency consistently on LightNVM when mixing I/O
>>>>>>>>> from pblk and I/O sent through an ioctl using liblightnvm, but I don't
>>>>>>>>> see anything on the LightNVM side that could impact the request
>>>>>>>>> allocation.
>>>>>>>>>
>>>>>>>>> When I have a 100% read workload sent from pblk, the max. latency is
>>>>>>>>> constant throughout several runs at ~80us (which is normal for the media
>>>>>>>>> we are using at bs=4k, qd=1). All pblk I/Os reach the nvme_nvm_submit_io
>>>>>>>>> function on lightnvm.c., which uses nvme_alloc_request. When we send a
>>>>>>>>> command from user space through an ioctl, then the max latency goes up
>>>>>>>>> to ~20-30ms. This happens independently from the actual command
>>>>>>>>> (IN/OUT). I tracked down the added latency down to the call
>>>>>>>>> percpu_ref_tryget_live in blk_queue_enter. Seems that the queue
>>>>>>>>> reference counter is not released as it should through blk_queue_exit in
>>>>>>>>> blk_mq_alloc_request. For reference, all ioctl I/Os reach the
>>>>>>>>> nvme_nvm_submit_user_cmd on lightnvm.c
>>>>>>>>>
>>>>>>>>> Do you have any idea about why this might happen? I can dig more into
>>>>>>>>> it, but first I wanted to make sure that I am not missing any obvious
>>>>>>>>> assumption, which would explain the reference counter to be held for a
>>>>>>>>> longer time.
>>>>>>>>
>>>>>>>> You need to check if the .q_usage_counter is working at atomic mode.
>>>>>>>> This counter is initialized as atomic mode, and finally switchs to
>>>>>>>> percpu mode via percpu_ref_switch_to_percpu() in blk_register_queue().
>>>>>>>
>>>>>>> Thanks for commenting Ming.
>>>>>>>
>>>>>>> The .q_usage_counter is not working on atomic mode. The queue is
>>>>>>> initialized normally through blk_register_queue() and the counter is
>>>>>>> switched to percpu mode, as you mentioned. As I understand it, this is
>>>>>>> how it should be, right?
>>>>>>
>>>>>> That is how it should be, yes. You're not running with any heavy
>>>>>> debugging options, like lockdep or anything like that?
>>>>>
>>>>> No lockdep, KASAN, kmemleak or any of the other usual suspects.
>>>>>
>>>>> What's interesting is that it only happens when one of the I/Os comes
>>>>> from user space through the ioctl. If I have several pblk instances on
>>>>> the same device (which would end up allocating a new request in
>>>>> parallel, potentially on the same core), the latency spike does not
>>>>> trigger.
>>>>>
>>>>> I also tried to bind the read thread and the liblightnvm thread issuing
>>>>> the ioctl to different cores, but it does not help...
>>>>
>>>> How do I reproduce this? Off the top of my head, and looking at the code,
>>>> I have no idea what is going on here.
>>>
>>> Using LightNVM and liblightnvm [1] you can reproduce it by:
>>>
>>> 1. Instantiate a pblk instance on the first channel (luns 0 - 7):
>>>        sudo nvme lnvm create -d nvme0n1 -n test0 -t pblk -b 0 -e 7 -f
>>> 2. Write 5GB to the test0 block device with a normal fio script
>>> 3. Read 5GB to verify that latencies are good (max. ~80-90us at bs=4k, qd=1)
>>> 4. Re-run 3. and in parallel send a command through liblightnvm to a
>>> different channel. A simple command is an erase (erase block 900 on
>>> channel 2, lun 0):
>>> 	sudo nvm_vblk line_erase /dev/nvme0n1 2 2 0 0 900
>>>
>>> After 4. you should see a ~25-30ms latency on the read workload.
>>>
>>> I tried to reproduce the ioctl in a more generic way to reach
>>> __nvme_submit_user_cmd(), but SPDK steals the whole device. Also, qemu
>>> is not reliable for this kind of performance testing.
>>>
>>> If you have a suggestion on how I can mix an ioctl with normal block I/O
>>> read on a standard NVMe device, I'm happy to try it and see if I can
>>> reproduce the issue.
>>
>> Just to rule out this being any hardware related delays in processing
>> IO:
>>
>> 1) Does it reproduce with a simpler command, anything close to a no-op
>>   that you can test?
> 
> Yes. I tried with a 4KB read and with a fake command I drop right after
> allocation.
> 
>> 2) What did you use to time the stall being blk_queue_enter()?
>>
> 
> I have some debug code measuring time with ktime_get() in different
> places in the stack, and among other places, around blk_queue_enter(). I
> use them then to measure max latency and expose it through sysfs. I can
> see that the latency peak is recorded in the probe before
> blk_queue_enter() and not in the one after.
> 
> I also did an experiment, where the normal I/O path allocates the
> request with BLK_MQ_REQ_NOWAIT. When running the experiment above, the
> read test fails since we reach:
> 	if (nowait)
> 	  return -EBUSY;
> 
> in blk_queue_enter.

OK, that's starting to make more sense, that indicates that there is indeed
something wrong with the refs. Does the below help?


diff --git a/block/blk-mq.c b/block/blk-mq.c
index 5d4ce7eb8dbf..df5ee82d28f8 100644
--- a/block/blk-mq.c
+++ b/block/blk-mq.c
@@ -292,10 +292,11 @@ struct request *blk_mq_alloc_request(struct request_queue *q, int rw,
 	rq = blk_mq_sched_get_request(q, NULL, rw, &alloc_data);
 
 	blk_mq_put_ctx(alloc_data.ctx);
-	blk_queue_exit(q);
 
-	if (!rq)
+	if (!rq) {
+		blk_queue_exit(q);
 		return ERR_PTR(-EWOULDBLOCK);
+	}
 
 	rq->__data_len = 0;
 	rq->__sector = (sector_t) -1;

-- 
Jens Axboe