Message-Id: <98125B90-AA08-49F4-8214-56AC86E4A645@lightnvm.io>
Date:   Mon, 8 May 2017 17:49:22 +0200
From:   Javier González <jg@...htnvm.io>
To:     Jens Axboe <axboe@...nel.dk>
Cc:     Ming Lei <ming.lei@...hat.com>, Christoph Hellwig <hch@....de>,
        Dan Williams <dan.j.williams@...el.com>,
        linux-block@...r.kernel.org,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Matias Bjørling <mb@...htnvm.io>
Subject: Re: Large latency on blk_queue_enter

> On 8 May 2017, at 17.40, Jens Axboe <axboe@...nel.dk> wrote:
> 
> On 05/08/2017 09:38 AM, Javier González wrote:
>>> On 8 May 2017, at 17.25, Jens Axboe <axboe@...nel.dk> wrote:
>>> 
>>> On 05/08/2017 09:22 AM, Javier González wrote:
>>>> Javier
>>>> 
>>>>> On 8 May 2017, at 17.14, Jens Axboe <axboe@...nel.dk> wrote:
>>>>> 
>>>>> On 05/08/2017 09:08 AM, Jens Axboe wrote:
>>>>>> On 05/08/2017 09:02 AM, Javier González wrote:
>>>>>>>> On 8 May 2017, at 16.52, Jens Axboe <axboe@...com> wrote:
>>>>>>>> 
>>>>>>>> On 05/08/2017 08:46 AM, Javier González wrote:
>>>>>>>>>> On 8 May 2017, at 16.23, Jens Axboe <axboe@...com> wrote:
>>>>>>>>>> 
>>>>>>>>>> On 05/08/2017 08:20 AM, Javier González wrote:
>>>>>>>>>>>> On 8 May 2017, at 16.13, Jens Axboe <axboe@...com> wrote:
>>>>>>>>>>>> 
>>>>>>>>>>>> On 05/08/2017 07:44 AM, Javier González wrote:
>>>>>>>>>>>>>> On 8 May 2017, at 14.27, Ming Lei <ming.lei@...hat.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?
>>>>> 
>>>>> No, that can't be right, it does look balanced to begin with.
>>>>> blk_mq_alloc_request() always grabs a queue ref, and always drops it. If
>>>>> we return with a request succesfully allocated, then we have an extra
>>>>> ref on it, which is dropped when it is later freed.
>>>> 
>>>> I agree, it seems more like a reference is put too late. I looked into
>>>> into the places where the reference is put, but it all seems normal. In
>>>> any case, I run it (just to see), and it did not help.
>>>> 
>>>>> Something smells fishy, I'll dig a bit.
>>>> 
>>>> Thanks! I continue looking into it myself; let me know if I can help
>>>> with something more specific.
>>> 
>>> What exact kernel are you running? And does the device have a scheduler
>>> attached, or is it set to "none"?
>> 
>> I can reproduce the issue on 4.11-rc7. I will rebase on top of your
>> for-4.12/block, but I cannot see any patches that might be related. If
>> it changes I'll ping you.
> 
> I don't suspect it will do anything for you. I just ask to know what
> base you are on.
> 
>> I mentioned the problem to Christoph last week and disabling the
>> schedulers was the first thing he recommended. I measured time around
>> blk_mq_sched_get_request and for this particular test the choose of
>> scheduler (including BFQ and kyber) does not seem to have an effect.
> 
> kyber vs none would be the interesting test. Some of the paths are a
> little different depending if there's a scheduler attached or not, so
> it's good to know that we're seeing this in both cases.
> 

I just tested on your for-4.12/block with none and kyber and the latency
spike appears in both cases.

Javier

Download attachment "signature.asc" of type "application/pgp-signature" (802 bytes)

Powered by blists - more mailing lists