12 hours of lvmcache

In the previous post I noted that the performance of lvmcache was still increasing and it might be worth testing it for longer than 3 hours.

Here’a a 12 hour test ^

$ cd /srv/cache/fio && FIOTEST=lvmcache-12h fio ~/lvmcache-12h.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] [6272KB/0KB/0KB /s] [1568/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=11130: Fri Jul 21 16:37:30 2017
  read : io=136145MB, bw=3227.2KB/s, iops=806, runt=43200062msec
    slat (usec): min=3, max=586402, avg=14.27, stdev=619.54
    clat (usec): min=2, max=1517.9K, avg=9897.80, stdev=29334.14
     lat (usec): min=71, max=1517.9K, avg=9912.72, stdev=29344.74
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  110], 10.00th=[  113], 20.00th=[  119],
     | 30.00th=[  124], 40.00th=[  129], 50.00th=[  133], 60.00th=[  143],
     | 70.00th=[  157], 80.00th=[11840], 90.00th=[30848], 95.00th=[56576],
     | 99.00th=[136192], 99.50th=[179200], 99.90th=[309248], 99.95th=[382976],
     | 99.99th=[577536]
    lat (usec) : 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.03%
    lat (usec) : 250=76.84%, 500=0.26%, 750=0.13%, 1000=0.13%
    lat (msec) : 2=0.25%, 4=0.02%, 10=1.19%, 20=6.67%, 50=8.59%
    lat (msec) : 100=3.93%, 250=1.77%, 500=0.18%, 750=0.02%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.44%, sys=1.63%, ctx=34524570, 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=34853153/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=11131: Fri Jul 21 16:37:30 2017
  read : io=134521MB, bw=3188.7KB/s, iops=797, runt=43200050msec
    slat (usec): min=3, max=588479, avg=14.35, stdev=613.38
    clat (usec): min=2, max=1530.3K, avg=10017.42, stdev=29196.28
     lat (usec): min=70, max=1530.3K, avg=10032.43, stdev=29207.06
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  109], 10.00th=[  112], 20.00th=[  118],
     | 30.00th=[  124], 40.00th=[  127], 50.00th=[  133], 60.00th=[  143],
     | 70.00th=[  157], 80.00th=[12352], 90.00th=[31360], 95.00th=[57600],
     | 99.00th=[138240], 99.50th=[179200], 99.90th=[301056], 99.95th=[370688],
     | 99.99th=[561152]
    lat (usec) : 4=0.01%, 20=0.01%, 50=0.01%, 100=0.04%, 250=76.56%
    lat (usec) : 500=0.26%, 750=0.12%, 1000=0.13%
    lat (msec) : 2=0.26%, 4=0.02%, 10=1.20%, 20=6.75%, 50=8.65%
    lat (msec) : 100=4.01%, 250=1.82%, 500=0.17%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.45%, sys=1.60%, ctx=34118324, 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=34437257/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=270666MB, aggrb=6415KB/s, minb=3188KB/s, maxb=3227KB/s, mint=43200050msec, maxt=43200062msec
 
Disk stats (read/write):
    dm-2: ios=69290239/1883, merge=0/0, ticks=690078104/246240, in_queue=690329868, util=100.00%, aggrios=23098543/27863, aggrmerge=0/0, aggrticks=229728200/637782, aggrin_queue=230366965, aggrutil=100.00%
    dm-1: ios=247/64985, merge=0/0, ticks=36/15464, in_queue=15504, util=0.02%, aggrios=53025553/63449, aggrmerge=0/7939, aggrticks=7413340/14760, aggrin_queue=7427028, aggrutil=16.42%
  xvdc: ios=53025553/63449, merge=0/7939, ticks=7413340/14760, in_queue=7427028, util=16.42%
  dm-0: ios=53025306/6403, merge=0/0, ticks=7417028/1852, in_queue=7419784, util=16.42%
    dm-3: ios=16270078/12201, merge=0/0, ticks=681767536/1896032, in_queue=683665608, util=100.00%, aggrios=16270077/12200, aggrmerge=1/1, aggrticks=681637744/1813744, aggrin_queue=683453224, aggrutil=100.00%
  xvdd: ios=16270077/12200, merge=1/1, ticks=681637744/1813744, in_queue=683453224, util=100.00%

It’s still going up, slowly. The cache hit rate was 76.53%. In the 30 minute test the hit rate was 73.64%.

Over 30 minutes the average IOPS was 1,484.

Over 12 hours the average IOPS was 1,603.

I was kind of hoping to reach the point where the hit rate is so high that it just takes off like bcache does and we start to see tens of thousands of IOPS, but it wasn’t to be.

24 hours of lvmcache ^

…so I went ahead and ran the same thing for 24 hours.

I’ve skipped the first 2 hours of results since we know what they look like. It appears to still be going up, although the results past 20 hours leave some doubt there.

Here’s the full fio output.

$ cd /srv/cache/fio && FIOTEST=lvmcache-24h fio ~/lvmcache-24h.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] [7152KB/0KB/0KB /s] [1788/0/0 iops] [eta 00m:00s]
partial: (groupid=0, jobs=1): err= 0: pid=14676: Sat Jul 22 21:34:12 2017
  read : io=278655MB, bw=3302.6KB/s, iops=825, runt=86400091msec
    slat (usec): min=3, max=326, avg=12.43, stdev= 6.97
    clat (usec): min=1, max=1524.1K, avg=9673.02, stdev=28748.45
     lat (usec): min=71, max=1525.7K, avg=9686.11, stdev=28748.87
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  106], 10.00th=[  111], 20.00th=[  116],
     | 30.00th=[  119], 40.00th=[  125], 50.00th=[  131], 60.00th=[  139],
     | 70.00th=[  155], 80.00th=[11456], 90.00th=[30336], 95.00th=[55552],
     | 99.00th=[134144], 99.50th=[177152], 99.90th=[305152], 99.95th=[374784],
     | 99.99th=[569344]
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.03%, 250=77.16%, 500=0.22%, 750=0.12%, 1000=0.12%
    lat (msec) : 2=0.23%, 4=0.02%, 10=1.18%, 20=6.65%, 50=8.54%
    lat (msec) : 100=3.84%, 250=1.70%, 500=0.17%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.47%, sys=1.64%, ctx=70653446, 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=71335660/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=14677: Sat Jul 22 21:34:12 2017
  read : io=283280MB, bw=3357.4KB/s, iops=839, runt=86400074msec
    slat (usec): min=3, max=330, avg=12.44, stdev= 6.98
    clat (usec): min=2, max=1515.9K, avg=9514.83, stdev=28128.86
     lat (usec): min=71, max=1515.2K, avg=9527.92, stdev=28129.29
    clat percentiles (usec):
     |  1.00th=[  103],  5.00th=[  109], 10.00th=[  112], 20.00th=[  118],
     | 30.00th=[  123], 40.00th=[  126], 50.00th=[  133], 60.00th=[  141],
     | 70.00th=[  157], 80.00th=[11328], 90.00th=[29824], 95.00th=[55040],
     | 99.00th=[132096], 99.50th=[173056], 99.90th=[292864], 99.95th=[362496],
     | 99.99th=[544768]
    lat (usec) : 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.03%
    lat (usec) : 250=77.29%, 500=0.23%, 750=0.11%, 1000=0.12%
    lat (msec) : 2=0.23%, 4=0.02%, 10=1.18%, 20=6.65%, 50=8.49%
    lat (msec) : 100=3.81%, 250=1.66%, 500=0.15%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu          : usr=0.47%, sys=1.67%, ctx=71794214, 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=72519640/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=561935MB, aggrb=6659KB/s, minb=3302KB/s, maxb=3357KB/s, mint=86400074msec, maxt=86400091msec
 
Disk stats (read/write):
    dm-2: ios=143855123/29, merge=0/0, ticks=1380761492/1976, in_queue=1380772508, util=100.00%, aggrios=47953627/25157, aggrmerge=0/0, aggrticks=459927326/7329, aggrin_queue=459937080, aggrutil=100.00%
    dm-1: ios=314/70172, merge=0/0, ticks=40/15968, in_queue=16008, util=0.01%, aggrios=110839338/72760, aggrmerge=0/2691, aggrticks=15300392/17100, aggrin_queue=15315432, aggrutil=16.92%
  xvdc: ios=110839338/72760, merge=0/2691, ticks=15300392/17100, in_queue=15315432, util=16.92%
  dm-0: ios=110839024/5279, merge=0/0, ticks=15308540/1768, in_queue=15312588, util=16.93%
    dm-3: ios=33021544/20, merge=0/0, ticks=1364473400/4252, in_queue=1364482644, util=100.00%, aggrios=33021544/19, aggrmerge=0/1, aggrticks=1364468920/4076, aggrin_queue=1364476064, aggrutil=100.00%
  xvdd: ios=33021544/19, merge=0/1, ticks=1364468920/4076, in_queue=1364476064, util=100.00%

So, 1,664 average IOPS (825 + 839), 77.05% (110,839,338 / (71,335,660 + 72,519,640)*100) cache hit rate.

Not sure I can be bothered to run a multi-day test on this now!

One thought on “12 hours of lvmcache

Leave a Reply

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