NVMe Read Performance Issues with ZFS (submit_bio to io_schedule)

[bwatkinson]

System information

Type	Version/Name
Distribution Name	CentOS
Distribution Version	7.5
Linux Kernel	4.18.20-100
Architecture	x86_64
ZFS Version	0.7.12-1
SPL Version	0.7.12-1

Describe the problem you're observing

We are currently seeing poor read performance with ZFS 0.7.12 with our Samsung PM1725a devices in a Dell PowerEdge R7425.

Describe how to reproduce the problem

Briefly describing our setup, we currently have four PM1724a devices attached to the PCIe root complex in NUMA domain 1 on an AMD EPYC 7401 processor. In order to measure read throughput of ZFS, XFS, and the Raw Devices, the XDD tool was used which is available at:

git@github.com:bwatkinson/xdd.git

In all cases I am presenting, kernel 4.18.20-100 was used and I disabled all CPU's not on socket 0 within the kernel. I also issued asynchronous sequential reads to the file systems/devices while pinning all XDD threads to NUMA domain 1 and Socket 0's memory banks. I conducted four tests consisting of measuring throughput for the raw devices, XFS, and ZFS 0.7.12. For the Raw Device tests, I had 6 I/O threads per devices with a request sizes of 1 MB and a total of 32 GB read from each device using Direct I/O. In the XFS case, I created a single XFS file system on each of the 4 devices. In each of the XFS file systems, I read a 32 GB file of random data using 6 I/O threads per file with request sizes of 1 MB using Direct I/O. In the ZFS Single ZPool case I created a single ZPool composed of 4 VDEVs and read 128 GB file of random data using 24 I/O threads with request sizes of 1 MB. In the ZFS Multiple ZPool case I create 4 separate ZPools each consisting of a single VDEV. In each of the ZPools, I read a 32 GB file of random data using 6 I/O threads per file with request sizes of 1 MB. In both the Single ZPool and Multipl ZPool cases I set the record sizes for all pools to 1 MB and I set the primarycache=none. We decided to disable the ARC in all cases, because we were reading 128 GB of data, which was exactly equal to 2x available memory on Socket 0. Even with the ARC enabled we were seeing no performance benefits. Below are the throughput measurements I collected for each of these case.

Performance Results:
Raw Device - 12,7246.724 MB/s
XFS Direct I/O - 12,734.633 MB/s
ZFS Single Zpool - 6,452.946 MB/s
ZFS Multiple Zpool – 6,344.915 MB/s

In order to try and solve what was cutting ZFS read performance in half, I generated flame graphs using the following tool:

http://www.brendangregg.com/flamegraphs.html

In general I found most of the perf samples were occurring in zio_wait. It is in this call that io_scheudle is called. Comparing the ZFS flame graphs to XFS flame graphs, I found that the number of samples between the submit_bio and io_schedule was significantly larger in the ZFS case. I decided to take timestamps of each call to io_schedule for both ZFS and XFS to measure the latency between the calls. Below is a link to to histograms as well as total elapsed time in microseconds between io_schedule calls for the tests I described above. In total I collected 110,000 timestamps. In plotted data the first 10,000 timestamps were ignored to allow for the file systems to reach a steady state.

https://drive.google.com/drive/folders/1t7tLXxyhurcxGjry4WYkw_wryh6eMqdh?usp=sharing

In general, ZFS has a significant latency between io_scheudule calls. I have also verified that the output from iostat shows a larger await_r value for ZFS over XFS for these tests as well. In general it seems ZFS is letting request sit in the hardware queues longer than XFS and the Raw Devices causing a huge performance penalty in ZFS reads (effectively cutting the available device bandwidth in half).

In general, has this issue been noticed with NVMe SSD’s and ZFS and is there a current fix to this issue? If there is no current fix, is this issue being worked on?

Also, I have tried to duplicate the XFS results using ZFS 0.8.0-rc2 using Direct I/O, but the performance for 0.8.0 read almost exactly matched ZFS 0.7.12 read performance without Direct I/O.

Include any warning/errors/backtraces from the system logs

[alatteri]

I setup a 72-bay SATA SSD server. Tried all sorts of ZFS tuning, was always 2-4x slower than HW RAID XFS. And that is what I eventually went with. I now get 9GB/s writes, 18GB/s reads. ZFS is great for many things, performance is not one.

[gcs-github]

When testing ZFS, what was your block devices IO scheduler set to?

cat /sys/block/your_nvme_drive_here/queue/scheduler

Normally it should be set to noop (which ZFS should set on its own if you've created your vdevs using full drives, which is recommended) so as to let ZFS do the heavy lifting instead of regular in-kernel IO schedulers. In some cases however, it can be necessary to set the scheduler yourself.

I'm not saying it'd necessarily explain your issues or fix them, but it might be a relevant piece of the puzzle here.

[bwatkinson]

In the data I have presented all the NVMe drive schedulers were set to none under /sys/block/nvme#n1/queue/scheduler. Also the ZFS module parameter for zfs_vdev_scheduler was set to noop.

I think only achieving half of the available bandwidth for synchronous reads is more than just under performance at this point. I could see only getting 75-80% as under performance; however, 50% is just way too low.

I have been continuing to try and track this issue down. I have taken my time stamp approach and placed time stamps in ZFS dmu.c (dmu_buf_hold_array_by_dnode), vdev_disk.c (vdev_submit_bio_impl), and SPL spl-condvar.c (cv_wait_common). My idea is try and narrow the scope down of what is causing such a drastic latencies in ZFS between when a read enters the ZFS software stack, to submitting the bio request to the linux block mulitqueue layer, and finally when the io_schdule call occurs. I am however seeing an issue where I am not collected the same number of time stamps in the vdev_submit_bio_impl call as the other 2 call sites for 1 MB request for a total of 128 GB of data with 24 I/O threads. I added a variable inside of the zio_t struct to flag the zio as a read and set this variable to true, for reads, inside of the dmu_buf_hold_array_by_node call right after the zio_root call occurs. I also updated the zio_create function to add the flag from the parent zio to the child if a parent is passed. Not sure why I am seeing less time stamps collected in just this one function, but I working to try and figure that out now.

I am sticking with this time stamp approach as nothing is blatantly obvious, when reading the source code, as the cause of the latencies. I thought maybe the issue might be occurring the SPL taskq's; however, for synchronous reads, there are 8 queues with 12 threads each to service the checksum verify in the read zio pipeline as well as finally calling zio_wait to hit the io_schedule call.

Hopefully collecting the timestamps and narrowing down the area of collection will lead to more insight to why this issue is present. Any advice on places to look in the source code or even why I am only getting a fraction of the time stamps collected in the vdev_submit_bio_impl call would greatly be appreciated.

[stevenh]

Have you tried increasing max number of I/O requests active for each device?

[bwatkinson]

Yes, I have done this for zfs_vdev_sync_read_max_active and zfs_vdev_max_active. Currently the amount of work does not seem to be causing the poor synchronous read performance. ZFS seems more than capable of handing off enough work to the NVMe SSD drives (even with default module parameter values). The real issue is that the requests are sitting the devices hardware queues for far too long (aka between when ZFS issues the requests and finally asks for the data). This is why I am trying to figure out what is causing the large latencies in the source code between calls to submit_bio and io_schedule for a synchronous read requests.

[prometheanfire]

NVME devs still have queue depth, maybe it's some issue with that (or other controller issues)

[jwittlincohen]

@bwatkinson Did you also try increasing zfs_vdev_sync_read_min_active?

[bwatkinson]

@jwittlincohen I did not increase the min. Is there a reason why you think this would decrease the latency issue I am seeing with read requests sitting the NVMe Device queues?

@prometheanfire The data (on the Google Drive) I presented in the first post shows that the hardware and hardware paths seem perfectly fine. XFS easily gets the full NVMe SDD's bandwidth for reads for the exact same workloads. Of course I am using Direct I/O with XFS. Also, directly reading from the devices I do not experience the same issue I am seeing in ZFS. That is also why I believe this has something to do with the ZFS software stack. I have tried using the ZFS 0.8.0-rc which allows for Direct I/O but this same issue is still present.

[bwatkinson]

I just wanted to give an update on this and see if there was any other suggestions where I should narrow my focus down in the ZFS source code to resolve the latency issues I am see with NVMe SDD's for synchronous reads.

I was able to solve where the missing timestamps were for the submit_bio calls. I had to trace the zio_t's to the parent from the children to get the correct matching PID's. I found that some of the submit_bio calls were being handled by the kernel threads in the SPL taskq's. I have attached the new results in the hrtime_dmu_submit_bio_io_schedule_data.zip. These timestamps were collected using a single ZPool in a RAIDZ0 configuration using 4 NVMe SDD's. The three call sites, where the timestamps were collected, were in the functions dmu_buf_hold_array_by_dnode, vdev_submit_bio_impl, and cv_wait_common. The total data read was 128 GB using 24 IO threads with each read request being 1 MB. I set the primarycache to none and set the recordsize to 1 MB for the ZPool.

In general there is a larger mean, median latency between the submit_bio to the io_schudule calls. Surprising, it is not as significant as I was expecting in comparison between the dmu_buf_hold_array_by_dnode call site and the submit_bio call site. One area I currently focusing on is the SPL taskq's. I have noticed the read queue is dynamic. I am planning on statically allocating all the kernel threads for this queue when the ZFS, SPL module is loaded to see if this has any effect. Any suggestions or advice related to places to focus on in the source code would be greatly be appreciated.

hrtime_dmu_submit_bio_io_schedule_data.zip

[bwatkinson]

Also, I meant to say having the kernel threads in the read taskq statically allocated when the ZPool is created.

[behlendorf]

@bwatkinson the taskq's are a good place to start investigating. I'd suggest setting the spl_taskq_thread_dynamic module option to 0 and see if it helps. This will disable all of the dynamic task queues and statistically allocate the threads.

I'd also suggest looking at the number of threads per taskq in the I/O pipeline. You may be encountering increased contention of the taskq locks due to the very low latency of your devices. Increasing the number of tasks and decreasing the number of threads may help reduce this contention. There is no tuning for this, but it's straight forward to make the change in the source here.

[bwatkinson]

@behlendorf that is the exact source file I am currently manipulating to conduct further testing. I am glad to know I wasn't that far off. At the moment I am just searching for the z_rd_int_* named taskq's in spa_taskqs_init (spa.c) and removing the TASKQ_DYNAMIC flag as a quick test. I wasn't sure if I should mess around with the other taskq's and their dynamic settings at the moment, but I will also disable the spa_taskq_thread_dynamic module parameter with further testing to see if this resolves the present issue. The contention issue also makes sense. I will explore adjusting the number of queues as well as the threads per queue. Thank you for you help with this.

[dweeezil]

Here's a couple of comments from my observations over time which have been gleaned mainly from running various tests and benchmarks on tmpfs-based pools: First off, on highly-concurrent workloads, as @behlendorf alluded to, the overhead in managing dynamic taskqs can become rather significant.

Also, as the devices used for vdevs become ever faster and lower latency, I think the overhead, in general, of the entire zio pipeline can start to become a bottleneck w.r.t. overall latency. I've also discovered that builds containing 1ce23dc (which is not in 0.7.x) can experience a sort-of fixed amount of latency due to zfs_commit_timeout_pct. There are likely other friction points within the ZIL code, but I've done done any more extensive research.

In general, however, it seems that as devices get ever faster and have ever lower latency, some of the rationale for pipelining starts to go away and the overhead in doing so becomes an ever larger contributor to user-visible latency. I think this is an area that's ripe for much more extensive performance analyses and it seems that @bwatkinson's work is a good start.

[janetcampbell]

primarycache=none will kill your read performance. ZFS normally brings in a fair amount of metadata from aggregated reads that you will not see any advantage from. Use primarycache=all and put in a smaller ARC max if you don't like how much memory it takes. Other settings of primarycache are only to be used in dire situations, they are major warning signs that something is wrong.

If you don't have a SLOG, you likely have a pool full of indirect writes. These will also kill read performance, as data and metadata end up fragmented from each other.

Get zpool iostat -r data while you are running a zfs send and while you are running a zfs receive, and post your kernel config and zfs get all - these will help significantly. I suspect you will see a lot of unaggregated 4K reads. If you set the vdev agg max to 1.5m or so and they still don't merge, then you have fragmented metadata. zfs send | receive it to another data set and repeat the test, if it helps significantly then you know what the problem is.

Hope this helps.