Re: Measuring IOPS

[Martin Steigerwald <Martin@lichtvoll.de>]

[-- Attachment #1: Type: Text/Plain, Size: 1661 bytes --]

Am Freitag, 29. Juli 2011 schrieben Sie:
> Hi!
> 
> I am currently writing an article about fio for a german print magazine
> after having packaged it for Debian and using it in performance
> analysis & tuning trainings.
> 
> After introducting into the concepts of fio with some basic job files
> I´d like how to do meaningful IOPS measurements that also work with
> SSDs that compress.
> 
> For some first tests I came up with:
> 
> martin@merkaba:~[…]> cat iops.job
> [global]
> size=2G
> bsrange=2-16k
> filename=iops1
> numjobs=1
> iodepth=1
> # Zufällige Daten für SSDs, die komprimieren
> refill_buffers=1
> 
> [zufälligschreiben]
> rw=randwrite
> stonewall
> [sequentiellschreiben]
> rw=write
> stonewall
> 
> [zufälliglesen]
> rw=randread
> stonewall
> [sequentielllesen]
> rw=read

Even with the additional stonewall this still isn´t accurate. I found this 
by getting completely bogus values with a SoftRAID 1 on two SAS disks.

It needs the following additional changes:

- ioengine=libaio
- direct=1
- and then due to direct I/O alignment requirement: bsrange=2k-16k

So I now also fully understand that ioengine=sync just refers to the 
synchronous nature of the system calls used, not on whether the I/Os are 
issued synchronously via sync=1 or by circumventing the page cache via 
direct=1

Attached are results that bring down IOPS on read drastically! I first let 
sequentiell.job write out the complete 2 gb with random data and then ran 
the iops.job.

Thanks,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: iops.job --]
[-- Type: text/plain, Size: 523 bytes --]

[global]
ioengine=libaio
direct=1
# Für zufällige Daten vorher den Job sequentiell
# laufen lassen
# Wichtig für SSDs, die komprimieren
filename=testdatei
size=2G
bsrange=2k-16k

# Das, was hier geschrieben wird, soll natürlich
# auch wieder zufällig sein
refill_buffers=1

[zufälliglesen]
stonewall
rw=randread
runtime=60

[sequentielllesen]
stonewall
rw=read
runtime=60

[zufälligschreiben]
stonewall
rw=randwrite
runtime=60

[sequentiellschreiben]
stonewall
rw=write
runtime=60


[-- Attachment #3: iops.log --]
[-- Type: text/x-log, Size: 4940 bytes --]

zufälliglesen: (g=0): rw=randread, bs=2K-16K/2K-16K, ioengine=libaio, iodepth=1
sequentielllesen: (g=1): rw=read, bs=2K-16K/2K-16K, ioengine=libaio, iodepth=1
zufälligschreiben: (g=2): rw=randwrite, bs=2K-16K/2K-16K, ioengine=libaio, iodepth=1
sequentiellschreiben: (g=3): rw=write, bs=2K-16K/2K-16K, ioengine=libaio, iodepth=1
fio 1.57
Starting 4 processes

zufälliglesen: (groupid=0, jobs=1): err= 0: pid=6954
  read : io=1322.9MB, bw=22563KB/s, iops=3194 , runt= 60001msec
    slat (usec): min=6 , max=1763 , avg=29.52, stdev=12.62
    clat (usec): min=2 , max=7206 , avg=274.52, stdev=114.08
     lat (usec): min=128 , max=7246 , avg=304.68, stdev=116.81
    bw (KB/s) : min=18844, max=25304, per=100.15%, avg=22596.20, stdev=1740.26
  cpu          : usr=4.15%, sys=10.50%, ctx=193490, majf=0, minf=23
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=191664/0/0, short=0/0/0
     lat (usec): 4=0.01%, 10=0.01%, 50=0.01%, 100=0.01%, 250=49.32%
     lat (usec): 500=48.57%, 750=1.98%, 1000=0.05%
     lat (msec): 2=0.05%, 4=0.02%, 10=0.01%
sequentielllesen: (groupid=1, jobs=1): err= 0: pid=6956
  read : io=2048.0MB, bw=72598KB/s, iops=8066 , runt= 28887msec
    slat (usec): min=5 , max=1909 , avg=26.76, stdev= 8.98
    clat (usec): min=1 , max=4631 , avg=91.18, stdev=36.03
     lat (usec): min=40 , max=4644 , avg=118.51, stdev=37.86
    bw (KB/s) : min=70224, max=77412, per=100.09%, avg=72663.79, stdev=1589.19
  cpu          : usr=6.47%, sys=24.83%, ctx=234568, majf=0, minf=25
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=233021/0/0, short=0/0/0
     lat (usec): 2=0.01%, 4=0.01%, 10=0.01%, 50=0.71%, 100=65.76%
     lat (usec): 250=33.16%, 500=0.29%, 750=0.05%, 1000=0.02%
     lat (msec): 2=0.01%, 4=0.01%, 10=0.01%
zufälligschreiben: (groupid=2, jobs=1): err= 0: pid=6958
  write: io=2048.0MB, bw=36083KB/s, iops=6594 , runt= 58121msec
    slat (usec): min=6 , max=1952 , avg=31.79, stdev= 9.51
    clat (usec): min=0 , max=19882 , avg=113.47, stdev=216.71
     lat (usec): min=44 , max=19949 , avg=145.84, stdev=217.32
    bw (KB/s) : min=14000, max=58580, per=100.12%, avg=36125.51, stdev=10544.88
  cpu          : usr=5.66%, sys=23.66%, ctx=386270, majf=0, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=0/383305/0, short=0/0/0
     lat (usec): 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=1.92%
     lat (usec): 100=61.91%, 250=30.73%, 500=5.22%, 750=0.12%, 1000=0.04%
     lat (msec): 2=0.03%, 4=0.01%, 10=0.01%, 20=0.01%
sequentiellschreiben: (groupid=3, jobs=1): err= 0: pid=6959
  write: io=2048.0MB, bw=63465KB/s, iops=7050 , runt= 33044msec
    slat (usec): min=6 , max=2854 , avg=30.54, stdev=11.23
    clat (usec): min=1 , max=19371 , avg=104.68, stdev=190.45
     lat (usec): min=43 , max=19417 , avg=135.81, stdev=191.17
    bw (KB/s) : min=22984, max=68224, per=100.07%, avg=63511.21, stdev=5443.51
  cpu          : usr=6.16%, sys=24.62%, ctx=234687, majf=0, minf=19
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=0/232969/0, short=0/0/0
     lat (usec): 2=0.01%, 4=0.01%, 10=0.01%, 50=0.68%, 100=51.92%
     lat (usec): 250=46.97%, 500=0.22%, 750=0.07%, 1000=0.07%
     lat (msec): 2=0.04%, 4=0.01%, 10=0.01%, 20=0.01%

Run status group 0 (all jobs):
   READ: io=1322.9MB, aggrb=22563KB/s, minb=23104KB/s, maxb=23104KB/s, mint=60001msec, maxt=60001msec

Run status group 1 (all jobs):
   READ: io=2048.0MB, aggrb=72598KB/s, minb=74340KB/s, maxb=74340KB/s, mint=28887msec, maxt=28887msec

Run status group 2 (all jobs):
  WRITE: io=2048.0MB, aggrb=36082KB/s, minb=36948KB/s, maxb=36948KB/s, mint=58121msec, maxt=58121msec

Run status group 3 (all jobs):
  WRITE: io=2048.0MB, aggrb=63465KB/s, minb=64988KB/s, maxb=64988KB/s, mint=33044msec, maxt=33044msec

Disk stats (read/write):
  dm-2: ios=424704/615629, merge=0/0, ticks=70028/59768, in_queue=129796, util=71.90%, aggrios=424704/616498, aggrmerge=0/60, aggrticks=69568/60584, aggrin_queue=128920, aggrutil=71.33%
    sda: ios=424704/616498, merge=0/60, ticks=69568/60584, in_queue=128920, util=71.33%

[-- Attachment #4: sequentiell.job --]
[-- Type: text/plain, Size: 221 bytes --]

[global]
ioengine=libaio
direct=1
filename=testdatei
size=2g
bs=4m

# Vollständig zufällige Daten für SSDs, die komprimieren
refill_buffers=1

[schreiben]
stonewall
rw=write

[lesen]
stonewall
rw=read

[-- Attachment #5: sequentiell.log --]
[-- Type: text/x-log, Size: 2432 bytes --]

[global]
ioengine=libaio
direct=1
filename=testdatei
size=2g
bs=4m

[schreiben]
stonewall
rw=write

[lesen]
stonewall
rw=read
schreiben: (g=0): rw=write, bs=4M-4M/4M-4M, ioengine=libaio, iodepth=1
lesen: (g=1): rw=read, bs=4M-4M/4M-4M, ioengine=libaio, iodepth=1
fio 1.57
Starting 2 processes
schreiben: Laying out IO file(s) (1 file(s) / 2048MB)

schreiben: (groupid=0, jobs=1): err= 0: pid=5855
  write: io=2048.0MB, bw=220150KB/s, iops=53 , runt=  9526msec
    slat (usec): min=239 , max=1328 , avg=452.88, stdev=182.05
    clat (msec): min=17 , max=22 , avg=18.14, stdev= 1.10
     lat (msec): min=17 , max=23 , avg=18.59, stdev= 1.12
    bw (KB/s) : min=216422, max=223128, per=100.08%, avg=220331.94, stdev=2205.18
  cpu          : usr=0.17%, sys=2.44%, ctx=557, majf=0, minf=19
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=0/512/0, short=0/0/0

     lat (msec): 20=93.55%, 50=6.45%
lesen: (groupid=1, jobs=1): err= 0: pid=5856
  read : io=2048.0MB, bw=267460KB/s, iops=65 , runt=  7841msec
    slat (usec): min=251 , max=4071 , avg=581.06, stdev=300.62
    clat (usec): min=14517 , max=17700 , avg=14724.38, stdev=340.74
     lat (usec): min=14906 , max=20094 , avg=15306.37, stdev=451.23
    bw (KB/s) : min=264000, max=270336, per=100.07%, avg=267634.87, stdev=1787.07
  cpu          : usr=0.10%, sys=3.78%, ctx=569, majf=0, minf=1045
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.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.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued r/w/d: total=512/0/0, short=0/0/0

     lat (msec): 20=100.00%

Run status group 0 (all jobs):
  WRITE: io=2048.0MB, aggrb=220150KB/s, minb=225433KB/s, maxb=225433KB/s, mint=9526msec, maxt=9526msec

Run status group 1 (all jobs):
   READ: io=2048.0MB, aggrb=267459KB/s, minb=273878KB/s, maxb=273878KB/s, mint=7841msec, maxt=7841msec

Disk stats (read/write):
  dm-2: ios=3991/4196, merge=0/0, ticks=33880/43220, in_queue=77124, util=96.78%, aggrios=4112/4143, aggrmerge=0/56, aggrticks=34944/42968, aggrin_queue=77904, aggrutil=96.79%
    sda: ios=4112/4143, merge=0/56, ticks=34944/42968, in_queue=77904, util=96.79%