I am using fio-2.2.10 on Ubuntu 16.04.
In one of my setup I am observing high value of read iops at io-depth = 1. One run is reporting iops=11418, another run iops=33507 andiops=44329. This does not seem to be correct. Below are the run results.
Can someone let me know what could be going wrong and if I am hitting some known issue in fio?
RUN 1
ubuntu@vrni-proxy-release:/var/log/foundationdb$ suf=`head
/dev/urandom | tr -dc A-Za-z0-9 | head -c 13 ; echo ''` &&
file="/var/lib/ubuntu/fio-$suf" && echo $file && fio --filename=$file
--direct=1 --ioengine=libaio --bs=4K --name=bw-test --rw=randread
--iodepth=1 --size=200M ; rm -f $file
/var/lib/ubuntu/fio-oPHRC8lfJujNk
bw-test: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
fio-2.2.10
Starting 1 process
bw-test: Laying out IO file(s) (1 file(s) / 200MB)
Jobs: 1 (f=1): [r(1)] [100.0% done] [49132KB/0KB/0KB /s] [12.3K/0/0
iops] [eta 00m:00s]
bw-test: (groupid=0, jobs=1): err= 0: pid=48549: Fri May 15 18:42:08 2020 read : io=204800KB, bw=45674KB/s, iops=11418, runt= 4484msec slat (usec): min=4, max=258, avg= 5.53, stdev= 2.20 clat (usec): min=0, max=22304, avg=81.16, stdev=230.44 lat (usec): min=17, max=22309, avg=86.78, stdev=230.46 clat percentiles (usec): | 1.00th=[ 14], 5.00th=[ 14], 10.00th=[ 15], 20.00th=[ 16], | 30.00th=[ 19], 40.00th=[ 19], 50.00th=[ 20], 60.00th=[ 20], | 70.00th=[ 21], 80.00th=[ 25], 90.00th=[ 266], 95.00th=[ 286], | 99.00th=[ 532], 99.50th=[ 1400], 99.90th=[ 2832], 99.95th=[ 3088], | 99.99th=[ 5280] bw (KB /s): min=33760, max=51584, per=98.18%, avg=44842.00, stdev=6783.12 lat (usec) : 2=0.04%, 4=0.01%, 10=0.02%, 20=45.62%, 50=35.21% lat (usec) : 100=0.15%, 250=2.24%, 500=15.67%, 750=0.25%, 1000=0.16% lat (msec) : 2=0.28%, 4=0.34%, 10=0.01%, 50=0.01% cpu : usr=0.98%, sys=10.53%, ctx=51195, majf=0, minf=10 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=51200/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=1
Run status group 0 (all jobs): READ: io=204800KB, aggrb=45673KB/s, minb=45673KB/s, maxb=45673KB/s,
mint=4484msec, maxt=4484msec
Disk stats (read/write): dm-6: ios=48310/2, merge=0/0, ticks=3944/0, in_queue=3972,
util=90.95%, aggrios=51200/40, aggrmerge=0/205, aggrticks=4048/0,
aggrin_queue=4048, aggrutil=87.75% sda: ios=51200/40, merge=0/205, ticks=4048/0, in_queue=4048, util=87.75%RUN 2
ubuntu@vrni-proxy-release:/var/log/foundationdb$ suf=`head
/dev/urandom | tr -dc A-Za-z0-9 | head -c 13 ; echo ''` &&
file="/var/lib/ubuntu/fio-$suf" && echo $file && fio --filename=$file
--direct=1 --ioengine=libaio --bs=4K --name=bw-test --rw=randread
--iodepth=1 --size=200M ; rm -f $file
/var/lib/ubuntu/fio-PipAwOU94ybHL
bw-test: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
fio-2.2.10
Starting 1 process
bw-test: Laying out IO file(s) (1 file(s) / 200MB)
Jobs: 1 (f=1)
bw-test: (groupid=0, jobs=1): err= 0: pid=48575: Fri May 15 18:42:15 2020 read : io=204800KB, bw=134031KB/s, iops=33507, runt= 1528msec slat (usec): min=4, max=19840, avg= 5.38, stdev=87.66 clat (usec): min=1, max=3589, avg=23.64, stdev=89.84 lat (usec): min=17, max=19863, avg=29.07, stdev=125.52 clat percentiles (usec): | 1.00th=[ 14], 5.00th=[ 15], 10.00th=[ 15], 20.00th=[ 15], | 30.00th=[ 15], 40.00th=[ 15], 50.00th=[ 16], 60.00th=[ 16], | 70.00th=[ 16], 80.00th=[ 16], 90.00th=[ 17], 95.00th=[ 17], | 99.00th=[ 286], 99.50th=[ 318], 99.90th=[ 1576], 99.95th=[ 2352], | 99.99th=[ 3056] bw (KB /s): min=119592, max=143792, per=99.48%, avg=133333.33,
stdev=12429.48 lat (usec) : 2=0.01%, 10=0.01%, 20=97.54%, 50=0.47%, 100=0.09% lat (usec) : 250=0.05%, 500=1.61%, 750=0.06%, 1000=0.02% lat (msec) : 2=0.06%, 4=0.08% cpu : usr=1.83%, sys=31.17%, ctx=51196, majf=0, minf=11 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=51200/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=1
Run status group 0 (all jobs): READ: io=204800KB, aggrb=134031KB/s, minb=134031KB/s,
maxb=134031KB/s, mint=1528msec, maxt=1528msec
Disk stats (read/write): dm-6: ios=43347/0, merge=0/0, ticks=1080/0, in_queue=1084,
util=75.80%, aggrios=51200/10, aggrmerge=0/6, aggrticks=1048/0,
aggrin_queue=1048, aggrutil=62.83% sda: ios=51200/10, merge=0/6, ticks=1048/0, in_queue=1048, util=62.83%1 Answer
I see you're using direct=1 (which will request O_DIRECT) but you seem to be using a file in a filesystem... Did you know there's no guarantee that O_DIRECT will bypass the buffer cache on all possible filesystem configurations?
A warning sign is:
clat (usec): min=1, max=3589, avg=23.64, stdev=89.84Can your SATA/SCSI disk really complete an I/O in one microsecond? If not then it's likely you were reading out of the kernel cache. However we also see this on RUN 2:
[...] issued : total=r=51200/w=0/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0
[...]
Disk stats (read/write):
[...] sda: ios=51200/10, merge=0/6, ticks=1048/0, in_queue=1048, util=62.83%(The "Disk stats" tell us kernel block device statistics for the duration the job was running and in this example sda is likely the block device for the "real" disk)
So the disk was sent 51200 I/Os which matches the number fio originally sent so maybe something else is going on? The area I/O is being done over is tiny (200MBytes) so maybe some part of it resides in the disk's own cache? It may be wise to do a test which involved sending I/O over a greater area (10s of gigabytes) to eliminate the effect of such caches. Also the test doesn't run for very long (4 seconds) so if some writes were being sent (hint: the disk I/O stats are in terms of reads/writes) then you may be seeing interference (take note of the util stat).
Without knowing more about your exact setup (e.g. filesystem, filesystem configuration, disk type, disk condition etc.) it's hard for a passerby to say anything definitive.
TLDR; It's unlikely to be an fio issue (but fio 2.2.10 is extremely old - ).
NB: According to a comment it looks like the questioner achieved more stable results by running a longer test on a bigger region of 1GByte.
6
