search

buty4649 / fio-cdm

fioでCrystalDiskMarkっぽい計測を行うコマンド
MIT License
48 stars 14 forks source link

Incorrect reporting of speeds #1

Closed JohnVeness closed 6 years ago

JohnVeness commented 6 years ago

I am seeing the following output on my HDD:

$ ./fio-cdm /myth/htpc-1
|      | Read(MB/s)|Write(MB/s)|
|------|-----------|-----------|
|  Seq |     42.993|     43.617|
| 512K |     23.759|     29.419|
|   4K |  43673.000|  94981.000|
|4KQD32|  96077.000|  95814.000|

Note the very high 4K results.

If I do a separate fio run, using your config file, I get:

Seq-Read: (g=0): rw=read, bs=1M-1M/1M-1M/1M-1M, ioengine=libaio, iodepth=1
Seq-Write: (g=1): rw=write, bs=1M-1M/1M-1M/1M-1M, ioengine=libaio, iodepth=1
Rand-Read-512K: (g=2): rw=randread, bs=512K-512K/512K-512K/512K-512K, ioengine=libaio, iodepth=1
Rand-Write-512K: (g=3): rw=randwrite, bs=512K-512K/512K-512K/512K-512K, ioengine=libaio, iodepth=1
Rand-Read-4K: (g=4): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
Rand-Write-4K: (g=5): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
Rand-Read-4K-QD32: (g=6): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=32
Rand-Write-4K-QD32: (g=7): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=32
fio-2.1.3
Starting 8 processes

Seq-Read: (groupid=0, jobs=1): err= 0: pid=19647: Sat Oct  7 20:49:46 2017
  read : io=1024.0MB, bw=43473KB/s, iops=42, runt= 24120msec
    slat (usec): min=97, max=430, avg=141.32, stdev=56.48
    clat (msec): min=4, max=509, avg=23.40, stdev=21.43
     lat (msec): min=4, max=509, avg=23.55, stdev=21.43
    clat percentiles (msec):
     |  1.00th=[   19],  5.00th=[   19], 10.00th=[   20], 20.00th=[   20],
     | 30.00th=[   21], 40.00th=[   21], 50.00th=[   21], 60.00th=[   23],
     | 70.00th=[   23], 80.00th=[   24], 90.00th=[   25], 95.00th=[   25],
     | 99.00th=[   64], 99.50th=[  176], 99.90th=[  265], 99.95th=[  510],
     | 99.99th=[  510]
    bw (KB  /s): min=16605, max=51497, per=100.00%, avg=43866.63, stdev=8112.00
    lat (msec) : 10=0.10%, 20=21.00%, 50=77.73%, 100=0.29%, 250=0.68%
    lat (msec) : 500=0.10%, 750=0.10%
  cpu          : usr=0.05%, sys=0.70%, ctx=1025, majf=0, minf=262
  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    : total=r=1024/w=0/d=0, short=r=0/w=0/d=0
Seq-Write: (groupid=1, jobs=1): err= 0: pid=20527: Sat Oct  7 20:49:46 2017
  write: io=1024.0MB, bw=43986KB/s, iops=42, runt= 23839msec
    slat (usec): min=267, max=1011, avg=350.45, stdev=113.89
    clat (msec): min=18, max=468, avg=22.92, stdev=19.51
     lat (msec): min=18, max=468, avg=23.27, stdev=19.52
    clat percentiles (msec):
     |  1.00th=[   19],  5.00th=[   19], 10.00th=[   19], 20.00th=[   20],
     | 30.00th=[   21], 40.00th=[   21], 50.00th=[   21], 60.00th=[   23],
     | 70.00th=[   23], 80.00th=[   24], 90.00th=[   24], 95.00th=[   24],
     | 99.00th=[   39], 99.50th=[  157], 99.90th=[  293], 99.95th=[  469],
     | 99.99th=[  469]
    bw (KB  /s): min=14927, max=51397, per=100.00%, avg=44248.69, stdev=8151.54
    lat (msec) : 20=21.78%, 50=77.25%, 100=0.29%, 250=0.49%, 500=0.20%
  cpu          : usr=0.12%, sys=1.53%, ctx=1032, majf=0, minf=6
  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    : total=r=0/w=1024/d=0, short=r=0/w=0/d=0
Rand-Read-512K: (groupid=2, jobs=1): err= 0: pid=22308: Sat Oct  7 20:49:46 2017
  read : io=1024.0MB, bw=21601KB/s, iops=42, runt= 48542msec
    slat (usec): min=53, max=243, avg=76.00, stdev=19.93
    clat (msec): min=2, max=174, avg=23.62, stdev=22.31
     lat (msec): min=2, max=174, avg=23.69, stdev=22.31
    clat percentiles (msec):
     |  1.00th=[   12],  5.00th=[   14], 10.00th=[   15], 20.00th=[   17],
     | 30.00th=[   18], 40.00th=[   19], 50.00th=[   20], 60.00th=[   21],
     | 70.00th=[   23], 80.00th=[   24], 90.00th=[   25], 95.00th=[   29],
     | 99.00th=[  149], 99.50th=[  155], 99.90th=[  165], 99.95th=[  167],
     | 99.99th=[  176]
    bw (KB  /s): min= 7543, max=29056, per=100.00%, avg=21604.89, stdev=3628.39
    lat (msec) : 4=0.05%, 10=0.24%, 20=51.42%, 50=45.02%, 100=0.05%
    lat (msec) : 250=3.22%
  cpu          : usr=0.11%, sys=0.36%, ctx=2054, majf=0, minf=133
  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    : total=r=2048/w=0/d=0, short=r=0/w=0/d=0
Rand-Write-512K: (groupid=3, jobs=1): err= 0: pid=24111: Sat Oct  7 20:49:46 2017
  write: io=1024.0MB, bw=25089KB/s, iops=49, runt= 41795msec
    slat (usec): min=115, max=548, avg=175.90, stdev=61.24
    clat (msec): min=2, max=480, avg=20.22, stdev=33.05
     lat (msec): min=2, max=480, avg=20.40, stdev=33.05
    clat percentiles (msec):
     |  1.00th=[    3],  5.00th=[    3], 10.00th=[    3], 20.00th=[   12],
     | 30.00th=[   14], 40.00th=[   15], 50.00th=[   15], 60.00th=[   16],
     | 70.00th=[   17], 80.00th=[   18], 90.00th=[   21], 95.00th=[   45],
     | 99.00th=[  182], 99.50th=[  192], 99.90th=[  281], 99.95th=[  293],
     | 99.99th=[  482]
    bw (KB  /s): min= 5595, max=38074, per=100.00%, avg=25232.44, stdev=4685.69
    lat (msec) : 4=16.31%, 10=1.81%, 20=71.53%, 50=6.25%, 100=0.44%
    lat (msec) : 250=3.52%, 500=0.15%
  cpu          : usr=0.12%, sys=0.90%, ctx=2058, majf=0, minf=6
  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    : total=r=0/w=2048/d=0, short=r=0/w=0/d=0
Rand-Read-4K: (groupid=4, jobs=1): err= 0: pid=25889: Sat Oct  7 20:49:46 2017
  read : io=22504KB, bw=384042B/s, iops=93, runt= 60004msec
    slat (usec): min=5, max=93, avg=18.98, stdev= 7.17
    clat (usec): min=142, max=327710, avg=10639.50, stdev=17862.58
     lat (usec): min=159, max=327718, avg=10658.76, stdev=17862.45
    clat percentiles (msec):
     |  1.00th=[    3],  5.00th=[    4], 10.00th=[    4], 20.00th=[    5],
     | 30.00th=[    6], 40.00th=[    8], 50.00th=[    9], 60.00th=[   10],
     | 70.00th=[   11], 80.00th=[   12], 90.00th=[   13], 95.00th=[   14],
     | 99.00th=[  130], 99.50th=[  135], 99.90th=[  147], 99.95th=[  206],
     | 99.99th=[  330]
    bw (KB  /s): min=  145, max=  508, per=100.00%, avg=375.02, stdev=53.33
    lat (usec) : 250=0.09%, 500=0.07%
    lat (msec) : 2=0.48%, 4=11.96%, 10=52.08%, 20=33.26%, 50=0.09%
    lat (msec) : 100=0.11%, 250=1.83%, 500=0.04%
  cpu          : usr=0.10%, sys=0.31%, ctx=5630, majf=0, minf=7
  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    : total=r=5626/w=0/d=0, short=r=0/w=0/d=0
Rand-Write-4K: (groupid=5, jobs=1): err= 0: pid=28574: Sat Oct  7 20:49:46 2017
  write: io=51680KB, bw=880948B/s, iops=215, runt= 60072msec
    slat (usec): min=4, max=926, avg=21.99, stdev=12.71
    clat (usec): min=141, max=854701, avg=4620.63, stdev=19135.86
     lat (usec): min=145, max=854726, avg=4642.94, stdev=19136.00
    clat percentiles (usec):
     |  1.00th=[  175],  5.00th=[  213], 10.00th=[  788], 20.00th=[ 2512],
     | 30.00th=[ 2832], 40.00th=[ 3056], 50.00th=[ 3248], 60.00th=[ 3472],
     | 70.00th=[ 3728], 80.00th=[ 4048], 90.00th=[ 4512], 95.00th=[ 5088],
     | 99.00th=[15168], 99.50th=[144384], 99.90th=[162816], 99.95th=[166912],
     | 99.99th=[847872]
    bw (KB  /s): min=    5, max= 1852, per=100.00%, avg=884.71, stdev=236.49
    lat (usec) : 250=7.62%, 500=0.29%, 750=1.57%, 1000=1.66%
    lat (msec) : 2=1.06%, 4=66.23%, 10=19.70%, 20=0.99%, 50=0.06%
    lat (msec) : 100=0.02%, 250=0.76%, 500=0.01%, 750=0.01%, 1000=0.02%
  cpu          : usr=0.28%, sys=0.74%, ctx=12940, majf=0, minf=7
  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    : total=r=0/w=12920/d=0, short=r=0/w=0/d=0
Rand-Read-4K-QD32: (groupid=6, jobs=1): err= 0: pid=31249: Sat Oct  7 20:49:46 2017
  read : io=49660KB, bw=843873B/s, iops=206, runt= 60260msec
    slat (usec): min=4, max=132, avg=18.63, stdev= 7.70
    clat (msec): min=3, max=2020, avg=155.28, stdev=199.96
     lat (msec): min=4, max=2020, avg=155.30, stdev=199.96
    clat percentiles (msec):
     |  1.00th=[    9],  5.00th=[   12], 10.00th=[   15], 20.00th=[   22],
     | 30.00th=[   33], 40.00th=[   49], 50.00th=[   74], 60.00th=[  114],
     | 70.00th=[  176], 80.00th=[  255], 90.00th=[  404], 95.00th=[  537],
     | 99.00th=[  947], 99.50th=[ 1123], 99.90th=[ 1565], 99.95th=[ 1631],
     | 99.99th=[ 2024]
    bw (KB  /s): min=   75, max= 1245, per=100.00%, avg=831.21, stdev=221.85
    lat (msec) : 4=0.01%, 10=2.68%, 20=15.65%, 50=22.22%, 100=16.56%
    lat (msec) : 250=22.38%, 500=14.34%, 750=3.97%, 1000=1.34%, 2000=0.83%
    lat (msec) : >=2000=0.02%
  cpu          : usr=0.21%, sys=0.77%, ctx=12417, majf=0, minf=37
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=99.8%, >=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.1%, 64=0.0%, >=64=0.0%
     issued    : total=r=12415/w=0/d=0, short=r=0/w=0/d=0
Rand-Write-4K-QD32: (groupid=7, jobs=1): err= 0: pid=1574: Sat Oct  7 20:49:46 2017
  write: io=52512KB, bw=894535B/s, iops=218, runt= 60112msec
    slat (usec): min=3, max=302, avg=24.09, stdev=11.05
    clat (usec): min=316, max=1302.2K, avg=146484.26, stdev=104592.54
     lat (usec): min=374, max=1302.2K, avg=146508.77, stdev=104592.55
    clat percentiles (msec):
     |  1.00th=[    6],  5.00th=[   74], 10.00th=[  100], 20.00th=[  103],
     | 30.00th=[  105], 40.00th=[  108], 50.00th=[  111], 60.00th=[  115],
     | 70.00th=[  123], 80.00th=[  239], 90.00th=[  251], 95.00th=[  262],
     | 99.00th=[  363], 99.50th=[  889], 99.90th=[ 1254], 99.95th=[ 1270],
     | 99.99th=[ 1287]
    bw (KB  /s): min=   59, max= 2294, per=100.00%, avg=893.60, stdev=276.69
    lat (usec) : 500=0.02%, 750=0.02%, 1000=0.01%
    lat (msec) : 2=0.05%, 4=0.07%, 10=4.27%, 20=0.04%, 50=0.30%
    lat (msec) : 100=5.16%, 250=79.43%, 500=9.67%, 750=0.11%, 1000=0.56%
    lat (msec) : 2000=0.30%
  cpu          : usr=0.41%, sys=0.83%, ctx=13107, majf=0, minf=5
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=99.8%, >=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.1%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=13128/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=1024.0MB, aggrb=43473KB/s, minb=43473KB/s, maxb=43473KB/s, mint=24120msec, maxt=24120msec

Run status group 1 (all jobs):
  WRITE: io=1024.0MB, aggrb=43985KB/s, minb=43985KB/s, maxb=43985KB/s, mint=23839msec, maxt=23839msec

Run status group 2 (all jobs):
   READ: io=1024.0MB, aggrb=21601KB/s, minb=21601KB/s, maxb=21601KB/s, mint=48542msec, maxt=48542msec

Run status group 3 (all jobs):
  WRITE: io=1024.0MB, aggrb=25088KB/s, minb=25088KB/s, maxb=25088KB/s, mint=41795msec, maxt=41795msec

Run status group 4 (all jobs):
   READ: io=22504KB, aggrb=375KB/s, minb=375KB/s, maxb=375KB/s, mint=60004msec, maxt=60004msec

Run status group 5 (all jobs):
  WRITE: io=51680KB, aggrb=860KB/s, minb=860KB/s, maxb=860KB/s, mint=60072msec, maxt=60072msec

Run status group 6 (all jobs):
   READ: io=49660KB, aggrb=824KB/s, minb=824KB/s, maxb=824KB/s, mint=60260msec, maxt=60260msec

Run status group 7 (all jobs):
  WRITE: io=52512KB, aggrb=873KB/s, minb=873KB/s, maxb=873KB/s, mint=60112msec, maxt=60112msec

Disk stats (read/write):
  sda: ios=21139/30361, merge=0/302, ticks=2056028/2237464, in_queue=4295252, util=98.95%

It looks to me like it's not interpreting the B/s rates correctly. I don't know enough awk to know where the problem is.

Many thanks for creating this script, though, as I'm used to Crystal Disk Mark on Windows and find raw fio output a bit overwhelming.

buty4649 commented 6 years ago

@JohnVeness Thank you for the rerport. I fixed it with https://github.com/buty4649/fio-cdm/pull/2, so try it.

JohnVeness commented 6 years ago

Many thanks, that looks like it's outputting correctly now.