lvmcache with a 4.12.3 kernel

Background ^

In the previous two articles I had discovered that lvmcache had amazing performance on an empty cache but then on every run after that (i.e. when the cache device was full of junk) went scarcely better than baseline HDD.

A few days ago I happened across an email on the linux-lvm list where Mike Snitzer advised:

the [CentOS] 7.4 dm-cache will be much more performant than the 7.3 cache you appear to be using.

…and…

It could be that your workload isn’t accessing the data enough to warrant promotion to the cache. dm-cache is a “hotspot” cache. If you aren’t accessing the data repeatedly then you won’t see much benefit (particularly with the 7.3 and earlier releases).

Just to get a feel, you could try the latest upstream 4.12 kernel to see how effective the 7.4 dm-cache will be for your setup.

I don’t know what kernel version CentOS 7.3 uses, but the VM I’m testing with is Debian testing (buster), so some version of 4.11.x plus backported patches.

That seemed pretty new, but Mike is suggesting 4.12.x so I thought I’d re-test lvmcache with the latest stable upstream kernel, which at the time of writing is version 4.12.3.

Test methodology ^

This time around I only focused on fio tests, using the same settings as before:

[partial]
ioengine=libaio
direct=1
iodepth=8
numjobs=2
readwrite=randread
random_distribution=zipf:1.2
bs=4k
size=2g
unlink=1
runtime=20m
time_based=1
per_job_logs=1
log_avg_msec=500
write_iops_log=/var/tmp/fio-${FIOTEST}

The only changes were:

  1. to reduce the run time to 20 minutes from 30 minutes, since all the interesting things happened within the first 20 minutes before.
  2. to write an IOPS log entry every 500ms instead of ever 1000ms, as the log files were quite small and some higher resolution might help smooth graphs out.

Last time there was a dramatic difference between the initial run with an empty cache and subsequent runs with a cache volume full of junk, so I did a test for each of those conditions, as well as tests for the baseline SSD and HDD.

The virtual machine had been upgraded from Debian 9 (stretch) to testing (buster), so it still had packaged kernel versions 4.9.30-2 and 4.11.6-1 laying around to test things with. In addition I compiled up version 4.12.3 by copying the .config from 4.11.6-1 then doing make oldconfig accepting all defaults.

Results ^

Although the fio job spec was essentially the same as in the previous article, I have since worked out how to merge the IOPS logs from both jobs so the graphs will seem to show about double the IOPS as they did before.

All-in-one ^

Well that’s an interesting set of graphs but rather hard to distinguish. Let’s try that by kernel version.

Baseline SSD by kernel version ^

A couple of weird things here:

  1. 4.12.3 and 4.11.6-1 are actually fairly consistent, but 4.9.30-2 varies rather a lot.
  2. All kernels show a sharp dip a few minutes in. I don’t know what that is about.

Although these lines do look quite far apart, bear in mind that this graph’s y axis starts at 92k IOPS. The average IOPS didn’t vary that much:

Average IOPS by kernel version
4.9.30-2 4.11.6-1 4.12.3
102,325 102,742 104,352

So there was actually only a 1.9% difference between the worst performer and the best.

Baseline HDD by kernel version ^

4.9.30-2 and 4.12.3 are close enough here to probably be within the margin of error, but there is something weird going on with 4.11.6-1.

Its average IOPS across the 20 minute test were only 56% of those for 4.12.3 and 53% of those for 4.9.30-2, which is quite a big disparity. I re-ran these tests 5 times to check it wasn’t some anomaly, but no, it’s reproducible.

Maybe something to look into another day.

lvmcache by kernel version ^

Dragging things back to the point of this article: previously we discovered that lvmcache worked great the first time through, when its cache volume was completely empty, but then subsequent runs all absolutely sucked. They didn’t perform significantly better than HDD baseline.

Let’s graph all the lvmcache results for each kernel version against the SSD baseline for that kernel to see if things changed at all.

lvmcache 4.9.30-2 ^

This is the similar to what we saw before: an empty cache volume produces decent results of around 47k IOPS. Although it’s interesting that the second job is down around 1k IOPS. Again the results on a full cache are poor. In fact the results for the second job of the empty cache are about the same as the results for both jobs on a full cache.

lvmcache 4.11.6-1 ^

Same story again here, although the performance is a little higher. Again the first job on an empty cache is getting the big results of almost 60k IOPS while the second job—and both jobs on a full cache—get only around 1k IOPS.

lvmcache 4.12.3 ^

Wow. Something dramatic has been fixed. The performance on an empty cache is still better, but crucially the performance on a full cache pretty quickly becomes very close to baseline SSD.

Also the runs against both the empty and full cache device result in both jobs getting roughly the same IOPS performance rather than the first job being great and all others very poor.

What’s next? ^

It’s really encouraging that the performance is so much better with 4.12.3. It’s changed lvmcache from a “hmm, maybe” option to one that I would strongly consider using anywhere I could.

It’s a shame though that such a new kernel is required. The kernel version in Debian testing (buster) is currently 4.11.6-1. Debian experimental’s linux-image-4.12.0-trunk-amd64 package currently has version 4.12.2-1 so I should test if that is new enough I tested to see if that was new enough.

Failing that I think I should git bisect or similar in order to find out exactly which changeset fixed this, so I could have some chance of knowing when it hits a packaged version.

Test output ^

Kernel 4.12.3 ^

Baseline SSD (4.12.3) ^

$ (cd /srv/ssd/fio && FIOTEST=ssd-4.12.3 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [407.9MB/0KB/0KB /s] [104K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=781: Wed Jul 26 19:03:54 2017
  read : io=237280MB, bw=202479KB/s, iops=50619, runt=1200001msec
    slat (usec): min=0, max=2094, avg= 4.55, stdev= 2.02
    clat (usec): min=36, max=8139, avg=151.16, stdev=42.74
     lat (usec): min=94, max=8140, avg=156.24, stdev=42.71
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  111], 10.00th=[  117], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  147],
     | 70.00th=[  157], 80.00th=[  173], 90.00th=[  201], 95.00th=[  233],
     | 99.00th=[  314], 99.50th=[  338], 99.90th=[  406], 99.95th=[  430],
     | 99.99th=[  502]
    lat (usec) : 50=0.01%, 100=0.10%, 250=96.22%, 500=3.67%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=12.41%, sys=35.81%, ctx=33753770, majf=0, minf=18
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=60743781/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=782: Wed Jul 26 19:03:54 2017
  read : io=251874MB, bw=214932KB/s, iops=53733, runt=1200001msec
    slat (usec): min=0, max=1050, avg= 4.58, stdev= 1.99
    clat (usec): min=25, max=8148, avg=142.00, stdev=31.19
     lat (usec): min=64, max=8151, avg=147.10, stdev=31.17
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  109], 10.00th=[  114], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  135], 60.00th=[  141],
     | 70.00th=[  149], 80.00th=[  161], 90.00th=[  179], 95.00th=[  199],
     | 99.00th=[  243], 99.50th=[  262], 99.90th=[  314], 99.95th=[  334],
     | 99.99th=[  414]
    lat (usec) : 50=0.01%, 100=0.32%, 250=98.86%, 500=0.81%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=12.91%, sys=38.04%, ctx=34484181, majf=1, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=64479700/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=489154MB, aggrb=417411KB/s, minb=202479KB/s, maxb=214932KB/s, mint=1200001msec, maxt=1200001msec
 
Disk stats (read/write):
  xvda: ios=125216086/42, merge=14/33, ticks=18252156/0, in_queue=18285152, util=100.00%

Combined average IOPS were 104,352 or 52,176 per job.

Baseline HDD (4.12.3) ^

$ (cd /srv/slow/fio && FIOTEST=hdd-4.12.3 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [3711KB/0KB/0KB /s] [927/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=2125: Wed Jul 26 22:41:52 2017
  read : io=2194.8MB, bw=1872.8KB/s, iops=468, runt=1200071msec
    slat (usec): min=1, max=125, avg=14.18, stdev= 8.85
    clat (usec): min=54, max=743383, avg=17067.31, stdev=35286.68
     lat (usec): min=65, max=743393, avg=17082.36, stdev=35286.75
    clat percentiles (usec):
     |  1.00th=[   70],  5.00th=[   77], 10.00th=[   87], 20.00th=[  109],
     | 30.00th=[  139], 40.00th=[  205], 50.00th=[ 1012], 60.00th=[ 1560],
     | 70.00th=[15424], 80.00th=[26752], 90.00th=[50944], 95.00th=[82432],
     | 99.00th=[168960], 99.50th=[214016], 99.90th=[313344], 99.95th=[366592],
     | 99.99th=[481280]
    lat (usec) : 100=15.90%, 250=25.89%, 500=3.68%, 750=1.82%, 1000=2.48%
    lat (msec) : 2=10.76%, 4=0.62%, 10=3.27%, 20=10.53%, 50=14.74%
    lat (msec) : 100=6.77%, 250=3.24%, 500=0.28%, 750=0.01%
  cpu          : usr=0.50%, sys=1.08%, ctx=549488, majf=0, minf=18
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=561853/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=2126: Wed Jul 26 22:41:52 2017
  read : io=1975.2MB, bw=1685.4KB/s, iops=421, runt=1200063msec
    slat (usec): min=1, max=169, avg=14.37, stdev= 8.96
    clat (usec): min=42, max=894017, avg=18966.69, stdev=38900.32
     lat (usec): min=67, max=894053, avg=18981.93, stdev=38900.42
    clat percentiles (usec):
     |  1.00th=[   70],  5.00th=[   77], 10.00th=[   87], 20.00th=[  110],
     | 30.00th=[  143], 40.00th=[  213], 50.00th=[ 1064], 60.00th=[ 5984],
     | 70.00th=[16768], 80.00th=[29056], 90.00th=[57088], 95.00th=[91648],
     | 99.00th=[189440], 99.50th=[234496], 99.90th=[346112], 99.95th=[399360],
     | 99.99th=[501760]
    lat (usec) : 50=0.01%, 100=15.65%, 250=25.63%, 500=3.66%, 750=1.72%
    lat (usec) : 1000=2.30%
    lat (msec) : 2=10.10%, 4=0.48%, 10=3.19%, 20=10.79%, 50=14.82%
    lat (msec) : 100=7.33%, 250=3.93%, 500=0.39%, 750=0.01%, 1000=0.01%
  cpu          : usr=0.48%, sys=0.96%, ctx=494683, majf=0, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=505636/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=4169.9MB, aggrb=3558KB/s, minb=1685KB/s, maxb=1872KB/s, mint=1200063msec, maxt=1200071msec
 
Disk stats (read/write):
  xvde: ios=1067472/11, merge=0/17, ticks=19179732/2528, in_queue=19182776, util=100.00%

Average combined IOPS were 889.

lvmcache (4.12.3, empty cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.3 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=0): [f(2)] [100.0% done] [395.1MB/0KB/0KB /s] [101K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1861: Wed Jul 26 21:43:37 2017
  read : io=233021MB, bw=198845KB/s, iops=49711, runt=1200001msec
    slat (usec): min=1, max=696, avg= 6.62, stdev= 2.57
    clat (usec): min=32, max=536652, avg=151.86, stdev=102.22
     lat (usec): min=71, max=536660, avg=158.96, stdev=102.21
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  117], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  147],
     | 70.00th=[  157], 80.00th=[  173], 90.00th=[  203], 95.00th=[  239],
     | 99.00th=[  326], 99.50th=[  362], 99.90th=[  454], 99.95th=[  510],
     | 99.99th=[ 1128]
    lat (usec) : 50=0.01%, 100=0.09%, 250=95.76%, 500=4.10%, 750=0.03%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, 750=0.01%
  cpu          : usr=12.28%, sys=45.34%, ctx=27534900, majf=0, minf=18
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=59653437/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=1862: Wed Jul 26 21:43:37 2017
  read : io=218979MB, bw=186862KB/s, iops=46715, runt=1200001msec
    slat (usec): min=1, max=2349, avg= 6.67, stdev= 2.64
    clat (usec): min=26, max=512486, avg=162.12, stdev=1013.93
     lat (usec): min=64, max=512495, avg=169.27, stdev=1014.06
    clat percentiles (usec):
     |  1.00th=[   98],  5.00th=[  109], 10.00th=[  114], 20.00th=[  121],
     | 30.00th=[  126], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  165], 90.00th=[  187], 95.00th=[  209],
     | 99.00th=[  274], 99.50th=[  306], 99.90th=[  450], 99.95th=[ 9664],
     | 99.99th=[44800]
    lat (usec) : 50=0.01%, 100=1.07%, 250=97.19%, 500=1.66%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.02%, 50=0.02%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
  cpu          : usr=11.90%, sys=42.52%, ctx=25462344, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=56058591/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=452000MB, aggrb=385706KB/s, minb=186861KB/s, maxb=198844KB/s, mint=1200001msec, maxt=1200001msec
 
Disk stats (read/write):
    dm-2: ios=115688209/28, merge=0/0, ticks=18037068/4148, in_queue=18097348, util=100.00%, aggrios=38592557/60889, aggrmerge=0/0, aggrticks=6093288/367342, aggrin_queue=6477849, aggrutil=100.00%
    dm-1: ios=23/117017, merge=0/0, ticks=4/19880, in_queue=19888, util=1.27%, aggrios=115726125/113023, aggrmerge=2/18688, aggrticks=16993500/21068, aggrin_queue=17022812, aggrutil=100.00%
  xvdc: ios=115726125/113023, merge=2/18688, ticks=16993500/21068, in_queue=17022812, util=100.00%
  dm-0: ios=115726104/16785, merge=0/0, ticks=16982820/3328, in_queue=17037740, util=100.00%
    dm-3: ios=51545/48866, merge=0/0, ticks=1297040/1078820, in_queue=2375920, util=20.61%, aggrios=51545/48849, aggrmerge=0/17, aggrticks=1297044/1075220, aggrin_queue=2372260, aggrutil=20.61%
  xvdd: ios=51545/48849, merge=0/17, ticks=1297044/1075220, in_queue=2372260, util=20.61%

lvmcache (4.12.3, full cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.3 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [391.3MB/0KB/0KB /s] [100K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1988: Wed Jul 26 22:13:33 2017
  read : io=142920MB, bw=121958KB/s, iops=30489, runt=1200001msec
    slat (usec): min=0, max=1489, avg= 6.76, stdev= 2.74
    clat (usec): min=27, max=1517.9K, avg=253.15, stdev=3966.27
     lat (usec): min=66, max=1517.1K, avg=260.40, stdev=3966.63
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  108], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  137], 60.00th=[  145],
     | 70.00th=[  155], 80.00th=[  171], 90.00th=[  203], 95.00th=[  245],
     | 99.00th=[  350], 99.50th=[  402], 99.90th=[27776], 99.95th=[61696],
     | 99.99th=[179200]
    lat (usec) : 50=0.01%, 100=0.86%, 250=94.46%, 500=4.44%, 750=0.04%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.04%, 50=0.06%
    lat (msec) : 100=0.03%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=7.69%, sys=28.25%, ctx=17949976, majf=0, minf=17
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=36587548/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=1989: Wed Jul 26 22:13:33 2017
  read : io=142448MB, bw=121556KB/s, iops=30388, runt=1200001msec
    slat (usec): min=1, max=2795, avg= 6.79, stdev= 2.76
    clat (usec): min=14, max=1271.5K, avg=253.96, stdev=4051.40
     lat (usec): min=66, max=1271.5K, avg=261.25, stdev=4051.71
    clat percentiles (usec):
     |  1.00th=[   90],  5.00th=[  108], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  169], 90.00th=[  197], 95.00th=[  231],
     | 99.00th=[  330], 99.50th=[  382], 99.90th=[28288], 99.95th=[63232],
     | 99.99th=[187392]
    lat (usec) : 20=0.01%, 50=0.01%, 100=1.41%, 250=94.94%, 500=3.42%
    lat (usec) : 750=0.03%, 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.04%, 50=0.06%
    lat (msec) : 100=0.03%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=7.79%, sys=28.22%, ctx=17393786, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=36466725/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=285368MB, aggrb=243514KB/s, minb=121555KB/s, maxb=121958KB/s, mint=1200001msec, maxt=1200001msec
 
Disk stats (read/write):
    dm-2: ios=73045110/29, merge=0/0, ticks=18465212/5508, in_queue=18503620, util=100.00%, aggrios=24373349/191891, aggrmerge=0/0, aggrticks=6909396/40201, aggrin_queue=6960561, aggrutil=80.17%
    dm-1: ios=78/509945, merge=0/0, ticks=16/63772, in_queue=63792, util=3.22%, aggrios=72922899/556621, aggrmerge=0/17454, aggrticks=10752172/73676, aggrin_queue=10833040, aggrutil=81.60%
  xvdc: ios=72922899/556621, merge=0/17454, ticks=10752172/73676, in_queue=10833040, util=81.60%
  dm-0: ios=72922821/64279, merge=0/0, ticks=10747112/12240, in_queue=10792240, util=80.17%
    dm-3: ios=197149/1449, merge=0/0, ticks=9981060/44592, in_queue=10025652, util=46.75%, aggrios=197149/1433, aggrmerge=0/16, aggrticks=9981044/40808, aggrin_queue=10021852, aggrutil=46.75%
  xvdd: ios=197149/1433, merge=0/16, ticks=9981044/40808, in_queue=10021852, util=46.75%

Kernel 4.11.6-1 ^

Baseline SSD (4.11.6-1) ^

$ (cd /srv/ssd/fio && FIOTEST=ssd-4.11.6-1 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [401.9MB/0KB/0KB /s] [103K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=2028: Wed Jul 26 18:01:52 2017
  read : io=240561MB, bw=205278KB/s, iops=51319, runt=1200001msec
    slat (usec): min=1, max=231, avg= 4.95, stdev= 1.91
    clat (usec): min=32, max=7892, avg=148.38, stdev=39.27
     lat (usec): min=95, max=7896, avg=153.84, stdev=39.25
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  115], 20.00th=[  122],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  155], 80.00th=[  169], 90.00th=[  193], 95.00th=[  223],
     | 99.00th=[  294], 99.50th=[  326], 99.90th=[  390], 99.95th=[  410],
     | 99.99th=[  474]
    lat (usec) : 50=0.01%, 100=0.12%, 250=97.04%, 500=2.83%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=13.47%, sys=38.85%, ctx=32087576, majf=0, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=61583511/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=2029: Wed Jul 26 18:01:52 2017
  read : io=241050MB, bw=205696KB/s, iops=51423, runt=1200001msec
    slat (usec): min=1, max=1065, avg= 4.98, stdev= 1.91
    clat (usec): min=38, max=7985, avg=148.06, stdev=41.67
     lat (usec): min=63, max=7992, avg=153.54, stdev=41.65
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  109], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  169], 90.00th=[  197], 95.00th=[  229],
     | 99.00th=[  306], 99.50th=[  334], 99.90th=[  398], 99.95th=[  418],
     | 99.99th=[  486]
    lat (usec) : 50=0.01%, 100=0.14%, 250=96.43%, 500=3.41%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=13.70%, sys=38.78%, ctx=31782354, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=61708761/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=481610MB, aggrb=410973KB/s, minb=205278KB/s, maxb=205695KB/s, mint=1200001msec, maxt=1200001msec
 
Disk stats (read/write):
  xvda: ios=123286829/13, merge=0/21, ticks=18148640/0, in_queue=18184316, util=100.00%

Combined average IOPS were 102,742 or 51,371 per job.

Baseline HDD (4.11.6-1) ^

$ (cd /srv/slow/fio && FIOTEST=hdd-4.11.6-1 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [2108KB/0KB/0KB /s] [527/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=904: Thu Jul 27 09:17:21 2017
  read : io=1218.3MB, bw=1039.6KB/s, iops=259, runt=1200088msec
    slat (usec): min=0, max=93, avg=14.37, stdev= 8.02
    clat (usec): min=62, max=1126.5K, avg=30763.45, stdev=56969.73
     lat (usec): min=68, max=1126.5K, avg=30778.70, stdev=56969.84
    clat percentiles (usec):
     |  1.00th=[   70],  5.00th=[   82], 10.00th=[   96], 20.00th=[  129],
     | 30.00th=[  175], 40.00th=[  724], 50.00th=[ 4320], 60.00th=[15552],
     | 70.00th=[29824], 80.00th=[49408], 90.00th=[90624], 95.00th=[140288],
     | 99.00th=[272384], 99.50th=[333824], 99.90th=[489472], 99.95th=[561152],
     | 99.99th=[733184]
    lat (usec) : 100=11.11%, 250=23.85%, 500=3.45%, 750=1.71%, 1000=1.28%
    lat (msec) : 2=6.65%, 4=1.72%, 10=6.07%, 20=7.46%, 50=16.95%
    lat (msec) : 100=11.01%, 250=7.46%, 500=1.19%, 750=0.09%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.21%, sys=0.60%, ctx=303130, majf=0, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=311877/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=905: Thu Jul 27 09:17:21 2017
  read : io=1142.7MB, bw=998342B/s, iops=243, runt=1200098msec
    slat (usec): min=0, max=171, avg=14.44, stdev= 7.98
    clat (usec): min=62, max=1288.1K, avg=32802.09, stdev=60366.24
     lat (usec): min=65, max=1288.2K, avg=32817.41, stdev=60366.35
    clat percentiles (usec):
     |  1.00th=[   71],  5.00th=[   83], 10.00th=[   98], 20.00th=[  133],
     | 30.00th=[  183], 40.00th=[ 1064], 50.00th=[ 7840], 60.00th=[16768],
     | 70.00th=[30592], 80.00th=[51456], 90.00th=[95744], 95.00th=[148480],
     | 99.00th=[292864], 99.50th=[354304], 99.90th=[522240], 99.95th=[593920],
     | 99.99th=[749568]
    lat (usec) : 100=10.59%, 250=22.93%, 500=3.11%, 750=1.64%, 1000=1.14%
    lat (msec) : 2=6.16%, 4=1.30%, 10=5.73%, 20=10.31%, 50=16.53%
    lat (msec) : 100=11.09%, 250=7.93%, 500=1.43%, 750=0.11%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.20%, sys=0.57%, ctx=283410, majf=0, minf=14
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=292507/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=2360.9MB, aggrb=2014KB/s, minb=974KB/s, maxb=1039KB/s, mint=1200088msec, maxt=1200098msec
 
Disk stats (read/write):
  xvde: ios=604364/11, merge=0/17, ticks=19188840/3004, in_queue=19192884, util=100.00%

Average combined IOPS were 502.

lvmcache (4.11.6-1, empty cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.11.6-1 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [229.7MB/0KB/0KB /s] [58.8K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1281: Wed Jul 26 16:36:01 2017
  read : io=270469MB, bw=230800KB/s, iops=57700, runt=1200001msec
    slat (usec): min=1, max=665, avg= 6.06, stdev= 1.39
    clat (usec): min=44, max=1129.8K, avg=130.33, stdev=356.51
     lat (usec): min=98, max=1129.8K, avg=136.83, stdev=356.51
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  105], 10.00th=[  107], 20.00th=[  111],
     | 30.00th=[  116], 40.00th=[  120], 50.00th=[  123], 60.00th=[  126],
     | 70.00th=[  133], 80.00th=[  141], 90.00th=[  161], 95.00th=[  183],
     | 99.00th=[  235], 99.50th=[  258], 99.90th=[  310], 99.95th=[  346],
     | 99.99th=[  940]
    lat (usec) : 50=0.01%, 100=0.32%, 250=99.05%, 500=0.60%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=13.58%, sys=47.73%, ctx=30980580, majf=0, minf=17
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=69240158/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=1282: Wed Jul 26 16:36:01 2017
  read : io=5438.4MB, bw=4640.4KB/s, iops=1160, runt=1200094msec
    slat (usec): min=3, max=501, avg= 8.90, stdev= 3.01
    clat (usec): min=1, max=1109.4K, avg=6884.09, stdev=22209.48
     lat (usec): min=66, max=1109.5K, avg=6893.50, stdev=22209.59
    clat percentiles (usec):
     |  1.00th=[   69],  5.00th=[   76], 10.00th=[   98], 20.00th=[  111],
     | 30.00th=[  118], 40.00th=[  122], 50.00th=[  127], 60.00th=[  135],
     | 70.00th=[  149], 80.00th=[  564], 90.00th=[23680], 95.00th=[43776],
     | 99.00th=[99840], 99.50th=[125440], 99.90th=[197632], 99.95th=[276480],
     | 99.99th=[544768]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=10.37%, 250=68.11%, 500=1.27%, 750=0.77%, 1000=0.64%
    lat (msec) : 2=1.11%, 4=0.37%, 10=1.68%, 20=4.42%, 50=7.14%
    lat (msec) : 100=3.13%, 250=0.94%, 500=0.04%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.39%, sys=1.53%, ctx=1364109, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=1392218/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=275908MB, aggrb=235422KB/s, minb=4640KB/s, maxb=230800KB/s, mint=1200001msec, maxt=1200094msec
 
Disk stats (read/write):
    dm-2: ios=70632376/28, merge=0/0, ticks=18853972/3148, in_queue=18878504, util=100.00%, aggrios=23553400/9408, aggrmerge=0/0, aggrticks=6264994/404240, aggrin_queue=6677382, aggrutil=100.00%
    dm-1: ios=1/372, merge=0/0, ticks=0/120, in_queue=120, util=0.01%, aggrios=70270018/409, aggrmerge=476/2, aggrticks=9314984/128, aggrin_queue=9321056, aggrutil=100.00%
  xvdc: ios=70270018/409, merge=476/2, ticks=9314984/128, in_queue=9321056, util=100.00%
  dm-0: ios=70270493/39, merge=0/0, ticks=9339988/4, in_queue=9364408, util=100.00%
    dm-3: ios=389707/27815, merge=0/0, ticks=9454996/1212596, in_queue=10667620, util=100.00%, aggrios=389707/27324, aggrmerge=0/491, aggrticks=9454912/1121628, aggrin_queue=10576496, aggrutil=100.00%
  xvdd: ios=389707/27324, merge=0/491, ticks=9454912/1121628, in_queue=10576496, util=100.00%

lvmcache (4.11.6-1, full cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.11.6-1 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [4904KB/0KB/0KB /s] [1226/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1723: Wed Jul 26 17:03:19 2017
  read : io=2713.5MB, bw=2315.3KB/s, iops=578, runt=1200126msec
    slat (usec): min=4, max=103, avg=14.92, stdev= 8.59
    clat (usec): min=67, max=943720, avg=13802.04, stdev=37388.05
     lat (usec): min=76, max=943732, avg=13817.72, stdev=37388.50
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  112], 10.00th=[  115], 20.00th=[  119],
     | 30.00th=[  127], 40.00th=[  131], 50.00th=[  141], 60.00th=[  155],
     | 70.00th=[  201], 80.00th=[17280], 90.00th=[43776], 95.00th=[79360],
     | 99.00th=[181248], 99.50th=[234496], 99.90th=[366592], 99.95th=[428032],
     | 99.99th=[585728]
    lat (usec) : 100=0.35%, 250=72.25%, 500=0.73%, 750=0.26%, 1000=0.22%
    lat (msec) : 2=0.53%, 4=0.06%, 10=1.18%, 20=6.18%, 50=9.45%
    lat (msec) : 100=5.33%, 250=3.06%, 500=0.39%, 750=0.02%, 1000=0.01%
  cpu          : usr=0.37%, sys=1.29%, ctx=688778, majf=0, minf=17
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=694643/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=1724: Wed Jul 26 17:03:19 2017
  read : io=2493.3MB, bw=2127.5KB/s, iops=531, runt=1200115msec
    slat (usec): min=3, max=113, avg=15.20, stdev= 8.84
    clat (usec): min=29, max=929665, avg=15021.94, stdev=39251.61
     lat (usec): min=76, max=929675, avg=15037.91, stdev=39252.04
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  112], 10.00th=[  116], 20.00th=[  124],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  143], 60.00th=[  159],
     | 70.00th=[  217], 80.00th=[19328], 90.00th=[48896], 95.00th=[85504],
     | 99.00th=[191488], 99.50th=[242688], 99.90th=[374784], 99.95th=[440320],
     | 99.99th=[602112]
    lat (usec) : 50=0.01%, 100=0.40%, 250=70.92%, 500=0.78%, 750=0.31%
    lat (usec) : 1000=0.23%
    lat (msec) : 2=0.60%, 4=0.08%, 10=1.17%, 20=5.98%, 50=9.80%
    lat (msec) : 100=5.83%, 250=3.46%, 500=0.43%, 750=0.03%, 1000=0.01%
  cpu          : usr=0.35%, sys=1.20%, ctx=632752, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=638283/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=5206.8MB, aggrb=4442KB/s, minb=2127KB/s, maxb=2315KB/s, mint=1200115msec, maxt=1200126msec
 
Disk stats (read/write):
    dm-2: ios=1332926/29, merge=0/0, ticks=19182084/4352, in_queue=19187080, util=100.00%, aggrios=445250/12578, aggrmerge=0/0, aggrticks=6224384/4612, aggrin_queue=6229029, aggrutil=100.00%
    dm-1: ios=60/34939, merge=0/0, ticks=16/6800, in_queue=6820, util=0.28%, aggrios=954236/35982, aggrmerge=0/1722, aggrticks=141920/7080, aggrin_queue=148992, aggrutil=11.70%
  xvdc: ios=954236/35982, merge=0/1722, ticks=141920/7080, in_queue=148992, util=11.70%
  dm-0: ios=954176/2767, merge=0/0, ticks=142036/720, in_queue=142780, util=11.53%
    dm-3: ios=381514/28, merge=0/0, ticks=18531100/6316, in_queue=18537488, util=100.00%, aggrios=381514/13, aggrmerge=0/15, aggrticks=18530984/2632, aggrin_queue=18533840, aggrutil=100.00%
  xvdd: ios=381514/13, merge=0/15, ticks=18530984/2632, in_queue=18533840, util=100.00%

Kernel 4.9.30-2 ^

Baseline SSD (4.9.30-2) ^

$ (cd /srv/ssd/fio && FIOTEST=ssd-4.9.30-2 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=0): [f(2)] [100.0% done] [399.8MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=770: Thu Jul 27 02:27:43 2017
  read : io=241655MB, bw=206212KB/s, iops=51553, runt=1200001msec
    slat (usec): min=1, max=1046, avg= 4.42, stdev= 1.59
    clat (usec): min=28, max=4828, avg=148.39, stdev=42.92
     lat (usec): min=95, max=4830, avg=153.26, stdev=42.90
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  109], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  169], 90.00th=[  197], 95.00th=[  235],
     | 99.00th=[  322], 99.50th=[  350], 99.90th=[  422], 99.95th=[  454],
     | 99.99th=[  532]
    lat (usec) : 50=0.01%, 100=0.15%, 250=96.00%, 500=3.84%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=13.51%, sys=36.36%, ctx=33974378, majf=1, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=61863654/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=771: Thu Jul 27 02:27:43 2017
  read : io=238123MB, bw=203198KB/s, iops=50799, runt=1200001msec
    slat (usec): min=1, max=997, avg= 4.39, stdev= 1.60
    clat (usec): min=42, max=4827, avg=150.72, stdev=47.68
     lat (usec): min=65, max=4832, avg=155.56, stdev=47.66
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  109], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  155], 80.00th=[  171], 90.00th=[  203], 95.00th=[  249],
     | 99.00th=[  342], 99.50th=[  386], 99.90th=[  458], 99.95th=[  486],
     | 99.99th=[  564]
    lat (usec) : 50=0.01%, 100=0.14%, 250=94.88%, 500=4.95%, 750=0.03%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
  cpu          : usr=13.44%, sys=35.68%, ctx=34074578, majf=0, minf=18
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=60959403/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=479778MB, aggrb=409409KB/s, minb=203197KB/s, maxb=206212KB/s, mint=1200001msec, maxt=1200001msec
 
Disk stats (read/write):
  xvda: ios=122797792/38, merge=0/33, ticks=18273356/0, in_queue=18319740, util=100.00%

Combined average IOPS were 102,352 or 51,176 per job.

Baseline HDD (4.9.30-2) ^

$ (cd /srv/slow/fio && FIOTEST=hdd-4.9.30-2 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [3847KB/0KB/0KB /s] [961/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1290: Thu Jul 27 02:57:41 2017
  read : io=2348.2MB, bw=2003.7KB/s, iops=500, runt=1200052msec
    slat (usec): min=2, max=88, avg=12.51, stdev= 7.84
    clat (usec): min=28, max=877693, avg=15952.77, stdev=32920.15
     lat (usec): min=65, max=877697, avg=15966.13, stdev=32920.23
    clat percentiles (usec):
     |  1.00th=[   69],  5.00th=[   77], 10.00th=[   86], 20.00th=[  108],
     | 30.00th=[  139], 40.00th=[  207], 50.00th=[  996], 60.00th=[ 1464],
     | 70.00th=[14912], 80.00th=[25472], 90.00th=[47872], 95.00th=[76288],
     | 99.00th=[156672], 99.50th=[197632], 99.90th=[296960], 99.95th=[346112],
     | 99.99th=[473088]
    lat (usec) : 50=0.01%, 100=15.94%, 250=25.74%, 500=3.72%, 750=1.98%
    lat (usec) : 1000=2.70%
    lat (msec) : 2=11.26%, 4=0.46%, 10=3.02%, 20=11.04%, 50=14.68%
    lat (msec) : 100=6.41%, 250=2.83%, 500=0.20%, 750=0.01%, 1000=0.01%
  cpu          : usr=0.47%, sys=1.14%, ctx=589357, majf=0, minf=16
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=601124/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=1291: Thu Jul 27 02:57:41 2017
  read : io=2094.6MB, bw=1787.3KB/s, iops=446, runt=1200065msec
    slat (usec): min=2, max=136, avg=12.86, stdev= 8.11
    clat (usec): min=57, max=1113.9K, avg=17886.33, stdev=37285.63
     lat (usec): min=62, max=1113.1K, avg=17900.05, stdev=37285.72
    clat percentiles (usec):
     |  1.00th=[   69],  5.00th=[   77], 10.00th=[   87], 20.00th=[  109],
     | 30.00th=[  141], 40.00th=[  209], 50.00th=[ 1032], 60.00th=[ 1832],
     | 70.00th=[16064], 80.00th=[27520], 90.00th=[52992], 95.00th=[85504],
     | 99.00th=[179200], 99.50th=[226304], 99.90th=[346112], 99.95th=[391168],
     | 99.99th=[536576]
    lat (usec) : 100=15.88%, 250=25.66%, 500=3.65%, 750=1.82%, 1000=2.45%
    lat (msec) : 2=10.62%, 4=0.32%, 10=2.87%, 20=11.21%, 50=14.75%
    lat (msec) : 100=6.98%, 250=3.46%, 500=0.34%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.39%, sys=1.08%, ctx=526250, majf=0, minf=14
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=536196/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=4442.7MB, aggrb=3790KB/s, minb=1787KB/s, maxb=2003KB/s, mint=1200052msec, maxt=1200065msec
 
Disk stats (read/write):
  xvde: ios=1137197/11, merge=0/17, ticks=19176720/2496, in_queue=19179612, util=100.00%

Average combined IOPS were 946.

lvmcache (4.9.30-2, empty cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.9.30-2 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [93173KB/0KB/0KB /s] [23.3K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=8863: Wed Jul 26 15:33:04 2017
  read : io=222011MB, bw=189442KB/s, iops=47360, runt=1200047msec
    slat (usec): min=1, max=536, avg= 5.50, stdev= 1.29
    clat (usec): min=45, max=1066.2K, avg=161.37, stdev=2258.81
     lat (usec): min=70, max=1066.2K, avg=167.26, stdev=2258.82
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  106], 20.00th=[  109],
     | 30.00th=[  114], 40.00th=[  118], 50.00th=[  121], 60.00th=[  124],
     | 70.00th=[  129], 80.00th=[  137], 90.00th=[  165], 95.00th=[  197],
     | 99.00th=[  282], 99.50th=[  322], 99.90th=[  422], 99.95th=[ 1176],
     | 99.99th=[90624]
    lat (usec) : 50=0.01%, 100=0.30%, 250=97.69%, 500=1.93%, 750=0.01%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.02%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=10.37%, sys=37.16%, ctx=31754180, majf=0, minf=17
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=56834728/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=8864: Wed Jul 26 15:33:04 2017
  read : io=6439.3MB, bw=5494.3KB/s, iops=1373, runt=1200133msec
    slat (usec): min=2, max=363, avg= 7.53, stdev= 2.49
    clat (usec): min=1, max=1082.6K, avg=5814.26, stdev=21389.31
     lat (usec): min=67, max=1082.6K, avg=5822.26, stdev=21389.42
    clat percentiles (usec):
     |  1.00th=[   72],  5.00th=[   97], 10.00th=[  104], 20.00th=[  109],
     | 30.00th=[  116], 40.00th=[  119], 50.00th=[  123], 60.00th=[  127],
     | 70.00th=[  139], 80.00th=[  318], 90.00th=[18304], 95.00th=[35072],
     | 99.00th=[89600], 99.50th=[120320], 99.90th=[218112], 99.95th=[337920],
     | 99.99th=[593920]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=5.70%
    lat (usec) : 250=73.84%, 500=1.37%, 750=0.81%, 1000=0.81%
    lat (msec) : 2=1.32%, 4=0.26%, 10=1.52%, 20=5.19%, 50=6.12%
    lat (msec) : 100=2.26%, 250=0.72%, 500=0.05%, 750=0.03%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.43%, sys=1.55%, ctx=1616527, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=1648391/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=228450MB, aggrb=194922KB/s, minb=5494KB/s, maxb=189441KB/s, mint=1200047msec, maxt=1200133msec
 
Disk stats (read/write):
    dm-2: ios=58483119/28, merge=0/0, ticks=18951620/1096, in_queue=18967248, util=100.00%, aggrios=19503443/9385, aggrmerge=0/0, aggrticks=6300254/611164, aggrin_queue=6914877, aggrutil=100.00%
    dm-1: ios=1/917, merge=0/0, ticks=0/316, in_queue=316, util=0.01%, aggrios=58032708/925, aggrmerge=600/80, aggrticks=7695844/316, aggrin_queue=7697340, aggrutil=99.47%   
  xvdc: ios=58032708/925, merge=600/80, ticks=7695844/316, in_queue=7697340, util=99.47%
  dm-0: ios=58033307/88, merge=0/0, ticks=7713444/8, in_queue=7724700, util=99.46%
    dm-3: ios=477022/27152, merge=0/0, ticks=11187320/1833168, in_queue=13019616, util=100.00%, aggrios=477022/26569, aggrmerge=0/598, aggrticks=11187220/1810144, aggrin_queue=12996476, aggrutil=100.00%
  xvdd: ios=477022/26569, merge=0/598, ticks=11187220/1810144, in_queue=12996476, util=100.00%

lvmcache (4.9.30-2, full cache device) ^

$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.9.30-2 fio ~/partial.fio)
partial: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=8
...
fio-2.16
Starting 2 processes
partial: Laying out IO file(s) (1 file(s) / 2048MB)
partial: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 2 (f=2): [r(2)] [100.0% done] [5953KB/0KB/0KB /s] [1488/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=9014: Wed Jul 26 16:09:32 2017
  read : io=3180.6MB, bw=2713.1KB/s, iops=678, runt=1200039msec
    slat (usec): min=3, max=172, avg=13.34, stdev= 7.73
    clat (usec): min=65, max=1177.6K, avg=11773.54, stdev=32057.40
     lat (usec): min=72, max=1177.7K, avg=11787.57, stdev=32057.79
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  113], 10.00th=[  118], 20.00th=[  125],
     | 30.00th=[  131], 40.00th=[  133], 50.00th=[  145], 60.00th=[  159],
     | 70.00th=[  213], 80.00th=[16512], 90.00th=[36096], 95.00th=[63232],
     | 99.00th=[148480], 99.50th=[197632], 99.90th=[337920], 99.95th=[415744],
     | 99.99th=[610304]
    lat (usec) : 100=0.45%, 250=70.90%, 500=0.60%, 750=0.28%, 1000=0.30%
    lat (msec) : 2=0.67%, 4=0.04%, 10=1.48%, 20=8.16%, 50=10.28%
    lat (msec) : 100=4.53%, 250=2.07%, 500=0.23%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.34%, sys=1.45%, ctx=806505, majf=0, minf=17
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=814209/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
partial: (groupid=0, jobs=1): err= 0: pid=9015: Wed Jul 26 16:09:32 2017
  read : io=3083.6MB, bw=2631.2KB/s, iops=657, runt=1200059msec
    slat (usec): min=3, max=251, avg=13.31, stdev= 7.88
    clat (usec): min=65, max=1195.8K, avg=12144.40, stdev=32642.85
     lat (usec): min=72, max=1195.8K, avg=12158.39, stdev=32643.28
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  111], 10.00th=[  115], 20.00th=[  122],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  143], 60.00th=[  159],
     | 70.00th=[  221], 80.00th=[17024], 90.00th=[37632], 95.00th=[65280],
     | 99.00th=[152576], 99.50th=[199680], 99.90th=[342016], 99.95th=[419840],
     | 99.99th=[610304]
    lat (usec) : 100=0.49%, 250=70.26%, 500=0.58%, 750=0.27%, 1000=0.30%
    lat (msec) : 2=0.77%, 4=0.04%, 10=1.51%, 20=8.18%, 50=10.43%
    lat (msec) : 100=4.74%, 250=2.17%, 500=0.24%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.43%, sys=1.30%, ctx=782175, majf=0, minf=15
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=789392/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
 
Run status group 0 (all jobs):
   READ: io=6264.7MB, aggrb=5345KB/s, minb=2631KB/s, maxb=2713KB/s, mint=1200039msec, maxt=1200059msec
 
Disk stats (read/write):
    dm-2: ios=1603515/29, merge=0/0, ticks=19178856/4820, in_queue=19184536, util=100.00%, aggrios=535452/12461, aggrmerge=0/0, aggrticks=6232844/4946, aggrin_queue=6237806, aggrutil=100.00%
    dm-1: ios=59/34655, merge=0/0, ticks=16/7544, in_queue=7560, util=0.29%, aggrios=1124948/36669, aggrmerge=0/683, aggrticks=166868/8120, aggrin_queue=174932, aggrutil=13.61%
  xvdc: ios=1124948/36669, merge=0/683, ticks=166868/8120, in_queue=174932, util=13.61%
  dm-0: ios=1124889/2697, merge=0/0, ticks=166996/736, in_queue=167772, util=13.44%
    dm-3: ios=481409/31, merge=0/0, ticks=18531520/6560, in_queue=18538088, util=100.00%, aggrios=481409/14, aggrmerge=0/17, aggrticks=18531404/2968, aggrin_queue=18534356, aggrutil=100.00%
  xvdd: ios=481409/14, merge=0/17, ticks=18531404/2968, in_queue=18534356, util=100.00%

2 thoughts on “lvmcache with a 4.12.3 kernel

Leave a Reply

Your email address will not be published. Required fields are marked *