0

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

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.84

Can 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 - https://github.com/axboe/fio/releases ).

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.

| improve this answer | |
  • Thanks for a detailed answer. Few doubts I see you're using direct=1 (which will request O_DIRECT) but you seem to be using a file in a filesystem - Is there any other way to do a read without using a file from a filesystem? . Also the test doesn't run for very long (4 seconds) so if some writes were being sent then you may be seeing interference - I did not get this properly. Can you explain this a bit more? Is there a way to bypass the disk cache or kernel cache? – tuk May 21 at 13:19
  • The other way is to go against a block device directly but this is DANGEROUS and prone to DATA LOSS so don't do it on disks/partitions with real data that you can't afford to be IRRECOVERABLY DESTROYED. For the later point is saying doing a small amount of I/O means a small disturbance has a big impact. If you use an area is at least 3 times the size of memory and run I/O for longer you reduce the benefit of cache and small effects. – Anon May 21 at 20:52
  • Thanks again. If you use an area is at least 3 times the size of memory and run I/O for longer you reduce the benefit of cache and small effects. If I get you correctly so if I am having a RAM of 32 GB then I should be reading a file of 96 GB ? – tuk May 22 at 5:52
  • Yes. Assuming no compression, you are now guaranteeing only one third of your I/O could be cached in RAM by the kernel in the perfect case so you know the other two thirds must be going to disk (maybe only double would also be good enough but you'll have to see for yourself). Additionally that size will far exceed a disk's own on-board cache. I'd likely avoid removing a file that large until I had done my last run though as setup time will be much higher than before. – Anon May 22 at 6:45
  • I have increased the size of file to 1GB and things do not look erratic as of now. – tuk May 23 at 16:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.