Tracking down the lvmcache fix

Background ^

In the previous article I covered how, in order to get decent performance out of lvmcache with a packaged Debian kernel, you’d have to use the 4.12.2-1~exp1 kernel from experimental. The kernels packaged in sid, testing (buster) and stable (stretch) aren’t new enough.

I decided to bisect the Linux kernel upstream git repository to find out exactly which commit(s) fixed things.

Results ^

Here’s a graph showing the IOPS over time for baseline SSD and lvmcache with a full cache under several different kernel versions. As in previous articles, the lines are actually Bezier curves fitted to the data which is scattered all over the place from 500ms averages.

What we can see here is that performance starts to improve with commit 4d44ec5ab751 authored by Joe Thornber:

dm cache policy smq: put newly promoted entries at the top of the multiqueue

This stops entries bouncing in and out of the cache quickly.

This is part of a set of commits authored by Joe Thornber on the drivers/md/dm-cache-policy-smq.c file and committed on 2017-05-14. By the time we reach commit 6cf4cc8f8b3b we have the long-term good performance that we were looking for.

The first of Joe Thornber’s commits on that day in the dm-cache area was 072792dcdfc8 and stepping back to the commit immediately prior to that one (2ea659a9ef48) we get a kernel representing the moment that Linus designated the v4.12-rc1 tag. Joe’s commits went into -rc1, and without them the performance of lvmcache under these test conditions isn’t much better than baseline HDD.

It seems like some of Joe’s changes helped a lot and then the last one really provided the long term performance.

git bisect procedure ^

Normally when you do a git bisect you’re starting with something that works and you’re looking for the commit that introduced a bug. In this case I was starting off with a known-good state and was interested in which commit(s) got me there. The normal bisect key words of “good” and “bad” in this case would be backwards to what I wanted. Dominic gave me the tip that I could alias the terms in order to reduce my confusion:

$ git bisect start --term-old broken --term-new fixed

From here on, when I encountered a test run that produced poor results I would issue:

$ git bisect broken

and when I had a test run with good results I would issue:

$ git bisect fixed

As I knew that the tag v4.13-rc1 produced a good run and v4.11 was bad, I could start off with:

$ git bisect reset v4.13-rc1
$ git bisect fixed
$ git bisect broken v4.11

git would then keep bisecting the search space of commits until I would find the one(s) that resulted in the high performance I was looking for.

Good and bad? ^

As before I’m using fio to conduct the testing, with the same job specification:

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

The only difference from the other articles was that the run time was reduced to 15 minutes as all of the interesting behaviour happened within the first 11 minutes.

To recap, this fio job specification lays out two 2GiB files of random data and then starts two processes that perform 4kiB-sized reads against the files. Direct IO is used, in order to bypass the page cache.

A Zipfian distribution with a factor of 1.2 is used; this gives a 90/10 split where about 90% of the reads should come from about 10% of the data. The purpose of this is to simulate the hot spots of popular data that occur in real life. If the access pattern were to be perfectly and uniformly random then caching would not be effective.

In previous tests we had observed that dramatically different performance would be seen on the first run against an empty cache device compared to all other subsequent runs against what would be a full cache device. In the tests using kernels with the fix present the IOPS achieved would converge towards baseline SSD performance, whereas in kernels without the fix the performance would remain down near the level of baseline HDD. Therefore the fio tests were carried out twice.

Where to next? ^

I think I am going to see what happens when the cache device is pretty small in comparison to the working data.

All of the tests so far have used a 4GiB cache with 4GiB of data, so if everything got promoted it would entirely fit in cache. Not only that but the Zipf distribution makes most of the hits come from 10% of the data, so it’s actually just ~400MiB of hot data. I think it would be interesting to see what happens when the hot 10% is bigger than the cache device.

git bisect progress and test output ^

Unless you are particularly interested in the fio output and why I considered each one to be either fixed or broken, you probably want to stop reading now.

4.12.0-rc1+ ^

I forgot to record the commit revision for this test so all I know is that it’s from somewhere in the first v4.12 release candidate.

The second job against an empty cache shows poor performance (8,210 average IOPS), and both jobs against a full cache show poor performance (2,141, 730 average IOPS), so this was marked broken.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+ 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] [206.7MB/0KB/0KB /s] [52.9K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1275: Fri Jul 28 18:23:26 2017
  read : io=126101MB, bw=143465KB/s, iops=35866, runt=900065msec
    slat (usec): min=3, max=25001, avg= 6.12, stdev= 4.73
    clat (usec): min=19, max=808324, avg=214.83, stdev=2941.63
     lat (usec): min=68, max=808334, avg=221.36, stdev=2942.04
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  105], 10.00th=[  106], 20.00th=[  109],
     | 30.00th=[  112], 40.00th=[  116], 50.00th=[  120], 60.00th=[  123],
     | 70.00th=[  129], 80.00th=[  137], 90.00th=[  161], 95.00th=[  207],
     | 99.00th=[  362], 99.50th=[  422], 99.90th=[27008], 99.95th=[50944],
     | 99.99th=[138240]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.23%, 250=96.86%, 500=2.52%
    lat (usec) : 750=0.07%, 1000=0.05%
    lat (msec) : 2=0.11%, 4=0.01%, 10=0.01%, 20=0.03%, 50=0.08%
    lat (msec) : 100=0.03%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=9.28%, sys=32.19%, ctx=19968665, 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=32281968/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=1276: Fri Jul 28 18:23:26 2017
  read : io=28868MB, bw=32843KB/s, iops=8210, runt=900062msec
    slat (usec): min=3, max=238, avg= 7.37, stdev= 3.18
    clat (usec): min=1, max=718073, avg=964.43, stdev=8565.89
     lat (usec): min=67, max=718080, avg=972.27, stdev=8566.73
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  104], 10.00th=[  106], 20.00th=[  109],
     | 30.00th=[  113], 40.00th=[  117], 50.00th=[  120], 60.00th=[  122],
     | 70.00th=[  126], 80.00th=[  133], 90.00th=[  157], 95.00th=[  237],
     | 99.00th=[27264], 99.50th=[51456], 99.90th=[127488], 99.95th=[164864],
     | 99.99th=[261120]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=0.75%
    lat (usec) : 250=94.77%, 500=2.20%, 750=0.11%, 1000=0.08%
    lat (msec) : 2=0.15%, 4=0.02%, 10=0.13%, 20=0.52%, 50=0.75%
    lat (msec) : 100=0.35%, 250=0.16%, 500=0.01%, 750=0.01%
  cpu          : usr=2.57%, sys=8.79%, ctx=6706909, 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=7390152/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=154969MB, aggrb=176307KB/s, minb=32842KB/s, maxb=143465KB/s, mint=900062msec, maxt=900065msec
 
Disk stats (read/write):
    dm-2: ios=39667388/28, merge=0/0, ticks=14142912/5308, in_queue=14158728, util=100.00%, aggrios=13263605/322030, aggrmerge=0/0, aggrticks=5479672/69964, aggrin_queue=5551697, aggrutil=100.00%
    dm-1: ios=2/847365, merge=0/0, ticks=0/131084, in_queue=131108, util=10.32%, aggrios=39457066/908046, aggrmerge=1462/48403, aggrticks=5249084/146536, aggrin_queue=5395788, aggrutil=99.89%
  xvdc: ios=39457066/908046, merge=1462/48403, ticks=5249084/146536, in_queue=5395788, util=99.89%
  dm-0: ios=39458525/110207, merge=0/0, ticks=5253332/20832, in_queue=5280728, util=99.89%
    dm-3: ios=332289/8519, merge=0/0, ticks=11185684/57976, in_queue=11243256, util=100.00%, aggrios=332289/6962, aggrmerge=0/1563, aggrticks=11185604/38544, aggrin_queue=11223832, aggrutil=100.00%
  xvdd: ios=332289/6962, merge=0/1563, ticks=11185604/38544, in_queue=11223832, util=100.00%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+ 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] [14150KB/0KB/0KB /s] [3537/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1674: Fri Jul 28 18:51:41 2017
  read : io=7529.9MB, bw=8566.5KB/s, iops=2141, runt=900093msec
    slat (usec): min=3, max=190, avg= 7.84, stdev= 5.41
    clat (usec): min=34, max=1514.5K, avg=3725.26, stdev=24447.20
     lat (usec): min=72, max=1514.6K, avg=3733.56, stdev=24449.04
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  103], 10.00th=[  104], 20.00th=[  106],
     | 30.00th=[  107], 40.00th=[  108], 50.00th=[  109], 60.00th=[  118],
     | 70.00th=[  121], 80.00th=[  123], 90.00th=[  155], 95.00th=[12992],
     | 99.00th=[100864], 99.50th=[158720], 99.90th=[325632], 99.95th=[419840],
     | 99.99th=[675840]
    lat (usec) : 50=0.01%, 100=0.39%, 250=93.41%, 500=0.29%, 750=0.08%
    lat (usec) : 1000=0.06%
    lat (msec) : 2=0.12%, 4=0.01%, 10=0.29%, 20=1.36%, 50=1.88%
    lat (msec) : 100=1.12%, 250=0.82%, 500=0.17%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.73%, sys=2.52%, ctx=1993978, 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=1927642/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=1675: Fri Jul 28 18:51:41 2017
  read : io=2568.1MB, bw=2921.6KB/s, iops=730, runt=900113msec
    slat (usec): min=3, max=146, avg= 8.82, stdev= 5.83
    clat (usec): min=64, max=1522.3K, avg=10941.33, stdev=44467.18
     lat (usec): min=70, max=1522.3K, avg=10950.66, stdev=44468.17
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  106], 20.00th=[  108],
     | 30.00th=[  117], 40.00th=[  119], 50.00th=[  121], 60.00th=[  123],
     | 70.00th=[  135], 80.00th=[  161], 90.00th=[26240], 95.00th=[62720],
     | 99.00th=[205824], 99.50th=[288768], 99.90th=[528384], 99.95th=[659456],
     | 99.99th=[1036288]
    lat (usec) : 100=0.30%, 250=83.22%, 500=0.41%, 750=0.11%, 1000=0.08%
    lat (msec) : 2=0.15%, 4=0.02%, 10=0.62%, 20=3.47%, 50=5.45%
    lat (msec) : 100=3.16%, 250=2.31%, 500=0.57%, 750=0.08%, 1000=0.02%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.35%, sys=0.94%, ctx=673091, 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=657432/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=10098MB, aggrb=11487KB/s, minb=2921KB/s, maxb=8566KB/s, mint=900093msec, maxt=900113msec
 
Disk stats (read/write):
    dm-2: ios=2585032/29, merge=0/0, ticks=14380160/2084, in_queue=14383828, util=100.00%, aggrios=897708/321791, aggrmerge=0/0, aggrticks=6187020/40796, aggrin_queue=6227841, aggrutil=100.00%
    dm-1: ios=34/857325, merge=0/0, ticks=4/100092, in_queue=100120, util=6.30%, aggrios=2366278/926181, aggrmerge=0/38684, aggrticks=290092/115464, aggrin_queue=405484, aggrutil=35.21%
  xvdc: ios=2366278/926181, merge=0/38684, ticks=290092/115464, in_queue=405484, util=35.21%
  dm-0: ios=2366244/108039, merge=0/0, ticks=290336/20212, in_queue=310600, util=30.59%
    dm-3: ios=326848/10, merge=0/0, ticks=18270720/2084, in_queue=18272804, util=100.00%, aggrios=326848/6, aggrmerge=0/4, aggrticks=18270688/1332, aggrin_queue=18272160, aggrutil=100.00%
  xvdd: ios=326848/6, merge=0/4, ticks=18270688/1332, in_queue=18272160, util=100.00%

4.12.0+5518b69b7668 (2017-07-05 12:31:59 -0700) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0+ 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.3MB/0KB/0KB /s] [103K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1126: Fri Jul 28 21:06:01 2017
  read : io=178623MB, bw=203233KB/s, iops=50808, runt=900001msec
    slat (usec): min=1, max=3059, avg= 7.04, stdev= 3.00
    clat (usec): min=37, max=1175.7K, avg=147.92, stdev=585.27
     lat (usec): min=66, max=1175.7K, avg=155.43, stdev=585.32
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  110], 10.00th=[  114], 20.00th=[  121],
     | 30.00th=[  126], 40.00th=[  131], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  163], 90.00th=[  185], 95.00th=[  207],
     | 99.00th=[  274], 99.50th=[  314], 99.90th=[  434], 99.95th=[  498],
     | 99.99th=[ 1400]
    lat (usec) : 50=0.01%, 100=0.42%, 250=97.80%, 500=1.72%, 750=0.02%
    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=14.76%, sys=51.47%, ctx=19663307, 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=45727501/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=1127: Fri Jul 28 21:06:01 2017
  read : io=170314MB, bw=193779KB/s, iops=48444, runt=900001msec
    slat (usec): min=0, max=4199, avg= 7.13, stdev= 3.11
    clat (usec): min=29, max=493434, avg=155.48, stdev=688.81
     lat (usec): min=64, max=493446, avg=163.07, stdev=688.95
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  111], 10.00th=[  116], 20.00th=[  122],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  153], 80.00th=[  167], 90.00th=[  189], 95.00th=[  215],
     | 99.00th=[  290], 99.50th=[  326], 99.90th=[  446], 99.95th=[  588],
     | 99.99th=[27008]
    lat (usec) : 50=0.01%, 100=0.32%, 250=97.35%, 500=2.27%, 750=0.02%
    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%
  cpu          : usr=13.65%, sys=50.13%, ctx=18808830, 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=43600368/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=348937MB, aggrb=397012KB/s, minb=193779KB/s, maxb=203233KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=89308932/28, merge=0/0, ticks=13329748/144, in_queue=13365712, util=100.00%, aggrios=29798461/41330, aggrmerge=0/0, aggrticks=4447461/538024, aggrin_queue=4995029, aggrutil=100.00%
    dm-1: ios=54/56500, merge=0/0, ticks=4/10576, in_queue=10580, util=0.86%, aggrios=89368372/54448, aggrmerge=3/8823, aggrticks=12815140/10948, aggrin_queue=12836708, aggrutil=100.00%
  xvdc: ios=89368372/54448, merge=3/8823, ticks=12815140/10948, in_queue=12836708, util=100.00%
  dm-0: ios=89368321/7982, merge=0/0, ticks=12772360/1672, in_queue=12802664, util=100.00%
    dm-3: ios=27010/59510, merge=0/0, ticks=570020/1601824, in_queue=2171844, util=22.47%, aggrios=27010/59506, aggrmerge=0/4, aggrticks=570012/1588432, aggrin_queue=2158444, aggrutil=22.47%
  xvdd: ios=27010/59506, merge=0/4, ticks=570012/1588432, in_queue=2158444, util=22.47%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0+ 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] [398.2MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1701: Fri Jul 28 21:31:14 2017
  read : io=81664MB, bw=92916KB/s, iops=23228, runt=900001msec
    slat (usec): min=1, max=236, avg= 7.03, stdev= 2.96
    clat (usec): min=20, max=1436.8K, avg=334.90, stdev=5455.47
     lat (usec): min=65, max=1436.8K, avg=342.37, stdev=5455.94
    clat percentiles (usec):
     |  1.00th=[   98],  5.00th=[  106], 10.00th=[  108], 20.00th=[  116],
     | 30.00th=[  122], 40.00th=[  127], 50.00th=[  135], 60.00th=[  143],
     | 70.00th=[  155], 80.00th=[  171], 90.00th=[  197], 95.00th=[  225],
     | 99.00th=[  322], 99.50th=[  406], 99.90th=[57600], 99.95th=[102912],
     | 99.99th=[244736]
    lat (usec) : 50=0.01%, 100=1.15%, 250=95.96%, 500=2.51%, 750=0.04%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.80%, sys=24.11%, ctx=10402905, 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=20906091/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=1702: Fri Jul 28 21:31:14 2017
  read : io=70584MB, bw=80309KB/s, iops=20077, runt=900001msec
    slat (usec): min=0, max=1925, avg= 7.09, stdev= 3.08
    clat (usec): min=28, max=1511.1K, avg=388.89, stdev=6127.50
     lat (usec): min=66, max=1511.1K, avg=396.42, stdev=6127.96
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  108], 10.00th=[  114], 20.00th=[  121],
     | 30.00th=[  127], 40.00th=[  135], 50.00th=[  145], 60.00th=[  155],
     | 70.00th=[  169], 80.00th=[  187], 90.00th=[  223], 95.00th=[  266],
     | 99.00th=[  382], 99.50th=[  470], 99.90th=[69120], 99.95th=[120320],
     | 99.99th=[272384]
    lat (usec) : 50=0.01%, 100=0.87%, 250=92.83%, 500=5.85%, 750=0.06%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.70%, sys=21.56%, ctx=9637603, 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=18069579/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=152249MB, aggrb=173225KB/s, minb=80309KB/s, maxb=92915KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=38952573/29, merge=0/0, ticks=13950768/2216, in_queue=13969108, util=100.00%, aggrios=13013773/192960, aggrmerge=0/0, aggrticks=5424846/37388, aggrin_queue=5466722, aggrutil=70.38%
    dm-1: ios=50/513251, merge=0/0, ticks=0/63836, in_queue=63844, util=4.22%, aggrios=38843781/560322, aggrmerge=0/17355, aggrticks=5786824/73580, aggrin_queue=5863840, aggrutil=72.24%
  xvdc: ios=38843781/560322, merge=0/17355, ticks=5786824/73580, in_queue=5863840, util=72.24%
  dm-0: ios=38843731/64559, merge=0/0, ticks=5772804/12088, in_queue=5798340, util=70.38%
    dm-3: ios=197538/1071, merge=0/0, ticks=10501736/36240, in_queue=10537984, util=66.09%, aggrios=197538/1068, aggrmerge=0/3, aggrticks=10501736/35036, aggrin_queue=10536764, aggrutil=66.09%
  xvdd: ios=197538/1068, merge=0/3, ticks=10501736/35036, in_queue=10536764, util=66.09%

4.12.0-rc7+458bc30cec26 (2017-07-04 22:35:16 +0100) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc7+ 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.1MB/0KB/0KB /s] [104K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1154: Sat Jul 29 00:38:19 2017
  read : io=183121MB, bw=208350KB/s, iops=52087, runt=900001msec
    slat (usec): min=2, max=7756, avg= 6.96, stdev= 2.90
    clat (usec): min=44, max=1200.4K, avg=144.14, stdev=472.71
     lat (usec): min=71, max=1200.4K, avg=151.59, stdev=472.73
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  114], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  135], 60.00th=[  143],
     | 70.00th=[  151], 80.00th=[  161], 90.00th=[  181], 95.00th=[  201],
     | 99.00th=[  262], 99.50th=[  298], 99.90th=[  418], 99.95th=[  466],
     | 99.99th=[ 1064]
    lat (usec) : 50=0.01%, 100=0.11%, 250=98.52%, 500=1.34%, 750=0.02%
    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=12.82%, sys=49.46%, ctx=19495852, 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=46878856/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=1155: Sat Jul 29 00:38:19 2017
  read : io=173527MB, bw=197435KB/s, iops=49358, runt=900001msec
    slat (usec): min=2, max=4008, avg= 6.91, stdev= 2.74
    clat (usec): min=1, max=1231.4K, avg=152.67, stdev=790.02
     lat (usec): min=70, max=1231.4K, avg=160.07, stdev=790.13
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  110], 10.00th=[  115], 20.00th=[  121],
     | 30.00th=[  126], 40.00th=[  133], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  163], 90.00th=[  183], 95.00th=[  205],
     | 99.00th=[  266], 99.50th=[  298], 99.90th=[  430], 99.95th=[  548],
     | 99.99th=[24192]
    lat (usec) : 2=0.01%, 50=0.01%, 100=0.10%, 250=98.42%, 500=1.42%
    lat (usec) : 750=0.02%, 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=12.64%, sys=46.41%, ctx=18940551, 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=44422812/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=356647MB, aggrb=405784KB/s, minb=197434KB/s, maxb=208350KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=91291408/28, merge=0/0, ticks=13391864/1088, in_queue=13429116, util=100.00%, aggrios=30455976/37704, aggrmerge=0/0, aggrticks=4468269/553084, aggrin_queue=5032300, aggrutil=100.00%
    dm-1: ios=20/46840, merge=0/0, ticks=4/8444, in_queue=8452, util=0.72%, aggrios=91341450/45704, aggrmerge=35/6871, aggrticks=12941984/9032, aggrin_queue=12962160, aggrutil=100.00%
  xvdc: ios=91341450/45704, merge=35/6871, ticks=12941984/9032, in_queue=12962160, util=100.00%
  dm-0: ios=91341465/6637, merge=0/0, ticks=12928860/1388, in_queue=12963072, util=100.00%
    dm-3: ios=26445/59635, merge=0/0, ticks=475944/1649420, in_queue=2125376, util=22.10%, aggrios=26445/59598, aggrmerge=0/37, aggrticks=475956/1637996, aggrin_queue=2113944, aggrutil=22.10%
  xvdd: ios=26445/59598, merge=0/37, ticks=475956/1637996, in_queue=2113944, util=22.10%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc7+ 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=1692: Sat Jul 29 01:03:52 2017
  read : io=80360MB, bw=91432KB/s, iops=22857, runt=900001msec
    slat (usec): min=2, max=2817, avg= 6.86, stdev= 2.92
    clat (usec): min=29, max=1517.4K, avg=340.64, stdev=5499.29
     lat (usec): min=70, max=1517.4K, avg=347.99, stdev=5499.77
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  108], 10.00th=[  112], 20.00th=[  120],
     | 30.00th=[  124], 40.00th=[  129], 50.00th=[  135], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  171], 90.00th=[  205], 95.00th=[  247],
     | 99.00th=[  346], 99.50th=[  414], 99.90th=[57600], 99.95th=[104960],
     | 99.99th=[248832]
    lat (usec) : 50=0.01%, 100=0.11%, 250=95.21%, 500=4.30%, 750=0.03%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.03%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.73%, sys=21.81%, ctx=10535581, 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=20572128/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=1693: Sat Jul 29 01:03:52 2017
  read : io=78767MB, bw=89620KB/s, iops=22404, runt=900001msec
    slat (usec): min=2, max=4079, avg= 6.86, stdev= 3.00
    clat (usec): min=37, max=1305.7K, avg=347.72, stdev=5796.35
     lat (usec): min=70, max=1305.7K, avg=355.07, stdev=5796.74
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  108], 10.00th=[  112], 20.00th=[  119],
     | 30.00th=[  124], 40.00th=[  129], 50.00th=[  135], 60.00th=[  141],
     | 70.00th=[  149], 80.00th=[  161], 90.00th=[  181], 95.00th=[  203],
     | 99.00th=[  270], 99.50th=[  350], 99.90th=[62208], 99.95th=[111104],
     | 99.99th=[264192]
    lat (usec) : 50=0.01%, 100=0.14%, 250=98.33%, 500=1.15%, 750=0.02%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.40%, sys=21.50%, ctx=9823341, 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=20164463/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=159127MB, aggrb=181051KB/s, minb=89619KB/s, maxb=91431KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=40711294/29, merge=0/0, ticks=13985492/1604, in_queue=14002044, util=100.00%, aggrios=13600731/192513, aggrmerge=0/0, aggrticks=5441234/38712, aggrin_queue=5484525, aggrutil=70.85%
    dm-1: ios=26/511933, merge=0/0, ticks=4/63176, in_queue=63180, util=4.35%, aggrios=40605636/559333, aggrmerge=1/16864, aggrticks=5853336/73380, aggrin_queue=5930420, aggrutil=72.72%
  xvdc: ios=40605636/559333, merge=1/16864, ticks=5853336/73380, in_queue=5930420, util=72.72%
  dm-0: ios=40605611/64403, merge=0/0, ticks=5848084/12288, in_queue=5874032, util=70.85%
    dm-3: ios=196556/1204, merge=0/0, ticks=10475616/40672, in_queue=10516364, util=65.70%, aggrios=196556/1201, aggrmerge=0/3, aggrticks=10475564/39108, aggrin_queue=10514664, aggrutil=65.70%
  xvdd: ios=196556/1201, merge=0/3, ticks=10475564/39108, in_queue=10514664, util=65.70%

4.12.0-rc4+458bc30cec26 (2017-07-04 22:35:16 +0100) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc4+ 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] [395.4MB/0KB/0KB /s] [101K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1087: Sat Jul 29 02:19:19 2017
  read : io=175192MB, bw=199329KB/s, iops=49832, runt=900001msec
    slat (usec): min=0, max=3864, avg= 6.57, stdev= 3.22
    clat (usec): min=30, max=267928, avg=151.65, stdev=87.18
     lat (usec): min=69, max=267942, avg=158.71, stdev=87.17
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  114], 20.00th=[  121],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  155], 80.00th=[  171], 90.00th=[  203], 95.00th=[  245],
     | 99.00th=[  334], 99.50th=[  374], 99.90th=[  462], 99.95th=[  516],
     | 99.99th=[ 1096]
    lat (usec) : 50=0.01%, 100=0.13%, 250=95.23%, 500=4.58%, 750=0.04%
    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%
  cpu          : usr=11.80%, sys=44.52%, ctx=20627701, 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=44849083/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=1088: Sat Jul 29 02:19:19 2017
  read : io=169484MB, bw=192835KB/s, iops=48208, runt=900001msec
    slat (usec): min=0, max=920, avg= 6.65, stdev= 3.13
    clat (usec): min=27, max=395221, avg=156.93, stdev=712.11
     lat (usec): min=64, max=395249, avg=164.07, stdev=712.24
    clat percentiles (usec):
     |  1.00th=[   92],  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=[  167], 90.00th=[  197], 95.00th=[  235],
     | 99.00th=[  322], 99.50th=[  358], 99.90th=[  466], 99.95th=[  636],
     | 99.99th=[29056]
    lat (usec) : 50=0.01%, 100=1.35%, 250=94.81%, 500=3.76%, 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%, 500=0.01%
  cpu          : usr=11.83%, sys=43.37%, ctx=19677405, 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=43387901/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=344676MB, aggrb=392163KB/s, minb=192834KB/s, maxb=199329KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=88216016/26, merge=0/0, ticks=13519572/1384, in_queue=13556832, util=100.00%, aggrios=29434288/40523, aggrmerge=0/0, aggrticks=4526756/395165, aggrin_queue=4932334, aggrutil=100.00%
    dm-1: ios=16/55677, merge=0/0, ticks=0/10000, in_queue=10004, util=0.85%, aggrios=88278149/52300, aggrmerge=0/9623, aggrticks=13075608/10432, aggrin_queue=13103668, aggrutil=100.00%
  xvdc: ios=88278149/52300, merge=0/9623, ticks=13075608/10432, in_queue=13103668, util=100.00%
  dm-0: ios=88278133/7958, merge=0/0, ticks=13062252/1688, in_queue=13095112, util=100.00%
    dm-3: ios=24715/57934, merge=0/0, ticks=518016/1173808, in_queue=1691888, util=19.21%, aggrios=24715/57931, aggrmerge=0/3, aggrticks=518016/1170636, aggrin_queue=1688652, aggrutil=19.21%
  xvdd: ios=24715/57931, merge=0/3, ticks=518016/1170636, in_queue=1688652, util=19.21%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc4+ 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=1): [f(2)] [100.0% done] [397.5MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1441: Sat Jul 29 02:36:06 2017
  read : io=87028MB, bw=99018KB/s, iops=24754, runt=900001msec
    slat (usec): min=0, max=2668, avg= 6.39, stdev= 3.49
    clat (usec): min=4, max=1267.9K, avg=314.52, stdev=5200.82
     lat (usec): min=70, max=1267.1K, avg=321.40, stdev=5201.22
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  108], 10.00th=[  112], 20.00th=[  118],
     | 30.00th=[  123], 40.00th=[  129], 50.00th=[  133], 60.00th=[  139],
     | 70.00th=[  147], 80.00th=[  157], 90.00th=[  179], 95.00th=[  201],
     | 99.00th=[  274], 99.50th=[  354], 99.90th=[52480], 99.95th=[95744],
     | 99.99th=[236544]
    lat (usec) : 10=0.01%, 50=0.01%, 100=0.15%, 250=98.28%, 500=1.22%
    lat (usec) : 750=0.02%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.10%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.77%, sys=21.69%, ctx=10852657, 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=22279060/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=1442: Sat Jul 29 02:36:06 2017
  read : io=75046MB, bw=85385KB/s, iops=21346, runt=900001msec
    slat (usec): min=0, max=2520, avg= 6.59, stdev= 3.40
    clat (usec): min=18, max=1428.8K, avg=365.77, stdev=5975.46
     lat (usec): min=70, max=1428.8K, avg=372.86, stdev=5975.77
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  111], 10.00th=[  116], 20.00th=[  122],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  155], 80.00th=[  173], 90.00th=[  207], 95.00th=[  249],
     | 99.00th=[  350], 99.50th=[  426], 99.90th=[63744], 99.95th=[112128],
     | 99.99th=[264192]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.11%, 250=94.94%, 500=4.55%
    lat (usec) : 750=0.03%, 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.28%, sys=19.54%, ctx=9973368, 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=19211686/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=162073MB, aggrb=184403KB/s, minb=85385KB/s, maxb=99017KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=41467013/28, merge=0/0, ticks=13982352/436, in_queue=14002096, util=100.00%, aggrios=13852123/192595, aggrmerge=0/0, aggrticks=5439580/41926, aggrin_queue=5486213, aggrutil=71.52%
    dm-1: ios=40/512174, merge=0/0, ticks=16/65512, in_queue=65540, util=4.37%, aggrios=41359847/559061, aggrmerge=1/17352, aggrticks=5953780/75680, aggrin_queue=6035140, aggrutil=73.41%
  xvdc: ios=41359847/559061, merge=1/17352, ticks=5953780/75680, in_queue=6035140, util=73.41%
  dm-0: ios=41359808/64396, merge=0/0, ticks=5949272/12428, in_queue=5975644, util=71.52%
    dm-3: ios=196521/1217, merge=0/0, ticks=10369452/47840, in_queue=10417456, util=65.41%, aggrios=196521/1215, aggrmerge=0/2, aggrticks=10369400/46792, aggrin_queue=10416188, aggrutil=65.41%
  xvdd: ios=196521/1215, merge=0/2, ticks=10369400/46792, in_queue=10416188, util=65.41%

4.12.0-rc2+b870aa901f4b (2017-05-31 19:29:48 -0400) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc2+ 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] [387.1MB/0KB/0KB /s] [99.3K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1034: Sat Jul 29 03:42:15 2017
  read : io=170714MB, bw=194235KB/s, iops=48558, runt=900001msec
    slat (usec): min=0, max=5188, avg= 7.17, stdev= 3.84
    clat (usec): min=33, max=868253, avg=154.79, stdev=246.43
     lat (usec): min=74, max=868258, avg=162.45, stdev=246.45
    clat percentiles (usec):
     |  1.00th=[  106],  5.00th=[  112], 10.00th=[  118], 20.00th=[  125],
     | 30.00th=[  131], 40.00th=[  137], 50.00th=[  143], 60.00th=[  151],
     | 70.00th=[  161], 80.00th=[  175], 90.00th=[  203], 95.00th=[  239],
     | 99.00th=[  326], 99.50th=[  362], 99.90th=[  454], 99.95th=[  510],
     | 99.99th=[ 1176]
    lat (usec) : 50=0.01%, 100=0.07%, 250=95.81%, 500=4.06%, 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%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=13.58%, sys=46.69%, ctx=17639239, 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=43702872/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=1035: Sat Jul 29 03:42:15 2017
  read : io=166633MB, bw=189591KB/s, iops=47397, runt=900001msec
    slat (usec): min=0, max=5427, avg= 7.20, stdev= 3.86
    clat (usec): min=25, max=1052.1K, avg=158.78, stdev=971.36
     lat (usec): min=67, max=1052.1K, avg=166.47, stdev=971.50
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  116], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  141], 60.00th=[  147],
     | 70.00th=[  157], 80.00th=[  169], 90.00th=[  191], 95.00th=[  211],
     | 99.00th=[  274], 99.50th=[  310], 99.90th=[  454], 99.95th=[  740],
     | 99.99th=[31104]
    lat (usec) : 50=0.01%, 100=0.09%, 250=98.15%, 500=1.69%, 750=0.02%
    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%, 2000=0.01%
  cpu          : usr=13.55%, sys=45.80%, ctx=17358595, 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=42657995/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=337347MB, aggrb=383825KB/s, minb=189590KB/s, maxb=194234KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=86351783/28, merge=0/0, ticks=13253620/1212, in_queue=13300668, util=100.00%, aggrios=28809668/39785, aggrmerge=0/0, aggrticks=4427297/502156, aggrin_queue=4941461, aggrutil=100.00%
    dm-1: ios=23/51212, merge=0/0, ticks=0/9628, in_queue=9632, util=0.83%, aggrios=86400786/48163, aggrmerge=36/10034, aggrticks=12739236/9992, aggrin_queue=12763444, aggrutil=100.00%
  xvdc: ios=86400786/48163, merge=36/10034, ticks=12739236/9992, in_queue=12763444, util=100.00%
  dm-0: ios=86400799/7291, merge=0/0, ticks=12710904/1508, in_queue=12748372, util=100.00%
    dm-3: ios=28182/60853, merge=0/0, ticks=570988/1495332, in_queue=2066380, util=21.95%, aggrios=28182/60807, aggrmerge=0/46, aggrticks=570992/1486948, aggrin_queue=2057924, aggrutil=21.95%
  xvdd: ios=28182/60807, merge=0/46, ticks=570992/1486948, in_queue=2057924, util=21.95%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc2+ 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] [373.7MB/0KB/0KB /s] [95.7K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1530: Sat Jul 29 03:59:03 2017
  read : io=76723MB, bw=87294KB/s, iops=21823, runt=900001msec
    slat (usec): min=0, max=2653, avg= 6.62, stdev= 4.06
    clat (usec): min=30, max=1178.5K, avg=357.41, stdev=5505.55
     lat (usec): min=70, max=1178.5K, avg=364.48, stdev=5505.64
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  112], 10.00th=[  117], 20.00th=[  124],
     | 30.00th=[  131], 40.00th=[  135], 50.00th=[  143], 60.00th=[  151],
     | 70.00th=[  163], 80.00th=[  183], 90.00th=[  217], 95.00th=[  262],
     | 99.00th=[  374], 99.50th=[  458], 99.90th=[61696], 99.95th=[109056],
     | 99.99th=[246784]
    lat (usec) : 50=0.01%, 100=0.09%, 250=93.93%, 500=5.55%, 750=0.06%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.03%, 4=0.01%, 10=0.01%, 20=0.08%, 50=0.11%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.69%, sys=19.74%, ctx=9908053, 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=19641135/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=1531: Sat Jul 29 03:59:03 2017
  read : io=74239MB, bw=84468KB/s, iops=21116, runt=900001msec
    slat (usec): min=0, max=317, avg= 6.86, stdev= 3.89
    clat (usec): min=24, max=1537.3K, avg=369.35, stdev=5950.92
     lat (usec): min=71, max=1537.3K, avg=376.68, stdev=5950.98
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  109], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  126], 40.00th=[  131], 50.00th=[  137], 60.00th=[  145],
     | 70.00th=[  157], 80.00th=[  173], 90.00th=[  207], 95.00th=[  247],
     | 99.00th=[  350], 99.50th=[  434], 99.90th=[66048], 99.95th=[116224],
     | 99.99th=[264192]
    lat (usec) : 50=0.01%, 100=0.16%, 250=95.11%, 500=4.32%, 750=0.04%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.71%, sys=19.66%, ctx=9087432, 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=19005271/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=150963MB, aggrb=171761KB/s, minb=84467KB/s, maxb=87293KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=38629806/29, merge=0/0, ticks=13959752/3564, in_queue=13980884, util=100.00%, aggrios=12904005/192734, aggrmerge=0/0, aggrticks=5435258/41146, aggrin_queue=5481312, aggrutil=71.34%
    dm-1: ios=57/512619, merge=0/0, ticks=4/65252, in_queue=65272, util=4.40%, aggrios=38515218/559828, aggrmerge=0/17125, aggrticks=5837752/75716, aggrin_queue=5921004, aggrutil=73.26%
  xvdc: ios=38515218/559828, merge=0/17125, ticks=5837752/75716, in_queue=5921004, util=73.26%
  dm-0: ios=38515161/64478, merge=0/0, ticks=5828092/12596, in_queue=5855388, util=71.34%
    dm-3: ios=196799/1107, merge=0/0, ticks=10477680/45592, in_queue=10523276, util=65.98%, aggrios=196799/1100, aggrmerge=0/7, aggrticks=10477632/43520, aggrin_queue=10521220, aggrutil=65.98%
  xvdd: ios=196799/1100, merge=0/7, ticks=10477632/43520, in_queue=10521220, util=65.98%

4.12.0-rc2+6ce478291137 (2017-05-26 10:51:18 -0700) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc2+6ce478291137 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] [398.7MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1324: Sat Jul 29 05:18:27 2017
  read : io=181395MB, bw=206387KB/s, iops=51596, runt=900001msec
    slat (usec): min=0, max=3628, avg= 6.85, stdev= 3.18
    clat (usec): min=31, max=650283, avg=145.71, stdev=401.45
     lat (usec): min=70, max=650322, avg=153.04, stdev=401.53
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 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=[  201],
     | 99.00th=[  266], 99.50th=[  302], 99.90th=[  430], 99.95th=[  502],
     | 99.99th=[ 1704]
    lat (usec) : 50=0.01%, 100=0.17%, 250=98.42%, 500=1.36%, 750=0.02%
    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%
  cpu          : usr=15.23%, sys=53.43%, ctx=19704592, 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=46437113/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=1325: Sat Jul 29 05:18:27 2017
  read : io=163235MB, bw=185725KB/s, iops=46431, runt=900001msec
    slat (usec): min=0, max=7249, avg= 7.00, stdev= 3.64
    clat (usec): min=29, max=321686, avg=162.76, stdev=759.82
     lat (usec): min=69, max=321717, avg=170.23, stdev=759.98
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  112], 10.00th=[  117], 20.00th=[  124],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  141], 60.00th=[  147],
     | 70.00th=[  157], 80.00th=[  173], 90.00th=[  203], 95.00th=[  243],
     | 99.00th=[  330], 99.50th=[  370], 99.90th=[  474], 99.95th=[  716],
     | 99.99th=[32128]
    lat (usec) : 50=0.01%, 100=0.12%, 250=95.44%, 500=4.36%, 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%, 500=0.01%
  cpu          : usr=13.56%, sys=49.51%, ctx=18629816, 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=41788282/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=344630MB, aggrb=392112KB/s, minb=185725KB/s, maxb=206386KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=88203561/28, merge=0/0, ticks=13332148/1696, in_queue=13367996, util=100.00%, aggrios=29431008/44535, aggrmerge=0/0, aggrticks=4467504/392230, aggrin_queue=4869529, aggrutil=100.00%
    dm-1: ios=13/65959, merge=0/0, ticks=4/11628, in_queue=11636, util=0.98%, aggrios=88262702/62581, aggrmerge=0/10717, aggrticks=12756980/12036, aggrin_queue=12776352, aggrutil=100.00%
  xvdc: ios=88262702/62581, merge=0/10717, ticks=12756980/12036, in_queue=12776352, util=100.00%
  dm-0: ios=88262689/9237, merge=0/0, ticks=12731748/1756, in_queue=12762868, util=100.00%
    dm-3: ios=30323/58410, merge=0/0, ticks=670760/1163308, in_queue=1834084, util=20.15%, aggrios=30323/58407, aggrmerge=0/3, aggrticks=670772/1159656, aggrin_queue=1830424, aggrutil=20.15%
  xvdd: ios=30323/58407, merge=0/3, ticks=670772/1159656, in_queue=1830424, util=20.15%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc2+6ce478291137 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] [364.8MB/0KB/0KB /s] [93.4K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1722: Sat Jul 29 05:41:43 2017
  read : io=74359MB, bw=84603KB/s, iops=21150, runt=900001msec
    slat (usec): min=0, max=2436, avg= 6.76, stdev= 3.33
    clat (usec): min=37, max=1305.6K, avg=369.04, stdev=5594.01
     lat (usec): min=68, max=1305.9K, avg=376.26, stdev=5594.50
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  109], 10.00th=[  113], 20.00th=[  120],
     | 30.00th=[  124], 40.00th=[  129], 50.00th=[  135], 60.00th=[  143],
     | 70.00th=[  155], 80.00th=[  179], 90.00th=[  258], 95.00th=[  346],
     | 99.00th=[  532], 99.50th=[  636], 99.90th=[63232], 99.95th=[110080],
     | 99.99th=[250880]
    lat (usec) : 50=0.01%, 100=0.17%, 250=89.28%, 500=9.28%, 750=0.88%
    lat (usec) : 1000=0.03%
    lat (msec) : 2=0.03%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.42%, sys=22.97%, ctx=10466417, 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=19035803/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=1723: Sat Jul 29 05:41:43 2017
  read : io=75299MB, bw=85674KB/s, iops=21418, runt=900001msec
    slat (usec): min=0, max=2420, avg= 6.72, stdev= 3.30
    clat (usec): min=32, max=1379.2K, avg=364.38, stdev=5736.94
     lat (usec): min=71, max=1379.2K, avg=371.55, stdev=5737.35
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  108], 10.00th=[  111], 20.00th=[  117],
     | 30.00th=[  122], 40.00th=[  127], 50.00th=[  133], 60.00th=[  141],
     | 70.00th=[  149], 80.00th=[  167], 90.00th=[  205], 95.00th=[  274],
     | 99.00th=[  490], 99.50th=[  612], 99.90th=[64768], 99.95th=[113152],
     | 99.99th=[259072]
    lat (usec) : 50=0.01%, 100=0.27%, 250=93.50%, 500=5.31%, 750=0.54%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.67%, sys=22.54%, ctx=10228527, 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=19276639/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=149658MB, aggrb=170277KB/s, minb=84603KB/s, maxb=85673KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=38294873/29, merge=0/0, ticks=13980376/4156, in_queue=13996968, util=100.00%, aggrios=12792699/192601, aggrmerge=0/0, aggrticks=5453128/37806, aggrin_queue=5494990, aggrutil=70.72%
    dm-1: ios=86/512203, merge=0/0, ticks=16/61356, in_queue=61388, util=4.27%, aggrios=38180502/560167, aggrmerge=1/16429, aggrticks=5907852/71764, aggrin_queue=5984152, aggrutil=72.60%
  xvdc: ios=38180502/560167, merge=1/16429, ticks=5907852/71764, in_queue=5984152, util=72.60%
  dm-0: ios=38180417/64538, merge=0/0, ticks=5896096/12280, in_queue=5920524, util=70.72%
    dm-3: ios=197595/1063, merge=0/0, ticks=10463272/39784, in_queue=10503060, util=65.39%, aggrios=197595/1056, aggrmerge=0/7, aggrticks=10463272/36948, aggrin_queue=10500280, aggrutil=65.39%
  xvdd: ios=197595/1056, merge=0/7, ticks=10463272/36948, in_queue=10500280, util=65.39%

4.12.0-rc1+331da109ec20 (2017-05-20 08:44:22 -0700) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+331da109ec20 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] [378.6MB/0KB/0KB /s] [96.1K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1342: Sat Jul 29 06:54:00 2017
  read : io=168144MB, bw=191310KB/s, iops=47827, runt=900001msec
    slat (usec): min=2, max=2850, avg= 6.93, stdev= 2.60
    clat (usec): min=39, max=1150.2K, avg=157.80, stdev=403.97
     lat (usec): min=70, max=1150.2K, avg=165.21, stdev=404.00
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  116], 20.00th=[  124],
     | 30.00th=[  131], 40.00th=[  137], 50.00th=[  145], 60.00th=[  153],
     | 70.00th=[  165], 80.00th=[  181], 90.00th=[  211], 95.00th=[  247],
     | 99.00th=[  330], 99.50th=[  370], 99.90th=[  466], 99.95th=[  532],
     | 99.99th=[ 1336]
    lat (usec) : 50=0.01%, 100=0.08%, 250=95.27%, 500=4.58%, 750=0.04%
    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=12.05%, sys=45.56%, ctx=19112237, 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=43044758/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=1343: Sat Jul 29 06:54:00 2017
  read : io=162387MB, bw=184760KB/s, iops=46190, runt=900001msec
    slat (usec): min=2, max=3771, avg= 6.95, stdev= 2.70
    clat (usec): min=18, max=528413, avg=163.71, stdev=689.58
     lat (usec): min=70, max=528456, avg=171.14, stdev=689.73
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  115], 20.00th=[  122],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  143], 60.00th=[  151],
     | 70.00th=[  163], 80.00th=[  181], 90.00th=[  211], 95.00th=[  247],
     | 99.00th=[  334], 99.50th=[  374], 99.90th=[  482], 99.95th=[  708],
     | 99.99th=[27520]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.11%, 250=95.14%, 500=4.67%
    lat (usec) : 750=0.04%, 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%
  cpu          : usr=12.07%, sys=43.77%, ctx=18853321, 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=41571072/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=330531MB, aggrb=376069KB/s, minb=184760KB/s, maxb=191309KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=84604087/28, merge=0/0, ticks=13465432/868, in_queue=13500164, util=100.00%, aggrios=28227541/40723, aggrmerge=0/0, aggrticks=4500645/520276, aggrin_queue=5032592, aggrutil=100.00%
    dm-1: ios=25/55370, merge=0/0, ticks=4/10480, in_queue=10484, util=0.88%, aggrios=84654863/53148, aggrmerge=27/9173, aggrticks=12992604/11056, aggrin_queue=13010688, aggrutil=100.00%
  xvdc: ios=84654863/53148, merge=27/9173, ticks=12992604/11056, in_queue=13010688, util=100.00%
  dm-0: ios=84654865/7809, merge=0/0, ticks=12987816/1676, in_queue=13024444, util=100.00%
    dm-3: ios=27734/58990, merge=0/0, ticks=514116/1548672, in_queue=2062848, util=22.31%, aggrios=27734/58961, aggrmerge=0/29, aggrticks=514100/1541080, aggrin_queue=2055176, aggrutil=22.31%
  xvdd: ios=27734/58961, merge=0/29, ticks=514100/1541080, in_queue=2055176, util=22.31%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+331da109ec20 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] [409.7MB/0KB/0KB /s] [105K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1729: Sat Jul 29 07:10:43 2017
  read : io=84440MB, bw=96074KB/s, iops=24018, runt=900001msec
    slat (usec): min=2, max=2584, avg= 6.82, stdev= 2.79
    clat (usec): min=16, max=1503.2K, avg=323.80, stdev=5298.35
     lat (usec): min=67, max=1503.2K, avg=331.09, stdev=5298.79
    clat percentiles (usec):
     |  1.00th=[   79],  5.00th=[   98], 10.00th=[  107], 20.00th=[  115],
     | 30.00th=[  122], 40.00th=[  127], 50.00th=[  135], 60.00th=[  141],
     | 70.00th=[  151], 80.00th=[  165], 90.00th=[  189], 95.00th=[  211],
     | 99.00th=[  282], 99.50th=[  366], 99.90th=[56064], 99.95th=[100864],
     | 99.99th=[238592]
    lat (usec) : 20=0.01%, 50=0.01%, 100=5.36%, 250=92.78%, 500=1.51%
    lat (usec) : 750=0.03%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.10%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.09%, sys=22.54%, ctx=10504259, 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=21616707/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=1730: Sat Jul 29 07:10:43 2017
  read : io=80128MB, bw=91168KB/s, iops=22791, runt=900001msec
    slat (usec): min=2, max=2258, avg= 6.89, stdev= 2.81
    clat (usec): min=21, max=1497.9K, avg=341.59, stdev=5610.12
     lat (usec): min=66, max=1497.9K, avg=348.97, stdev=5610.53
    clat percentiles (usec):
     |  1.00th=[   76],  5.00th=[   89], 10.00th=[  104], 20.00th=[  113],
     | 30.00th=[  121], 40.00th=[  127], 50.00th=[  133], 60.00th=[  141],
     | 70.00th=[  151], 80.00th=[  167], 90.00th=[  191], 95.00th=[  219],
     | 99.00th=[  314], 99.50th=[  394], 99.90th=[60672], 99.95th=[108032],
     | 99.99th=[252928]
    lat (usec) : 50=0.01%, 100=8.41%, 250=88.94%, 500=2.27%, 750=0.03%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.90%, sys=21.52%, ctx=9740291, 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=20512763/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=164568MB, aggrb=187241KB/s, minb=91167KB/s, maxb=96074KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=42117663/29, merge=0/0, ticks=13957468/4044, in_queue=13976576, util=100.00%, aggrios=14065022/191669, aggrmerge=0/0, aggrticks=5437961/43466, aggrin_queue=5485902, aggrutil=71.18%
    dm-1: ios=23/509401, merge=0/0, ticks=4/64012, in_queue=64032, util=4.37%, aggrios=41998935/556367, aggrmerge=0/16995, aggrticks=5877544/74016, aggrin_queue=5952992, aggrutil=73.08%
  xvdc: ios=41998935/556367, merge=0/16995, ticks=5877544/74016, in_queue=5952992, util=73.08%
  dm-0: ios=41998912/64099, merge=0/0, ticks=5872440/12180, in_queue=5897884, util=71.18%
    dm-3: ios=196133/1507, merge=0/0, ticks=10441440/54208, in_queue=10495792, util=65.28%, aggrios=196133/1501, aggrmerge=0/6, aggrticks=10441400/51888, aggrin_queue=10493276, aggrutil=65.28%
  xvdd: ios=196133/1501, merge=0/6, ticks=10441400/51888, in_queue=10493276, util=65.28%

4.12.0-rc1+d51aff16e821 (2017-05-20 06:00:49 +1000) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+d51aff16e821 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] [406.3MB/0KB/0KB /s] [104K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1248: Sat Jul 29 08:51:19 2017
  read : io=177645MB, bw=202121KB/s, iops=50530, runt=900001msec
    slat (usec): min=0, max=3003, avg= 7.12, stdev= 3.03
    clat (usec): min=39, max=971679, avg=148.57, stdev=681.72
     lat (usec): min=70, max=971686, avg=156.15, stdev=681.79
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  110], 10.00th=[  115], 20.00th=[  122],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  137], 60.00th=[  145],
     | 70.00th=[  151], 80.00th=[  163], 90.00th=[  181], 95.00th=[  201],
     | 99.00th=[  262], 99.50th=[  302], 99.90th=[  438], 99.95th=[  556],
     | 99.99th=[ 7264]
    lat (usec) : 50=0.01%, 100=0.11%, 250=98.53%, 500=1.30%, 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%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=15.07%, sys=52.23%, ctx=18395569, 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=45477192/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=1249: Sat Jul 29 08:51:19 2017
  read : io=169585MB, bw=192950KB/s, iops=48237, runt=900001msec
    slat (usec): min=0, max=2529, avg= 7.21, stdev= 3.13
    clat (usec): min=27, max=1731.8K, avg=156.00, stdev=919.90
     lat (usec): min=67, max=1731.8K, avg=163.66, stdev=920.02
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  116], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  153], 80.00th=[  165], 90.00th=[  185], 95.00th=[  205],
     | 99.00th=[  266], 99.50th=[  302], 99.90th=[  450], 99.95th=[  724],
     | 99.99th=[31104]
    lat (usec) : 50=0.01%, 100=0.19%, 250=98.36%, 500=1.38%, 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%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=14.06%, sys=50.57%, ctx=17854020, 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=43413691/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=347230MB, aggrb=395070KB/s, minb=192949KB/s, maxb=202120KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=88868766/28, merge=0/0, ticks=13255048/544, in_queue=13291156, util=100.00%, aggrios=29652308/43870, aggrmerge=0/0, aggrticks=4437944/678066, aggrin_queue=5124804, aggrutil=100.00%
    dm-1: ios=40/65580, merge=0/0, ticks=8/11168, in_queue=11184, util=0.96%, aggrios=88925731/62252, aggrmerge=5/10546, aggrticks=12610900/11908, aggrin_queue=12628964, aggrutil=100.00%
  xvdc: ios=88925731/62252, merge=5/10546, ticks=12610900/11908, in_queue=12628964, util=100.00%
  dm-0: ios=88925696/9160, merge=0/0, ticks=12587208/1880, in_queue=12615460, util=100.00%
    dm-3: ios=31188/56871, merge=0/0, ticks=726616/2021152, in_queue=2747768, util=27.31%, aggrios=31188/56865, aggrmerge=0/6, aggrticks=726608/2002592, aggrin_queue=2729192, aggrutil=27.32%
  xvdd: ios=31188/56865, merge=0/6, ticks=726608/2002592, in_queue=2729192, util=27.32%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+d51aff16e821 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] [384.3MB/0KB/0KB /s] [98.4K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1535: Sat Jul 29 09:10:07 2017
  read : io=81142MB, bw=92322KB/s, iops=23080, runt=900001msec
    slat (usec): min=0, max=2500, avg= 6.89, stdev= 3.06
    clat (usec): min=27, max=1250.7K, avg=337.19, stdev=5337.52
     lat (usec): min=66, max=1250.8K, avg=344.53, stdev=5338.02
    clat percentiles (usec):
     |  1.00th=[   89],  5.00th=[  107], 10.00th=[  110], 20.00th=[  118],
     | 30.00th=[  123], 40.00th=[  129], 50.00th=[  135], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  171], 90.00th=[  203], 95.00th=[  245],
     | 99.00th=[  358], 99.50th=[  434], 99.90th=[57600], 99.95th=[103936],
     | 99.99th=[240640]
    lat (usec) : 50=0.01%, 100=1.73%, 250=93.69%, 500=4.18%, 750=0.04%
    lat (usec) : 1000=0.02%
    lat (msec) : 2=0.03%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.95%, sys=23.93%, ctx=10312344, 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=20772473/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=1536: Sat Jul 29 09:10:07 2017
  read : io=73428MB, bw=83544KB/s, iops=20886, runt=900001msec
    slat (usec): min=0, max=1453, avg= 6.96, stdev= 2.98
    clat (usec): min=15, max=1524.7K, avg=373.51, stdev=6231.54
     lat (usec): min=67, max=1524.7K, avg=380.92, stdev=6231.92
    clat percentiles (usec):
     |  1.00th=[   90],  5.00th=[  107], 10.00th=[  112], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  157], 80.00th=[  173], 90.00th=[  203], 95.00th=[  241],
     | 99.00th=[  350], 99.50th=[  434], 99.90th=[66048], 99.95th=[117248],
     | 99.99th=[276480]
    lat (usec) : 20=0.01%, 50=0.01%, 100=1.63%, 250=94.04%, 500=3.91%
    lat (usec) : 750=0.04%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.40%, sys=21.56%, ctx=9325698, 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=18797466/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=154570MB, aggrb=175866KB/s, minb=83544KB/s, maxb=92321KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=39560967/29, merge=0/0, ticks=13949328/1084, in_queue=13964452, util=100.00%, aggrios=13211863/192921, aggrmerge=0/0, aggrticks=5416640/38728, aggrin_queue=5458597, aggrutil=70.47%
    dm-1: ios=47/513127, merge=0/0, ticks=0/64104, in_queue=64112, util=4.32%, aggrios=39438165/560401, aggrmerge=0/17140, aggrticks=5784740/74192, aggrin_queue=5861736, aggrutil=72.34%
  xvdc: ios=39438165/560401, merge=0/17140, ticks=5784740/74192, in_queue=5861736, util=72.34%
  dm-0: ios=39438118/64534, merge=0/0, ticks=5774760/12144, in_queue=5796584, util=70.47%
    dm-3: ios=197426/1102, merge=0/0, ticks=10475160/39936, in_queue=10515096, util=66.94%, aggrios=197426/1101, aggrmerge=0/1, aggrticks=10475168/39392, aggrin_queue=10514556, aggrutil=66.94%
  xvdd: ios=197426/1101, merge=0/1, ticks=10475168/39392, in_queue=10514556, util=66.94%

4.12.0-rc1+a58a260fd96b (2017-05-18 11:21:10 -0700) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+a58a260fd96b 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] [403.7MB/0KB/0KB /s] [103K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1469: Sat Jul 29 10:38:52 2017
  read : io=178006MB, bw=202531KB/s, iops=50632, runt=900001msec
    slat (usec): min=0, max=6867, avg= 7.12, stdev= 3.46
    clat (usec): min=32, max=1286.2K, avg=148.28, stdev=540.32
     lat (usec): min=67, max=1286.2K, avg=155.87, stdev=540.36
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  116], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  153], 80.00th=[  165], 90.00th=[  185], 95.00th=[  207],
     | 99.00th=[  270], 99.50th=[  306], 99.90th=[  430], 99.95th=[  494],
     | 99.99th=[ 1352]
    lat (usec) : 50=0.01%, 100=0.12%, 250=98.28%, 500=1.55%, 750=0.02%
    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=15.17%, sys=54.06%, ctx=18845932, 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=45569414/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=1470: Sat Jul 29 10:38:52 2017
  read : io=173743MB, bw=197681KB/s, iops=49420, runt=900001msec
    slat (usec): min=0, max=3071, avg= 7.07, stdev= 3.36
    clat (usec): min=19, max=1304.0K, avg=152.23, stdev=680.26
     lat (usec): min=69, max=1304.2K, avg=159.77, stdev=680.38
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  115], 20.00th=[  122],
     | 30.00th=[  127], 40.00th=[  133], 50.00th=[  137], 60.00th=[  143],
     | 70.00th=[  153], 80.00th=[  163], 90.00th=[  185], 95.00th=[  205],
     | 99.00th=[  266], 99.50th=[  302], 99.90th=[  438], 99.95th=[  588],
     | 99.99th=[22912]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.17%, 250=98.29%, 500=1.48%
    lat (usec) : 750=0.02%, 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=15.16%, sys=52.26%, ctx=18799543, 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=44478196/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=351748MB, aggrb=400211KB/s, minb=197680KB/s, maxb=202530KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=90047147/28, merge=0/0, ticks=13242192/1464, in_queue=13298304, util=100.00%, aggrios=30038236/40110, aggrmerge=0/0, aggrticks=4422056/701994, aggrin_queue=5135569, aggrutil=100.00%
    dm-1: ios=45/53246, merge=0/0, ticks=8/9560, in_queue=9572, util=0.81%, aggrios=90087618/50539, aggrmerge=21/8883, aggrticks=12812936/9916, aggrin_queue=12830368, aggrutil=100.00%
  xvdc: ios=90087618/50539, merge=21/8883, ticks=12812936/9916, in_queue=12830368, util=100.00%
  dm-0: ios=90087594/7476, merge=0/0, ticks=12789572/1472, in_queue=12825580, util=100.00%
    dm-3: ios=27070/59608, merge=0/0, ticks=476588/2094952, in_queue=2571556, util=26.41%, aggrios=27070/59583, aggrmerge=0/25, aggrticks=476596/2078296, aggrin_queue=2554892, aggrutil=26.41%
  xvdd: ios=27070/59583, merge=0/25, ticks=476596/2078296, in_queue=2554892, util=26.41%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+a58a260fd96b 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] [369.8MB/0KB/0KB /s] [94.7K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1970: Sat Jul 29 11:17:21 2017
  read : io=77095MB, bw=87717KB/s, iops=21929, runt=900001msec
    slat (usec): min=0, max=2471, avg= 6.97, stdev= 3.30
    clat (usec): min=4, max=1523.7K, avg=355.35, stdev=5578.26
     lat (usec): min=64, max=1523.7K, avg=362.77, stdev=5578.75
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  108], 10.00th=[  111], 20.00th=[  120],
     | 30.00th=[  125], 40.00th=[  133], 50.00th=[  143], 60.00th=[  153],
     | 70.00th=[  167], 80.00th=[  185], 90.00th=[  213], 95.00th=[  247],
     | 99.00th=[  346], 99.50th=[  426], 99.90th=[61184], 99.95th=[108032],
     | 99.99th=[248832]
    lat (usec) : 10=0.01%, 50=0.01%, 100=0.83%, 250=94.43%, 500=4.33%
    lat (usec) : 750=0.04%, 1000=0.02%
    lat (msec) : 2=0.03%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.11%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=6.49%, sys=24.26%, ctx=10152879, 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=19736266/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=1971: Sat Jul 29 11:17:21 2017
  read : io=70627MB, bw=80357KB/s, iops=20089, runt=900001msec
    slat (usec): min=0, max=1736, avg= 6.99, stdev= 3.37
    clat (usec): min=17, max=1334.4K, avg=388.69, stdev=6080.75
     lat (usec): min=62, max=1334.4K, avg=396.14, stdev=6081.19
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  108], 10.00th=[  114], 20.00th=[  122],
     | 30.00th=[  129], 40.00th=[  137], 50.00th=[  147], 60.00th=[  159],
     | 70.00th=[  173], 80.00th=[  191], 90.00th=[  225], 95.00th=[  262],
     | 99.00th=[  366], 99.50th=[  454], 99.90th=[69120], 99.95th=[119296],
     | 99.99th=[272384]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.76%, 250=92.96%, 500=5.83%
    lat (usec) : 750=0.04%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.95%, sys=22.37%, ctx=9542001, 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=18080386/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=147721MB, aggrb=168073KB/s, minb=80357KB/s, maxb=87716KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=37811927/29, merge=0/0, ticks=13950924/2420, in_queue=13976400, util=100.00%, aggrios=12627432/192884, aggrmerge=0/0, aggrticks=5423964/40908, aggrin_queue=5469672, aggrutil=70.48%
    dm-1: ios=41/513019, merge=0/0, ticks=8/61768, in_queue=61776, util=4.19%, aggrios=37684593/560591, aggrmerge=0/16798, aggrticks=5810780/72380, aggrin_queue=5885452, aggrutil=72.25%
  xvdc: ios=37684593/560591, merge=0/16798, ticks=5810780/72380, in_queue=5885452, util=72.25%
  dm-0: ios=37684552/64512, merge=0/0, ticks=5808316/12596, in_queue=5835296, util=70.48%
    dm-3: ios=197703/1122, merge=0/0, ticks=10463568/48360, in_queue=10511944, util=65.97%, aggrios=197703/1119, aggrmerge=0/3, aggrticks=10463584/46584, aggrin_queue=10510148, aggrutil=65.97%
  xvdd: ios=197703/1119, merge=0/3, ticks=10463584/46584, in_queue=10510148, util=65.97%

4.12.0-rc1+243bfd2c052d (2017-05-17 14:13:44 -0700) ^

just 2,130 and 738 average IOPS on the run against a full cache means this was marked broken.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+243bfd2c052d 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] [223.5MB/0KB/0KB /s] [57.2K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1033: Sat Jul 29 13:21:34 2017
  read : io=136455MB, bw=155242KB/s, iops=38810, runt=900078msec
    slat (usec): min=0, max=26662, avg= 4.82, stdev= 6.30
    clat (usec): min=21, max=880182, avg=199.68, stdev=2322.99
     lat (usec): min=70, max=880190, avg=204.84, stdev=2323.29
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  106], 10.00th=[  109], 20.00th=[  114],
     | 30.00th=[  119], 40.00th=[  122], 50.00th=[  126], 60.00th=[  131],
     | 70.00th=[  137], 80.00th=[  149], 90.00th=[  189], 95.00th=[  245],
     | 99.00th=[  382], 99.50th=[  446], 99.90th=[17792], 99.95th=[36608],
     | 99.99th=[108032]
    lat (usec) : 50=0.01%, 100=0.24%, 250=95.07%, 500=4.31%, 750=0.09%
    lat (usec) : 1000=0.05%
    lat (msec) : 2=0.11%, 4=0.01%, 10=0.01%, 20=0.03%, 50=0.06%
    lat (msec) : 100=0.02%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=7.38%, sys=26.41%, ctx=19119794, 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=34932423/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=1034: Sat Jul 29 13:21:34 2017
  read : io=42407MB, bw=48247KB/s, iops=12061, runt=900066msec
    slat (usec): min=0, max=236, avg= 7.12, stdev= 4.37
    clat (usec): min=2, max=1038.3K, avg=653.49, stdev=6208.11
     lat (usec): min=71, max=1038.3K, avg=661.11, stdev=6209.00
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  104], 10.00th=[  106], 20.00th=[  109],
     | 30.00th=[  113], 40.00th=[  117], 50.00th=[  120], 60.00th=[  124],
     | 70.00th=[  129], 80.00th=[  137], 90.00th=[  163], 95.00th=[  237],
     | 99.00th=[16512], 99.50th=[35072], 99.90th=[93696], 99.95th=[123392],
     | 99.99th=[195584]
    lat (usec) : 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.64%
    lat (usec) : 250=94.91%, 500=2.76%, 750=0.11%, 1000=0.07%
    lat (msec) : 2=0.14%, 4=0.02%, 10=0.10%, 20=0.37%, 50=0.56%
    lat (msec) : 100=0.23%, 250=0.08%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=3.63%, sys=12.48%, ctx=9079177, 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=10856295/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=178862MB, aggrb=203487KB/s, minb=48246KB/s, maxb=155241KB/s, mint=900066msec, maxt=900078msec
 
Disk stats (read/write):
    dm-2: ios=45783724/28, merge=0/0, ticks=14086884/552, in_queue=14099888, util=100.00%, aggrios=15302554/317325, aggrmerge=0/0, aggrticks=5324778/75793, aggrin_queue=5403120, aggrutil=100.00%
    dm-1: ios=5/833005, merge=0/0, ticks=0/136424, in_queue=136468, util=10.74%, aggrios=45578059/918360, aggrmerge=965/23157, aggrticks=6367068/155120, aggrin_queue=6522812, aggrutil=100.00%
  xvdc: ios=45578059/918360, merge=965/23157, ticks=6367068/155120, in_queue=6522812, util=100.00%
  dm-0: ios=45579019/109294, merge=0/0, ticks=6367368/21496, in_queue=6396436, util=100.00%
    dm-3: ios=328639/9676, merge=0/0, ticks=9606968/69460, in_queue=9676456, util=100.00%, aggrios=328639/8639, aggrmerge=0/1037, aggrticks=9606840/46124, aggrin_queue=9652956, aggrutil=100.00%
  xvdd: ios=328639/8639, merge=0/1037, ticks=9606840/46124, in_queue=9652956, util=100.00%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+243bfd2c052d 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] [12052KB/0KB/0KB /s] [3013/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1455: Sat Jul 29 13:50:32 2017
  read : io=7490.4MB, bw=8521.4KB/s, iops=2130, runt=900105msec
    slat (usec): min=0, max=128, avg= 1.71, stdev= 4.39
    clat (usec): min=64, max=1526.2K, avg=3752.99, stdev=24771.48
     lat (usec): min=73, max=1526.2K, avg=3754.82, stdev=24772.16
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  106], 10.00th=[  111], 20.00th=[  115],
     | 30.00th=[  117], 40.00th=[  118], 50.00th=[  119], 60.00th=[  125],
     | 70.00th=[  131], 80.00th=[  133], 90.00th=[  171], 95.00th=[12736],
     | 99.00th=[101888], 99.50th=[160768], 99.90th=[333824], 99.95th=[428032],
     | 99.99th=[692224]
    lat (usec) : 100=0.26%, 250=93.35%, 500=0.50%, 750=0.07%, 1000=0.06%
    lat (msec) : 2=0.11%, 4=0.01%, 10=0.29%, 20=1.36%, 50=1.87%
    lat (msec) : 100=1.09%, 250=0.82%, 500=0.18%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.19%, sys=0.72%, ctx=1983309, 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=1917523/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=1456: Sat Jul 29 13:50:32 2017
  read : io=2596.8MB, bw=2953.6KB/s, iops=738, runt=900054msec
    slat (usec): min=0, max=154, avg= 3.92, stdev= 5.64
    clat (usec): min=66, max=1527.1K, avg=10829.22, stdev=43048.40
     lat (usec): min=72, max=1527.1K, avg=10833.40, stdev=43048.88
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  105], 10.00th=[  106], 20.00th=[  111],
     | 30.00th=[  116], 40.00th=[  118], 50.00th=[  120], 60.00th=[  131],
     | 70.00th=[  139], 80.00th=[  173], 90.00th=[26240], 95.00th=[63232],
     | 99.00th=[201728], 99.50th=[280576], 99.90th=[501760], 99.95th=[626688],
     | 99.99th=[937984]
    lat (usec) : 100=0.47%, 250=83.17%, 500=0.37%, 750=0.09%, 1000=0.07%
    lat (msec) : 2=0.14%, 4=0.02%, 10=0.60%, 20=3.44%, 50=5.41%
    lat (msec) : 100=3.19%, 250=2.37%, 500=0.55%, 750=0.08%, 1000=0.02%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.14%, sys=0.48%, ctx=670686, 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=664578/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=10086MB, aggrb=11474KB/s, minb=2953KB/s, maxb=8521KB/s, mint=900054msec, maxt=900105msec
 
Disk stats (read/write):
    dm-2: ios=2581744/29, merge=0/0, ticks=14383904/4548, in_queue=14390016, util=100.00%, aggrios=896781/322000, aggrmerge=0/0, aggrticks=6180766/42330, aggrin_queue=6223142, aggrutil=100.00%
    dm-1: ios=5/857732, merge=0/0, ticks=0/101316, in_queue=101320, util=6.42%, aggrios=2363753/933247, aggrmerge=0/32409, aggrticks=294652/118376, aggrin_queue=412980, aggrutil=35.73%
  xvdc: ios=2363753/933247, merge=0/32409, ticks=294652/118376, in_queue=412980, util=35.73%
  dm-0: ios=2363748/108251, merge=0/0, ticks=294752/21128, in_queue=315924, util=31.04%
    dm-3: ios=326590/17, merge=0/0, ticks=18247548/4548, in_queue=18252184, util=100.00%, aggrios=326590/10, aggrmerge=0/7, aggrticks=18247532/2576, aggrin_queue=18250100, aggrutil=100.00%
  xvdd: ios=326590/10, merge=0/7, ticks=18247532/2576, in_queue=18250100, util=100.00%

4.12.0-rc1+f98e0eb68008 (2017-05-15 15:09:53 -0400) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+f98e0eb68008 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] [389.1MB/0KB/0KB /s] [99.9K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1473: Sat Jul 29 15:01:22 2017
  read : io=175480MB, bw=199657KB/s, iops=49914, runt=900001msec
    slat (usec): min=0, max=2865, avg= 7.12, stdev= 3.47
    clat (usec): min=32, max=272750, avg=150.49, stdev=61.07
     lat (usec): min=82, max=272765, avg=158.13, stdev=61.08
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  111], 10.00th=[  116], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  133], 50.00th=[  139], 60.00th=[  145],
     | 70.00th=[  155], 80.00th=[  169], 90.00th=[  197], 95.00th=[  235],
     | 99.00th=[  326], 99.50th=[  362], 99.90th=[  454], 99.95th=[  502],
     | 99.99th=[ 1020]
    lat (usec) : 50=0.01%, 100=0.09%, 250=95.99%, 500=3.87%, 750=0.03%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 500=0.01%
  cpu          : usr=13.53%, sys=47.87%, ctx=18357918, 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=44922870/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=1474: Sat Jul 29 15:01:22 2017
  read : io=166695MB, bw=189662KB/s, iops=47415, runt=900001msec
    slat (usec): min=0, max=7688, avg= 7.16, stdev= 3.64
    clat (usec): min=14, max=600437, avg=158.90, stdev=650.77
     lat (usec): min=69, max=600476, avg=166.58, stdev=650.92
    clat percentiles (usec):
     |  1.00th=[  106],  5.00th=[  113], 10.00th=[  118], 20.00th=[  124],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  141], 60.00th=[  147],
     | 70.00th=[  155], 80.00th=[  171], 90.00th=[  197], 95.00th=[  231],
     | 99.00th=[  318], 99.50th=[  350], 99.90th=[  454], 99.95th=[  564],
     | 99.99th=[24448]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.06%, 250=96.33%, 500=3.54%
    lat (usec) : 750=0.02%, 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%
  cpu          : usr=13.03%, sys=45.62%, ctx=17895059, 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=42673942/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=342175MB, aggrb=389318KB/s, minb=189661KB/s, maxb=199656KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=87581336/28, merge=0/0, ticks=13288760/1272, in_queue=13321684, util=100.00%, aggrios=29220805/38094, aggrmerge=0/0, aggrticks=4442181/395562, aggrin_queue=4846680, aggrutil=100.00%
    dm-1: ios=13/48662, merge=0/0, ticks=4/8880, in_queue=8892, util=0.76%, aggrios=87640393/44939, aggrmerge=1/9151, aggrticks=12922660/9064, aggrin_queue=12942364, aggrutil=100.00%
  xvdc: ios=87640393/44939, merge=1/9151, ticks=12922660/9064, in_queue=12942364, util=100.00%
  dm-0: ios=87640381/6972, merge=0/0, ticks=12891608/1372, in_queue=12919780, util=100.00%
    dm-3: ios=22021/58648, merge=0/0, ticks=434932/1176436, in_queue=1611368, util=17.77%, aggrios=22021/58631, aggrmerge=0/17, aggrticks=434920/1170812, aggrin_queue=1605732, aggrutil=17.77%
  xvdd: ios=22021/58631, merge=0/17, ticks=434920/1170812, in_queue=1605732, util=17.77%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+f98e0eb68008 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] [378.6MB/0KB/0KB /s] [96.8K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1827: Sat Jul 29 15:19:18 2017
  read : io=81213MB, bw=92402KB/s, iops=23100, runt=900001msec
    slat (usec): min=0, max=653, avg= 6.99, stdev= 3.51
    clat (usec): min=25, max=1352.2K, avg=336.83, stdev=5321.69
     lat (usec): min=72, max=1352.2K, avg=344.32, stdev=5322.11
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  108], 10.00th=[  112], 20.00th=[  119],
     | 30.00th=[  125], 40.00th=[  131], 50.00th=[  139], 60.00th=[  149],
     | 70.00th=[  159], 80.00th=[  175], 90.00th=[  201], 95.00th=[  229],
     | 99.00th=[  314], 99.50th=[  390], 99.90th=[56576], 99.95th=[101888],
     | 99.99th=[242688]
    lat (usec) : 50=0.01%, 100=0.13%, 250=96.71%, 500=2.78%, 750=0.03%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.96%, sys=21.63%, ctx=10178854, 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=20790563/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=1828: Sat Jul 29 15:19:18 2017
  read : io=73647MB, bw=83794KB/s, iops=20948, runt=900001msec
    slat (usec): min=0, max=2496, avg= 7.18, stdev= 3.62
    clat (usec): min=23, max=1510.2K, avg=372.08, stdev=6082.40
     lat (usec): min=72, max=1510.2K, avg=379.78, stdev=6082.74
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  114], 20.00th=[  122],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  143], 60.00th=[  151],
     | 70.00th=[  163], 80.00th=[  179], 90.00th=[  207], 95.00th=[  237],
     | 99.00th=[  330], 99.50th=[  414], 99.90th=[65280], 99.95th=[113152],
     | 99.99th=[272384]
    lat (usec) : 50=0.01%, 100=0.13%, 250=96.03%, 500=3.44%, 750=0.03%
    lat (usec) : 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.82%, sys=20.07%, ctx=9121390, 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=18853758/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=154861MB, aggrb=176196KB/s, minb=83794KB/s, maxb=92402KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=39629245/29, merge=0/0, ticks=13922184/2932, in_queue=13938180, util=100.00%, aggrios=13236641/192742, aggrmerge=0/0, aggrticks=5404900/39769, aggrin_queue=5447944, aggrutil=71.24%
    dm-1: ios=35/512628, merge=0/0, ticks=0/63156, in_queue=63168, util=4.26%, aggrios=39512858/560041, aggrmerge=1/16890, aggrticks=5866812/73188, aggrin_queue=5946060, aggrutil=73.11%
  xvdc: ios=39512858/560041, merge=1/16890, ticks=5866812/73188, in_queue=5946060, util=73.11%
  dm-0: ios=39512824/64453, merge=0/0, ticks=5858616/12180, in_queue=5880596, util=71.24%
    dm-3: ios=197065/1146, merge=0/0, ticks=10356084/43972, in_queue=10400068, util=65.55%, aggrios=197065/1143, aggrmerge=0/3, aggrticks=10356072/42172, aggrin_queue=10398236, aggrutil=65.55%
  xvdd: ios=197065/1143, merge=0/3, ticks=10356072/42172, in_queue=10398236, util=65.55%

4.12.0-rc1+701e03e4e180 (2017-05-14 21:54:33 -0400) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+701e03e4e180 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] [383.6MB/0KB/0KB /s] [98.2K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1488: Sun Jul 30 00:38:12 2017
  read : io=163416MB, bw=185931KB/s, iops=46482, runt=900001msec
    slat (usec): min=0, max=6338, avg= 6.90, stdev= 4.29
    clat (usec): min=2, max=423004, avg=162.74, stdev=659.06
     lat (usec): min=70, max=423007, avg=170.12, stdev=659.18
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  112], 10.00th=[  117], 20.00th=[  124],
     | 30.00th=[  131], 40.00th=[  137], 50.00th=[  143], 60.00th=[  153],
     | 70.00th=[  163], 80.00th=[  179], 90.00th=[  207], 95.00th=[  241],
     | 99.00th=[  326], 99.50th=[  362], 99.90th=[  490], 99.95th=[  828],
     | 99.99th=[23680]
    lat (usec) : 4=0.01%, 20=0.01%, 50=0.01%, 100=0.10%, 250=95.64%
    lat (usec) : 500=4.17%, 750=0.04%, 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%
  cpu          : usr=11.29%, sys=43.37%, ctx=18655951, 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=41834439/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=1489: Sun Jul 30 00:38:12 2017
  read : io=163729MB, bw=186287KB/s, iops=46571, runt=900001msec
    slat (usec): min=0, max=3379, avg= 6.91, stdev= 4.05
    clat (usec): min=1, max=647713, avg=162.39, stdev=1109.49
     lat (usec): min=71, max=647715, avg=169.78, stdev=1109.58
    clat percentiles (usec):
     |  1.00th=[  105],  5.00th=[  112], 10.00th=[  117], 20.00th=[  123],
     | 30.00th=[  129], 40.00th=[  135], 50.00th=[  141], 60.00th=[  149],
     | 70.00th=[  159], 80.00th=[  173], 90.00th=[  195], 95.00th=[  219],
     | 99.00th=[  286], 99.50th=[  322], 99.90th=[  462], 99.95th=[  764],
     | 99.99th=[36096]
    lat (usec) : 2=0.01%, 20=0.01%, 50=0.01%, 100=0.10%, 250=97.69%
    lat (usec) : 500=2.13%, 750=0.03%, 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%
  cpu          : usr=11.62%, sys=43.26%, ctx=18444169, 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=41914621/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=327145MB, aggrb=372217KB/s, minb=185930KB/s, maxb=186286KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=83732468/28, merge=0/0, ticks=13437692/4572, in_queue=13474260, util=100.00%, aggrios=27939916/52846, aggrmerge=0/0, aggrticks=4517696/389793, aggrin_queue=4918218, aggrutil=100.00%
    dm-1: ios=3/87822, merge=0/0, ticks=0/14672, in_queue=14672, util=1.21%, aggrios=83780322/91760, aggrmerge=1107/8163, aggrticks=12562052/16096, aggrin_queue=12583792, aggrutil=100.00%
  xvdc: ios=83780322/91760, merge=1107/8163, ticks=12562052/16096, in_queue=12583792, util=100.00%
  dm-0: ios=83781426/12436, merge=0/0, ticks=12554856/2392, in_queue=12589888, util=100.00%
    dm-3: ios=38320/58280, merge=0/0, ticks=998232/1152316, in_queue=2150096, util=21.10%, aggrios=38320/57106, aggrmerge=0/1182, aggrticks=998232/1128504, aggrin_queue=2126504, aggrutil=21.10%
  xvdd: ios=38320/57106, merge=0/1182, ticks=998232/1128504, in_queue=2126504, util=21.10%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+701e03e4e180 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] [396.7MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=4235: Sun Jul 30 00:57:53 2017
  read : io=83984MB, bw=95555KB/s, iops=23888, runt=900001msec
    slat (usec): min=0, max=2757, avg= 6.65, stdev= 4.15
    clat (usec): min=0, max=1331.1K, avg=325.84, stdev=5327.61
     lat (usec): min=70, max=1331.1K, avg=333.00, stdev=5327.93
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  108], 10.00th=[  113], 20.00th=[  118],
     | 30.00th=[  124], 40.00th=[  129], 50.00th=[  135], 60.00th=[  141],
     | 70.00th=[  149], 80.00th=[  161], 90.00th=[  183], 95.00th=[  205],
     | 99.00th=[  278], 99.50th=[  362], 99.90th=[56064], 99.95th=[100864],
     | 99.99th=[242688]
    lat (usec) : 2=0.01%, 20=0.01%, 50=0.01%, 100=0.14%, 250=98.20%
    lat (usec) : 500=1.30%, 750=0.02%, 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.07%, 50=0.10%
    lat (msec) : 100=0.06%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.85%, sys=21.52%, ctx=10254989, 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=21499909/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=4236: Sun Jul 30 00:57:53 2017
  read : io=75994MB, bw=86464KB/s, iops=21616, runt=900001msec
    slat (usec): min=0, max=3457, avg= 6.91, stdev= 4.10
    clat (usec): min=2, max=1517.1K, avg=360.70, stdev=5924.51
     lat (usec): min=72, max=1517.1K, avg=368.13, stdev=5924.81
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  110], 10.00th=[  114], 20.00th=[  121],
     | 30.00th=[  126], 40.00th=[  131], 50.00th=[  137], 60.00th=[  145],
     | 70.00th=[  153], 80.00th=[  169], 90.00th=[  195], 95.00th=[  227],
     | 99.00th=[  326], 99.50th=[  406], 99.90th=[64256], 99.95th=[114176],
     | 99.99th=[264192]
    lat (usec) : 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.11%
    lat (usec) : 250=96.53%, 500=2.96%, 750=0.03%, 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.07%, 50=0.11%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.46%, sys=20.26%, ctx=9368609, 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=19454516/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=159978MB, aggrb=182019KB/s, minb=86464KB/s, maxb=95555KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=40941858/29, merge=0/0, ticks=13939452/2924, in_queue=13957884, util=100.00%, aggrios=13673355/191614, aggrmerge=0/0, aggrticks=5425713/41914, aggrin_queue=5472632, aggrutil=70.78%
    dm-1: ios=72/509243, merge=0/0, ticks=12/62896, in_queue=62908, util=4.30%, aggrios=40823706/556590, aggrmerge=1/16815, aggrticks=5811880/73008, aggrin_queue=5889632, aggrutil=72.65%
  xvdc: ios=40823706/556590, merge=1/16815, ticks=5811880/73008, in_queue=5889632, util=72.65%
  dm-0: ios=40823635/64315, merge=0/0, ticks=5806500/12056, in_queue=5833472, util=70.78%
    dm-3: ios=196358/1284, merge=0/0, ticks=10470628/50792, in_queue=10521516, util=65.71%, aggrios=196358/1281, aggrmerge=0/3, aggrticks=10470612/48468, aggrin_queue=10519068, aggrutil=65.71%
  xvdd: ios=196358/1281, merge=0/3, ticks=10470612/48468, in_queue=10519068, util=65.71%

4.12.0-rc1+78c45607b909 (2017-05-14 21:54:32 -0400) ^

The first job running against a full cache managed 17,398 average IOPS which isn’t terrible, but the second job only managed 694 average IOPS. Although this is a lot better than the worst performance seen, it is far below the best so this must be considered broken.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+78c45607b909 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] [127.8MB/0KB/0KB /s] [32.8K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1633: Sun Jul 30 01:32:22 2017
  read : io=20052MB, bw=22814KB/s, iops=5703, runt=900027msec
    slat (usec): min=2, max=79803, avg= 7.19, stdev=36.71
    clat (usec): min=13, max=929368, avg=1392.96, stdev=9447.28
     lat (usec): min=72, max=929376, avg=1400.61, stdev=9448.72
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  105], 10.00th=[  108], 20.00th=[  114],
     | 30.00th=[  118], 40.00th=[  121], 50.00th=[  124], 60.00th=[  131],
     | 70.00th=[  143], 80.00th=[  175], 90.00th=[  247], 95.00th=[  378],
     | 99.00th=[39168], 99.50th=[61184], 99.90th=[124416], 99.95th=[158720],
     | 99.99th=[257024]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.37%, 250=89.87%, 500=5.63%
    lat (usec) : 750=0.28%, 1000=0.19%
    lat (msec) : 2=0.30%, 4=0.01%, 10=0.16%, 20=1.05%, 50=1.44%
    lat (msec) : 100=0.52%, 250=0.17%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=1.61%, sys=5.89%, ctx=4272767, 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=5133359/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=1634: Sun Jul 30 01:32:22 2017
  read : io=70562MB, bw=80281KB/s, iops=20070, runt=900023msec
    slat (usec): min=2, max=63808, avg= 6.52, stdev=17.03
    clat (usec): min=12, max=1526.4K, avg=389.81, stdev=4546.59
     lat (usec): min=69, max=1526.4K, avg=396.77, stdev=4547.95
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  106], 20.00th=[  108],
     | 30.00th=[  112], 40.00th=[  118], 50.00th=[  121], 60.00th=[  125],
     | 70.00th=[  135], 80.00th=[  159], 90.00th=[  227], 95.00th=[  286],
     | 99.00th=[  988], 99.50th=[16064], 99.90th=[59136], 99.95th=[84480],
     | 99.99th=[168960]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.34%, 250=92.06%, 500=6.20%
    lat (usec) : 750=0.23%, 1000=0.18%
    lat (msec) : 2=0.34%, 4=0.01%, 10=0.03%, 20=0.19%, 50=0.29%
    lat (msec) : 100=0.10%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=4.86%, sys=17.98%, ctx=12698034, 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=18063745/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=90614MB, aggrb=103095KB/s, minb=22814KB/s, maxb=80281KB/s, mint=900023msec, maxt=900027msec
 
Disk stats (read/write):
    dm-2: ios=23193142/28, merge=0/0, ticks=14243636/2712, in_queue=14251904, util=100.00%, aggrios=7849034/861075, aggrmerge=0/0, aggrticks=5211602/303989, aggrin_queue=5516568, aggrutil=99.10%
    dm-1: ios=1/2233198, merge=0/0, ticks=0/337548, in_queue=337612, util=25.48%, aggrios=22971489/2441741, aggrmerge=998/75445, aggrticks=3693756/390528, aggrin_queue=4083748, aggrutil=94.88%
  xvdc: ios=22971489/2441741, merge=998/75445, ticks=3693756/390528, in_queue=4083748, util=94.88%
  dm-0: ios=22972486/284707, merge=0/0, ticks=3711344/62548, in_queue=3776724, util=94.74%
    dm-3: ios=574615/65320, merge=0/0, ticks=11923464/511872, in_queue=12435368, util=99.10%, aggrios=574505/64312, aggrmerge=109/1008, aggrticks=11894448/464704, aggrin_queue=12359116, aggrutil=99.10%
  xvdd: ios=574505/64312, merge=109/1008, ticks=11894448/464704, in_queue=12359116, util=99.10%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+78c45607b909 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] [71928KB/0KB/0KB /s] [17.1K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=4136: Sun Jul 30 01:48:29 2017
  read : io=61171MB, bw=69594KB/s, iops=17398, runt=900076msec
    slat (usec): min=0, max=3387, avg= 6.22, stdev= 3.45
    clat (usec): min=1, max=1174.6K, avg=451.49, stdev=7201.13
     lat (usec): min=68, max=1174.6K, avg=458.13, stdev=7201.29
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  104], 10.00th=[  106], 20.00th=[  108],
     | 30.00th=[  110], 40.00th=[  116], 50.00th=[  120], 60.00th=[  121],
     | 70.00th=[  123], 80.00th=[  129], 90.00th=[  173], 95.00th=[  239],
     | 99.00th=[  548], 99.50th=[ 7008], 99.90th=[91648], 99.95th=[150528],
     | 99.99th=[313344]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=0.30%
    lat (usec) : 250=95.24%, 500=3.42%, 750=0.18%, 1000=0.15%
    lat (msec) : 2=0.19%, 4=0.01%, 10=0.04%, 20=0.12%, 50=0.17%
    lat (msec) : 100=0.09%, 250=0.07%, 500=0.02%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=3.99%, sys=15.44%, ctx=12579924, 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=15659896/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=4137: Sun Jul 30 01:48:29 2017
  read : io=2440.7MB, bw=2776.7KB/s, iops=694, runt=900089msec
    slat (usec): min=2, max=821, avg= 7.64, stdev= 2.96
    clat (usec): min=1, max=1511.6K, avg=11514.55, stdev=48644.41
     lat (usec): min=69, max=1511.7K, avg=11522.66, stdev=48644.81
    clat percentiles (usec):
     |  1.00th=[   99],  5.00th=[  104], 10.00th=[  106], 20.00th=[  112],
     | 30.00th=[  117], 40.00th=[  119], 50.00th=[  121], 60.00th=[  123],
     | 70.00th=[  126], 80.00th=[  159], 90.00th=[22656], 95.00th=[70144],
     | 99.00th=[240640], 99.50th=[329728], 99.90th=[569344], 99.95th=[675840],
     | 99.99th=[921600]
    lat (usec) : 2=0.01%, 20=0.01%, 100=1.12%, 250=83.31%, 500=2.64%
    lat (usec) : 750=0.21%, 1000=0.15%
    lat (msec) : 2=0.26%, 4=0.04%, 10=0.33%, 20=1.50%, 50=4.00%
    lat (msec) : 100=2.81%, 250=2.69%, 500=0.77%, 750=0.13%, 1000=0.02%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.25%, sys=0.76%, ctx=624059, 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=624801/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=63612MB, aggrb=72369KB/s, minb=2776KB/s, maxb=69593KB/s, mint=900076msec, maxt=900089msec
 
Disk stats (read/write):
    dm-2: ios=16284697/27, merge=0/0, ticks=14316884/11932, in_queue=14332000, util=100.00%, aggrios=5485619/348652, aggrmerge=0/0, aggrticks=6603850/63144, aggrin_queue=6667324, aggrutil=100.00%
    dm-1: ios=2/873767, merge=0/0, ticks=0/151744, in_queue=151760, util=8.83%, aggrios=16104758/960703, aggrmerge=0/80804, aggrticks=2186320/160864, aggrin_queue=2346844, aggrutil=91.57%
  xvdc: ios=16104758/960703, merge=0/80804, ticks=2186320/160864, in_queue=2346844, util=91.57%
  dm-0: ios=16104756/172087, merge=0/0, ticks=2187352/31620, in_queue=2219940, util=91.28%
    dm-3: ios=352100/102, merge=0/0, ticks=17624200/6068, in_queue=17630272, util=100.00%, aggrios=352101/91, aggrmerge=0/11, aggrticks=17624100/3584, aggrin_queue=17627592, aggrutil=100.00%
  xvdd: ios=352101/91, merge=0/11, ticks=17624100/3584, in_queue=17627592, util=100.00%

4.12.0-rc1+6cf4cc8f8b3b (2017-05-14 21:54:33 -0400) ^

Over 20k average IOPS on the run against a full cache means this was marked fixed.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+6cf4cc8f8b3b 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] [399.9MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1314: Sun Jul 30 02:20:12 2017
  read : io=132841MB, bw=151143KB/s, iops=37785, runt=900001msec
    slat (usec): min=2, max=4635, avg= 6.74, stdev= 3.66
    clat (usec): min=1, max=1208.1K, avg=202.59, stdev=2398.09
     lat (usec): min=68, max=1209.8K, avg=209.79, stdev=2398.38
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  108], 10.00th=[  111], 20.00th=[  119],
     | 30.00th=[  123], 40.00th=[  129], 50.00th=[  135], 60.00th=[  141],
     | 70.00th=[  151], 80.00th=[  163], 90.00th=[  189], 95.00th=[  217],
     | 99.00th=[  322], 99.50th=[  402], 99.90th=[18560], 99.95th=[31360],
     | 99.99th=[88576]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=0.17%
    lat (usec) : 250=97.09%, 500=2.42%, 750=0.06%, 1000=0.03%
    lat (msec) : 2=0.05%, 4=0.01%, 10=0.02%, 20=0.05%, 50=0.07%
    lat (msec) : 100=0.02%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=9.52%, sys=36.77%, ctx=17387398, 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=34007324/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=1315: Sun Jul 30 02:20:12 2017
  read : io=134807MB, bw=153381KB/s, iops=38345, runt=900001msec
    slat (usec): min=2, max=4192, avg= 6.64, stdev= 3.55
    clat (usec): min=1, max=1525.4K, avg=199.62, stdev=3082.99
     lat (usec): min=66, max=1525.4K, avg=206.71, stdev=3083.18
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  107], 10.00th=[  111], 20.00th=[  118],
     | 30.00th=[  122], 40.00th=[  127], 50.00th=[  133], 60.00th=[  139],
     | 70.00th=[  149], 80.00th=[  161], 90.00th=[  187], 95.00th=[  221],
     | 99.00th=[  326], 99.50th=[  398], 99.90th=[13888], 99.95th=[26496],
     | 99.99th=[99840]
    lat (usec) : 2=0.01%, 10=0.01%, 50=0.01%, 100=0.19%, 250=96.79%
    lat (usec) : 500=2.73%, 750=0.05%, 1000=0.03%
    lat (msec) : 2=0.06%, 4=0.01%, 10=0.02%, 20=0.05%, 50=0.05%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=9.82%, sys=36.76%, ctx=17659747, 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=34510679/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=267648MB, aggrb=304524KB/s, minb=151143KB/s, maxb=153380KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=68501557/28, merge=0/0, ticks=13693912/524, in_queue=13720060, util=100.00%, aggrios=22876855/176918, aggrmerge=0/0, aggrticks=4875376/104950, aggrin_queue=4986021, aggrutil=98.38%
    dm-1: ios=19/418181, merge=0/0, ticks=4/70080, in_queue=70112, util=5.49%, aggrios=68456360/446285, aggrmerge=2397/24774, aggrticks=9939560/79736, aggrin_queue=10019744, aggrutil=98.40%
  xvdc: ios=68456360/446285, merge=2397/24774, ticks=9939560/79736, in_queue=10019744, util=98.40%
  dm-0: ios=68458738/53971, merge=0/0, ticks=9966748/12776, in_queue=9996560, util=98.38%
    dm-3: ios=171810/58604, merge=0/0, ticks=4659376/231996, in_queue=4891392, util=57.31%, aggrios=171801/56085, aggrmerge=9/2519, aggrticks=4655812/142768, aggrin_queue=4798556, aggrutil=57.31%
  xvdd: ios=171801/56085, merge=9/2519, ticks=4655812/142768, in_queue=4798556, util=57.31%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+6cf4cc8f8b3b 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] [397.6MB/0KB/0KB /s] [102K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=3900: Sun Jul 30 02:38:37 2017
  read : io=73397MB, bw=83509KB/s, iops=20877, runt=900001msec
    slat (usec): min=3, max=3087, avg= 6.85, stdev= 3.37
    clat (usec): min=9, max=1501.2K, avg=373.90, stdev=6030.69
     lat (usec): min=72, max=1501.2K, avg=381.22, stdev=6031.19
    clat percentiles (usec):
     |  1.00th=[  104],  5.00th=[  109], 10.00th=[  114], 20.00th=[  121],
     | 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=[  338], 99.50th=[  418], 99.90th=[69120], 99.95th=[118272],
     | 99.99th=[268288]
    lat (usec) : 10=0.01%, 50=0.01%, 100=0.10%, 250=96.05%, 500=3.43%
    lat (usec) : 750=0.03%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.08%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.68%, sys=20.45%, ctx=9729438, 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=18789539/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=3901: Sun Jul 30 02:38:37 2017
  read : io=76248MB, bw=86753KB/s, iops=21688, runt=900001msec
    slat (usec): min=3, max=3309, avg= 6.82, stdev= 3.51
    clat (usec): min=1, max=1436.1K, avg=359.59, stdev=5873.40
     lat (usec): min=70, max=1436.1K, avg=366.87, stdev=5873.83
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  107], 10.00th=[  110], 20.00th=[  117],
     | 30.00th=[  122], 40.00th=[  127], 50.00th=[  133], 60.00th=[  139],
     | 70.00th=[  147], 80.00th=[  159], 90.00th=[  181], 95.00th=[  205],
     | 99.00th=[  282], 99.50th=[  370], 99.90th=[67072], 99.95th=[116224],
     | 99.99th=[268288]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.18%, 250=98.06%, 500=1.36%, 750=0.02%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.02%, 20=0.07%, 50=0.12%
    lat (msec) : 100=0.07%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=5.57%, sys=21.29%, ctx=9691035, 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=19519474/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=149645MB, aggrb=170262KB/s, minb=83508KB/s, maxb=86753KB/s, mint=900001msec, maxt=900001msec
 
Disk stats (read/write):
    dm-2: ios=38297973/29, merge=0/0, ticks=13982664/7004, in_queue=14003132, util=100.00%, aggrios=12791550/194298, aggrmerge=0/0, aggrticks=5442113/27136, aggrin_queue=5472816, aggrutil=68.60%
    dm-1: ios=102/517327, merge=0/0, ticks=12/62076, in_queue=62116, util=4.27%, aggrios=38174313/566608, aggrmerge=0/16117, aggrticks=5431508/72500, aggrin_queue=5506176, aggrutil=70.51%
  xvdc: ios=38174313/566608, merge=0/16117, ticks=5431508/72500, in_queue=5506176, util=70.51%
  dm-0: ios=38174211/65537, merge=0/0, ticks=5427632/12328, in_queue=5450628, util=68.60%
    dm-3: ios=200338/30, merge=0/0, ticks=10898696/7004, in_queue=10905704, util=68.37%, aggrios=200338/12, aggrmerge=0/18, aggrticks=10898668/2728, aggrin_queue=10901396, aggrutil=68.37%
  xvdd: ios=200338/12, merge=0/18, ticks=10898668/2728, in_queue=10901396, util=68.37%

4.12.0-rc1+4d44ec5ab751 (2017-05-14 21:54:33 -0400) ^

Although this time against a full cache both jobs manage a fairly consistent 6 or 7 thousand IOPS, this is nowhere near the level of performance we had seen before so this must be considered broken.

At this point git bisect was able to report that 6cf4cc8f8b3b was the first fixed commit.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+4d44ec5ab751 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] [48908KB/0KB/0KB /s] [12.3K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1745: Sun Jul 30 03:23:34 2017
  read : io=24635MB, bw=28027KB/s, iops=7006, runt=900037msec
    slat (usec): min=1, max=14906, avg= 6.77, stdev= 8.06
    clat (usec): min=1, max=1249.6K, avg=1132.59, stdev=9627.84
     lat (usec): min=69, max=1249.6K, avg=1139.79, stdev=9628.80
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  106], 20.00th=[  108],
     | 30.00th=[  112], 40.00th=[  118], 50.00th=[  121], 60.00th=[  123],
     | 70.00th=[  127], 80.00th=[  147], 90.00th=[  213], 95.00th=[  282],
     | 99.00th=[32128], 99.50th=[57088], 99.90th=[136192], 99.95th=[177152],
     | 99.99th=[292864]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.38%, 250=93.13%, 500=3.55%, 750=0.22%, 1000=0.21%
    lat (msec) : 2=0.29%, 4=0.01%, 10=0.07%, 20=0.57%, 50=0.98%
    lat (msec) : 100=0.41%, 250=0.18%, 500=0.02%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=2.13%, sys=6.56%, ctx=5311621, majf=1, 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=6306443/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=1746: Sun Jul 30 03:23:34 2017
  read : io=35476MB, bw=40361KB/s, iops=10090, runt=900046msec
    slat (usec): min=1, max=23444, avg= 6.51, stdev=11.66
    clat (usec): min=1, max=1501.4K, avg=784.01, stdev=8022.09
     lat (usec): min=67, max=1501.4K, avg=790.95, stdev=8022.73
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  106], 20.00th=[  108],
     | 30.00th=[  111], 40.00th=[  117], 50.00th=[  121], 60.00th=[  123],
     | 70.00th=[  127], 80.00th=[  145], 90.00th=[  211], 95.00th=[  278],
     | 99.00th=[19840], 99.50th=[40192], 99.90th=[113152], 99.95th=[152576],
     | 99.99th=[280576]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.37%, 250=93.16%, 500=4.24%, 750=0.27%, 1000=0.20%
    lat (msec) : 2=0.29%, 4=0.02%, 10=0.07%, 20=0.37%, 50=0.62%
    lat (msec) : 100=0.25%, 250=0.11%, 500=0.01%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=2.58%, sys=9.44%, ctx=6971695, 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=9081785/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=60110MB, aggrb=68388KB/s, minb=28027KB/s, maxb=40361KB/s, mint=900037msec, maxt=900046msec
 
Disk stats (read/write):
    dm-2: ios=15387198/28, merge=0/0, ticks=14306100/6972, in_queue=14316452, util=100.00%, aggrios=5233578/737062, aggrmerge=0/0, aggrticks=5314757/297484, aggrin_queue=5612629, aggrutil=100.00%
    dm-1: ios=0/1898650, merge=0/0, ticks=0/275700, in_queue=275740, util=20.28%, aggrios=15166622/2060890, aggrmerge=2630/85657, aggrticks=2377016/315952, aggrin_queue=2692844, aggrutil=88.91%
  xvdc: ios=15166622/2060890, merge=2630/85657, ticks=2377016/315952, in_queue=2692844, util=88.91%
  dm-0: ios=15169252/249770, merge=0/0, ticks=2424412/51644, in_queue=2477168, util=88.37%
    dm-3: ios=531482/62766, merge=0/0, ticks=13519860/565108, in_queue=14084980, util=100.00%, aggrios=531464/60098, aggrmerge=18/2668, aggrticks=13515428/447352, aggrin_queue=13962752, aggrutil=100.00%
  xvdd: ios=531464/60098, merge=18/2668, ticks=13515428/447352, in_queue=13962752, util=100.00%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+4d44ec5ab751 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] [42352KB/0KB/0KB /s] [10.6K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=4248: Sun Jul 30 03:40:34 2017
  read : io=27816MB, bw=31644KB/s, iops=7911, runt=900111msec
    slat (usec): min=1, max=3143, avg= 6.38, stdev= 3.68
    clat (usec): min=1, max=1247.3K, avg=1002.62, stdev=10214.33
     lat (usec): min=69, max=1247.4K, avg=1009.42, stdev=10214.63
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  103], 10.00th=[  105], 20.00th=[  107],
     | 30.00th=[  109], 40.00th=[  114], 50.00th=[  119], 60.00th=[  121],
     | 70.00th=[  123], 80.00th=[  135], 90.00th=[  207], 95.00th=[  278],
     | 99.00th=[25472], 99.50th=[53504], 99.90th=[150528], 99.95th=[195584],
     | 99.99th=[337920]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=0.49%
    lat (usec) : 250=93.10%, 500=4.06%, 750=0.23%, 1000=0.21%
    lat (msec) : 2=0.29%, 4=0.01%, 10=0.05%, 20=0.36%, 50=0.66%
    lat (msec) : 100=0.32%, 250=0.20%, 500=0.02%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=2.18%, sys=7.27%, ctx=6208585, 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=7120878/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=4249: Sun Jul 30 03:40:34 2017
  read : io=21517MB, bw=24481KB/s, iops=6120, runt=900042msec
    slat (usec): min=1, max=3946, avg= 6.52, stdev= 4.06
    clat (usec): min=1, max=1225.4K, avg=1298.37, stdev=13872.59
     lat (usec): min=68, max=1225.4K, avg=1305.32, stdev=13872.88
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  103], 10.00th=[  105], 20.00th=[  107],
     | 30.00th=[  108], 40.00th=[  111], 50.00th=[  118], 60.00th=[  121],
     | 70.00th=[  122], 80.00th=[  127], 90.00th=[  195], 95.00th=[  270],
     | 99.00th=[29568], 99.50th=[82432], 99.90th=[207872], 99.95th=[268288],
     | 99.99th=[452608]
    lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=0.60%
    lat (usec) : 250=93.47%, 500=3.81%, 750=0.20%, 1000=0.17%
    lat (msec) : 2=0.28%, 4=0.01%, 10=0.05%, 20=0.23%, 50=0.44%
    lat (msec) : 100=0.34%, 250=0.34%, 500=0.05%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=1.71%, sys=5.81%, ctx=5136977, 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=5508414/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=49333MB, aggrb=56123KB/s, minb=24480KB/s, maxb=31644KB/s, mint=900042msec, maxt=900111msec
 
Disk stats (read/write):
    dm-2: ios=12628996/29, merge=0/0, ticks=14325248/9004, in_queue=14337928, util=100.00%, aggrios=4283504/430396, aggrmerge=0/0, aggrticks=6408228/152828, aggrin_queue=6561282, aggrutil=100.00%
    dm-1: ios=1/1069937, merge=0/0, ticks=0/186088, in_queue=186096, util=11.15%, aggrios=12454547/1169074, aggrmerge=94/92406, aggrticks=1764348/199032, aggrin_queue=1963216, aggrutil=82.20%
  xvdc: ios=12454547/1169074, merge=94/92406, ticks=1764348/199032, in_queue=1963216, util=82.20%
  dm-0: ios=12454640/195514, merge=0/0, ticks=1766212/37200, in_queue=1804008, util=82.11%
    dm-3: ios=395873/25738, merge=0/0, ticks=17458472/235196, in_queue=17693744, util=100.00%, aggrios=395871/25673, aggrmerge=2/65, aggrticks=17458124/214396, aggrin_queue=17672604, aggrutil=100.00%
  xvdd: ios=395871/25673, merge=2/65, ticks=17458124/214396, in_queue=17672604, util=100.00%

Tests against additional kernel builds ^

4.12.0-rc1 2ea659a9ef48 (2017-05-13 13:19:49 -0700) ^

A couple of the release candidates with some of Joe’s fixes in had started to produce approaching decent performance so I wanted to go back to the first tagged kernel for this release candidate to get an overview of where Joe had been starting from.

2,069 and 689 average IOPS against a full cache demonstrate the poor performance.

Empty cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-empty-4.12.0-rc1+2ea659a9ef48 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] [226.2MB/0KB/0KB /s] [57.9K/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=1410: Sun Jul 30 05:18:46 2017
  read : io=119229MB, bw=135648KB/s, iops=33911, runt=900055msec
    slat (usec): min=3, max=4243, avg= 6.13, stdev= 2.67
    clat (usec): min=12, max=777623, avg=227.66, stdev=3034.59
     lat (usec): min=69, max=777634, avg=234.21, stdev=3035.00
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  105], 10.00th=[  107], 20.00th=[  111],
     | 30.00th=[  117], 40.00th=[  121], 50.00th=[  123], 60.00th=[  126],
     | 70.00th=[  131], 80.00th=[  143], 90.00th=[  183], 95.00th=[  237],
     | 99.00th=[  370], 99.50th=[  466], 99.90th=[29568], 99.95th=[52480],
     | 99.99th=[140288]
    lat (usec) : 20=0.01%, 50=0.01%, 100=0.22%, 250=95.59%, 500=3.73%
    lat (usec) : 750=0.10%, 1000=0.07%
    lat (msec) : 2=0.10%, 4=0.01%, 10=0.01%, 20=0.03%, 50=0.09%
    lat (msec) : 100=0.03%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
  cpu          : usr=8.43%, sys=31.48%, ctx=19010691, 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=30522650/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=1411: Sun Jul 30 05:18:46 2017
  read : io=38320MB, bw=43598KB/s, iops=10899, runt=900034msec
    slat (usec): min=3, max=2937, avg= 7.12, stdev= 3.52
    clat (usec): min=1, max=664000, avg=724.45, stdev=7322.47
     lat (usec): min=69, max=664008, avg=732.02, stdev=7323.28
    clat percentiles (usec):
     |  1.00th=[  101],  5.00th=[  104], 10.00th=[  107], 20.00th=[  111],
     | 30.00th=[  117], 40.00th=[  120], 50.00th=[  122], 60.00th=[  125],
     | 70.00th=[  129], 80.00th=[  137], 90.00th=[  165], 95.00th=[  235],
     | 99.00th=[16512], 99.50th=[38656], 99.90th=[111104], 99.95th=[148480],
     | 99.99th=[246784]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.59%, 250=95.04%, 500=2.69%, 750=0.11%, 1000=0.08%
    lat (msec) : 2=0.14%, 4=0.02%, 10=0.10%, 20=0.34%, 50=0.52%
    lat (msec) : 100=0.25%, 250=0.11%, 500=0.01%, 750=0.01%
  cpu          : usr=3.25%, sys=11.57%, ctx=8505263, 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=9809817/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=157549MB, aggrb=179244KB/s, minb=43597KB/s, maxb=135647KB/s, mint=900034msec, maxt=900055msec
 
Disk stats (read/write):
    dm-2: ios=40332438/28, merge=0/0, ticks=14117864/2196, in_queue=14130156, util=100.00%, aggrios=13483192/313952, aggrmerge=0/0, aggrticks=5420121/72913, aggrin_queue=5494664, aggrutil=100.00%
    dm-1: ios=2/824719, merge=0/0, ticks=0/128108, in_queue=128144, util=10.06%, aggrios=40125306/891909, aggrmerge=1810/39159, aggrticks=5531356/144120, aggrin_queue=5674304, aggrutil=99.96%
  xvdc: ios=40125306/891909, merge=1810/39159, ticks=5531356/144120, in_queue=5674304, util=99.96%
  dm-0: ios=40127114/107088, merge=0/0, ticks=5533456/20608, in_queue=5559116, util=99.96%
    dm-3: ios=322461/10050, merge=0/0, ticks=10726908/70024, in_queue=10796732, util=100.00%, aggrios=322461/8135, aggrmerge=0/1923, aggrticks=10726860/46396, aggrin_queue=10773180, aggrutil=100.00%
  xvdd: ios=322461/8135, merge=0/1923, ticks=10726860/46396, in_queue=10773180, util=100.00%
Full cache
$ (cd /srv/cache/fio && FIOTEST=lvmcache-full-4.12.0-rc1+2ea659a9ef48 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] [11616KB/0KB/0KB /s] [2904/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=3880: Sun Jul 30 05:36:12 2017
  read : io=7278.8MB, bw=8279.1KB/s, iops=2069, runt=900169msec
    slat (usec): min=3, max=749, avg= 7.94, stdev= 6.36
    clat (usec): min=2, max=1369.3K, avg=3854.37, stdev=24787.42
     lat (usec): min=72, max=1369.3K, avg=3862.76, stdev=24789.32
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  104], 10.00th=[  107], 20.00th=[  108],
     | 30.00th=[  116], 40.00th=[  118], 50.00th=[  121], 60.00th=[  121],
     | 70.00th=[  122], 80.00th=[  125], 90.00th=[  163], 95.00th=[13632],
     | 99.00th=[104960], 99.50th=[162816], 99.90th=[337920], 99.95th=[423936],
     | 99.99th=[659456]
    lat (usec) : 4=0.01%, 50=0.01%, 100=0.15%, 250=93.36%, 500=0.46%
    lat (usec) : 750=0.09%, 1000=0.07%
    lat (msec) : 2=0.11%, 4=0.01%, 10=0.29%, 20=1.36%, 50=1.89%
    lat (msec) : 100=1.15%, 250=0.85%, 500=0.18%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.71%, sys=2.61%, ctx=1927655, 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=1863344/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=3881: Sun Jul 30 05:36:12 2017
  read : io=2423.8MB, bw=2757.4KB/s, iops=689, runt=900123msec
    slat (usec): min=3, max=702, avg= 8.61, stdev= 5.54
    clat (usec): min=64, max=1534.9K, avg=11593.97, stdev=45491.15
     lat (usec): min=70, max=1534.9K, avg=11603.08, stdev=45492.10
    clat percentiles (usec):
     |  1.00th=[  100],  5.00th=[  103], 10.00th=[  104], 20.00th=[  106],
     | 30.00th=[  108], 40.00th=[  113], 50.00th=[  119], 60.00th=[  122],
     | 70.00th=[  131], 80.00th=[  163], 90.00th=[28288], 95.00th=[68096],
     | 99.00th=[216064], 99.50th=[296960], 99.90th=[544768], 99.95th=[659456],
     | 99.99th=[929792]
    lat (usec) : 100=0.68%, 250=82.38%, 500=0.40%, 750=0.11%, 1000=0.08%
    lat (msec) : 2=0.15%, 4=0.02%, 10=0.62%, 20=3.41%, 50=5.54%
    lat (msec) : 100=3.34%, 250=2.53%, 500=0.61%, 750=0.10%, 1000=0.02%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.36%, sys=0.86%, ctx=628886, 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=620477/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=9702.5MB, aggrb=11037KB/s, minb=2757KB/s, maxb=8279KB/s, mint=900123msec, maxt=900169msec
 
Disk stats (read/write):
    dm-2: ios=2483744/29, merge=0/0, ticks=14379036/2900, in_queue=14383400, util=100.00%, aggrios=863141/314477, aggrmerge=0/0, aggrticks=6157485/39758, aggrin_queue=6197288, aggrutil=100.00%
    dm-1: ios=33/837830, merge=0/0, ticks=0/96648, in_queue=96660, util=6.07%, aggrios=2269963/907940, aggrmerge=0/35094, aggrticks=285192/112048, aggrin_queue=397148, aggrutil=34.50%
  xvdc: ios=2269963/907940, merge=0/35094, ticks=285192/112048, in_queue=397148, util=34.50%
  dm-0: ios=2269930/105586, merge=0/0, ticks=285436/19728, in_queue=305184, util=30.03%
    dm-3: ios=319462/16, merge=0/0, ticks=18187020/2900, in_queue=18190020, util=100.00%, aggrios=319462/8, aggrmerge=0/8, aggrticks=18187012/1068, aggrin_queue=18188076, aggrutil=100.00%
  xvdd: ios=319462/8, merge=0/8, ticks=18187012/1068, in_queue=18188076, util=100.00%

Leave a Reply

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