Hi
I am trying to understand fio latency numbers.
Would be great if you can clarify why latency numbers are inconsistent.
Here is sample fio output:
read_lat: (g=0): rw=randread, bs=512-512/512-512/512-512,
ioengine=libaio, iodepth=1
fio-2.1.10
Starting 1 thread
read_lat: (groupid=0, jobs=1): err= 0: pid=10848: Mon Jul 11 13:34:27 2016
read : io=7541.2MB, bw=12870KB/s, iops=25740, runt=600001msec
slat (usec): min=3, max=62, avg= 3.95, stdev= 0.37
clat (usec): min=0, max=12053, avg=34.19, stdev=24.21
lat (usec): min=28, max=12057, avg=38.24, stdev=24.21
clat percentiles (usec):
| 1.00th=[ 25], 5.00th=[ 26], 10.00th=[ 26], 20.00th=[ 26],
| 30.00th=[ 26], 40.00th=[ 26], 50.00th=[ 26], 60.00th=[ 27],
| 70.00th=[ 27], 80.00th=[ 27], 90.00th=[ 91], 95.00th=[ 106],
| 99.00th=[ 112], 99.50th=[ 112], 99.90th=[ 118], 99.95th=[ 120],
| 99.99th=[ 129]
bw (KB /s): min=11701, max=13161, per=100.00%, avg=12870.89, stdev=114.55
lat (usec) : 2=0.01%, 10=0.01%, 20=0.01%, 50=89.85%, 100=5.02%
lat (usec) : 250=5.12%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=5.91%, sys=13.98%, ctx=15444904, majf=0, minf=8
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=15444203/w=0/d=0, short=r=0/w=0/d=0
latency : target=0, window=0, percentile=100.00%, depth=1
Run status group 0 (all jobs):
READ: io=7541.2MB, aggrb=12870KB/s, minb=12870KB/s, maxb=12870KB/s,
mint=600001msec, maxt=600001msec
Disk stats (read/write):
sdb: ios=15440539/0, merge=0/0, ticks=506729/0, in_queue=504796, util=84.17%
>From output:
Run time = 600001 ms
queue depth = 1
performed IO = 25740
So correct me if i am wrong, but 600001 / 25740 = 23.31 ms
However, fio reports an average latency of 38.24 ms.
Should those numbers be consistent?
Thanks
--
Lucas
read_lat: (g=0): rw=randread, bs=512-512/512-512/512-512, ioengine=libaio, iodepth=1
fio-2.1.10
Starting 1 thread
read_lat: (groupid=0, jobs=1): err= 0: pid=10848: Mon Jul 11 13:34:27 2016
read : io=7541.2MB, bw=12870KB/s, iops=25740, runt=600001msec
slat (usec): min=3, max=62, avg= 3.95, stdev= 0.37
clat (usec): min=0, max=12053, avg=34.19, stdev=24.21
lat (usec): min=28, max=12057, avg=38.24, stdev=24.21
clat percentiles (usec):
| 1.00th=[ 25], 5.00th=[ 26], 10.00th=[ 26], 20.00th=[ 26],
| 30.00th=[ 26], 40.00th=[ 26], 50.00th=[ 26], 60.00th=[ 27],
| 70.00th=[ 27], 80.00th=[ 27], 90.00th=[ 91], 95.00th=[ 106],
| 99.00th=[ 112], 99.50th=[ 112], 99.90th=[ 118], 99.95th=[ 120],
| 99.99th=[ 129]
bw (KB /s): min=11701, max=13161, per=100.00%, avg=12870.89, stdev=114.55
lat (usec) : 2=0.01%, 10=0.01%, 20=0.01%, 50=89.85%, 100=5.02%
lat (usec) : 250=5.12%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=5.91%, sys=13.98%, ctx=15444904, majf=0, minf=8
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=15444203/w=0/d=0, short=r=0/w=0/d=0
latency : target=0, window=0, percentile=100.00%, depth=1
Run status group 0 (all jobs):
READ: io=7541.2MB, aggrb=12870KB/s, minb=12870KB/s, maxb=12870KB/s, mint=600001msec, maxt=600001msec
Disk stats (read/write):
sdb: ios=15440539/0, merge=0/0, ticks=506729/0, in_queue=504796, util=84.17%
