> On 9 May 2017, at 12.58, Ming Lei <ming....@redhat.com> wrote: > > On Tue, May 09, 2017 at 12:34:42PM +0200, Javier González wrote: >>> On 8 May 2017, at 18.39, Javier González <j...@lightnvm.io> wrote: >>> >>>> On 8 May 2017, at 18.06, Jens Axboe <ax...@kernel.dk> wrote: >>>> >>>> On 05/08/2017 09:49 AM, Javier González wrote: >>>>>> On 8 May 2017, at 17.40, Jens Axboe <ax...@kernel.dk> wrote: >>>>>> >>>>>> On 05/08/2017 09:38 AM, Javier González wrote: >>>>>>>> On 8 May 2017, at 17.25, Jens Axboe <ax...@kernel.dk> wrote: >>>>>>>> >>>>>>>> On 05/08/2017 09:22 AM, Javier González wrote: >>>>>>>>> Javier >>>>>>>>> >>>>>>>>>> On 8 May 2017, at 17.14, Jens Axboe <ax...@kernel.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 <ax...@fb.com> wrote: >>>>>>>>>>>>> >>>>>>>>>>>>> On 05/08/2017 08:46 AM, Javier González wrote: >>>>>>>>>>>>>>> On 8 May 2017, at 16.23, Jens Axboe <ax...@fb.com> wrote: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> On 05/08/2017 08:20 AM, Javier González wrote: >>>>>>>>>>>>>>>>> On 8 May 2017, at 16.13, Jens Axboe <ax...@fb.com> wrote: >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> On 05/08/2017 07:44 AM, Javier González wrote: >>>>>>>>>>>>>>>>>>> On 8 May 2017, at 14.27, Ming Lei <ming....@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? >>>>>>>>>> >>>>>>>>>> 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. >>>> >>>> OK good. I looked at your reproduction case. Looks like we ultimately >>>> end up submitting IO through nvme_nvm_submit_user_cmd() when you do the >>>> nvm_vblk line_erase, which is basically the same code as >>>> NVME_IOCTL_SUBMIT_IO as far as request alloc, setup, issue, free goes. >>>> So does it reproduce for you as well on a normal nvme device, if you run >>>> a nvme read /dev/nvme0 [...] while running the same read fio job? >>> >>> Ok. I'll try that. >> >> I cannot reproduce the latency on a normal nvme drive when mixing I/O >> from a fio job and ioctls. >> >> The path is different from the one in pblk, since normal block I/O >> uses the generic_make_request(), but still, they both need to >> blk_queue_enter(), allocate a request, etc. They only "major" difference >> I see is that normal block I/O requests are given by get_request() >> (which as far as I understand takes pre-allocated requests from the >> queue request list), while pblk allocates each request via >> nvme_alloc_request(). >> >> What puzzles me most is that having different pblk instances, issuing >> I/O in parallel does not trigger the long tail. Otherwise, I would think >> that we are just unlucky and get scheduled out. Still, 20ms... >> >> BTW, in order to discard NUMA, I tried on a single socket machine, and >> same, same. > > I suspect the .q_usage_counter is DEAD, and you can check it via > percpu_ref_is_dying(), or just check if slow path is reached. > > The fast path is that percpu_ref_tryget_live() returns directly, > and slow path is reached only if queue is freezed or dead. > > If that is true, you can add a dump_stack() in blk_freeze_queue_start() > to see where the unusual freezing/unfreezing is from.
Thanks for the hint Ming! You are right. We somehow trigger a re-read partition: [ 324.010184] dump_stack+0x63/0x90 [ 324.010191] blk_freeze_queue_start+0x1e/0x50 [ 324.010194] blk_mq_freeze_queue+0x12/0x20 [ 324.010199] __nvme_revalidate_disk+0xa4/0x350 [ 324.010203] nvme_revalidate_disk+0x53/0x90 [ 324.010206] rescan_partitions+0x8d/0x380 [ 324.010211] ? tlb_flush_mmu_free+0x36/0x60 [ 324.010218] ? security_capable+0x48/0x60 [ 324.010221] __blkdev_reread_part+0x65/0x70 [ 324.010223] blkdev_reread_part+0x23/0x40 [ 324.010225] blkdev_ioctl+0x387/0x910 [ 324.010229] ? locks_insert_lock_ctx+0x7e/0xd0 [ 324.010235] block_ioctl+0x3d/0x50 [ 324.010239] do_vfs_ioctl+0xa1/0x5d0 [ 324.010242] ? locks_lock_inode_wait+0x51/0x150 [ 324.010247] ? kmem_cache_alloc+0xd7/0x1b0 [ 324.010249] ? locks_alloc_lock+0x1b/0x70 [ 324.010252] SyS_ioctl+0x79/0x90 [ 324.010254] ? SyS_flock+0x11c/0x180 [ 324.010260] entry_SYSCALL_64_fastpath+0x1e/0xad I'm checking why this happens now... Javier
signature.asc
Description: Message signed with OpenPGP
