Bonnie isn't that good at characterizing system IO rates
By joe
- 4 minutes read - 850 wordsI started thinking about bonnie’s IO after looking at some of the numbers, and how the system behaved while running the tool. Fio is much better and more controllable tool. You can understand what it is doing. And you can use it to model bonnie, and therefore understand what bonnie is and isn’t doing.
In short, while running bonnie++, I found the core machine stats, as seen in vmstat, dstat, iostat, and other tools, to be basically idle during the writes. That is, data wasn’t getting efficiently from the user space buffers onto disks. So I modeled bonnie using fio to see if I could replicate the results.
[streaming-write]
rw=write
size=96g
directory=/data
iodepth=1
blocksize=1024k
numjobs=1
nrfiles=1
loops=1
create_serialize=0
group_reporting
[streaming-readwrite]
stonewall
create_serialize=0
loops=1
rw=rw
size=96g
directory=/data
iodepth=1
direct=0
blocksize=1024k
numjobs=1
nrfiles=1
group_reporting
[streaming-read]
stonewall
create_serialize=0
loops=1
rw=read
size=96g
directory=/data
iodepth=1
direct=0
blocksize=1024k
numjobs=1
nrfiles=1
group_reporting
This will do it. Copy the above to bonnie.fio, and run
fio bonnie.fio
You will get output that matches some of what bonnie reports. Ok, the writes are different. The read/write is quite similar. The reads are different. This assumes you run bonnie as
bonnie++ -u root -d /data -s 96g:1024k -f
Here is the bonnie output
[root@jr4s ~]# bonnie++ -u root -d /data -s 96g:1024k -f
Using uid:0, gid:0.
Writing intelligently...done
Rewriting... done
Reading intelligently...done
start 'em...done...done...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version 1.94 ------Sequential Output------ --Sequential Input- --Random-
Concurrency 1 -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine Size:chnk K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP /sec %CP
jr4s 96G:1m 102805 9 249906 29 599950 36 157.0 52
Latency 4081ms 1499ms 1339ms 3289ms
Version 1.94 ------Sequential Create------ --------Random Create--------
jr4s -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
files /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP
16 11262 48 +++++ +++ 25964 88 12145 39 +++++ +++ 5352 31
Latency 41559us 1358us 1469us 21744us 10us 39535us
1.93c,1.94,jr4s,1,1247278563,96G,1m,,,102805,9,249906,29,,,599950,36,157.0,52,16,,,,,11262,48,+++++,+++,25964,88,12145,39,+++++,+++,5352,31,,4081ms,1499ms,,1339ms,3289ms,41559us,1358us,1469us,21744us,10us,39535us
There are significant sections where little actual IO is fed to the OS from the application, as can be seen by observing the machine state using the tools I indicated. Here is the fio output for this bonnie.fio run
[root@jr4s ~]# fio bonnie.fio
streaming-write: (g=0): rw=write, bs=1M-1M/1M-1M, ioengine=sync, iodepth=1
streaming-readwrite: (g=1): rw=rw, bs=1M-1M/1M-1M, ioengine=sync, iodepth=1
streaming-read: (g=2): rw=read, bs=1M-1M/1M-1M, ioengine=sync, iodepth=1
Starting 3 processes
Jobs: 1 (f=1): [__R] [99.7% done] [780140/ 0 kb/s] [eta 00m:02s]
streaming-write: (groupid=0, jobs=1): err= 0: pid=10789
write: io=98,304MiB, bw=612MiB/s, iops=597, runt=164567msec
clat (usec): min=448, max=4,864K, avg=1618.42, stdev=29973.80
bw (KiB/s) : min= 0, max=1795162, per=121.97%, avg=763970.86, stdev=318417.79
cpu : usr=0.12%, sys=50.68%, ctx=3011534, majf=0, minf=1174
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: total=0/98304, short=0/0
lat (usec): 500=2.68%, 750=26.84%, 1000=22.58%
lat (msec): 2=43.03%, 4=3.96%, 10=0.73%, 20=0.11%, 50=0.01%
lat (msec): 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2000=0.02%, >=2000=0.01%
streaming-readwrite: (groupid=1, jobs=1): err= 0: pid=10811
read : io=49,152MiB, bw=102MiB/s, iops=99, runt=493992msec
clat (usec): min=178, max=2,076K, avg=5990.38, stdev=31565.52
bw (KiB/s) : min= 505, max=429916, per=107.73%, avg=112391.77, stdev=83309.91
write: io=49,152MiB, bw=102MiB/s, iops=99, runt=493789msec
clat (usec): min=398, max=1,400K, avg=4017.14, stdev=20847.25
bw (KiB/s) : min= 0, max=377487, per=108.55%, avg=113302.61, stdev=82851.97
cpu : usr=0.05%, sys=14.45%, ctx=344641, majf=0, minf=91
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: total=49152/49152, short=0/0
lat (usec): 250=18.81%, 500=20.83%, 750=22.96%, 1000=3.90%
lat (msec): 2=6.85%, 4=6.65%, 10=9.53%, 20=4.64%, 50=4.59%
lat (msec): 100=0.80%, 250=0.29%, 500=0.10%, 750=0.03%, 1000=0.01%
lat (msec): 2000=0.01%, >=2000=0.01%
streaming-read: (groupid=2, jobs=1): err= 0: pid=10824
read : io=98,304MiB, bw=729MiB/s, iops=712, runt=138010msec
clat (usec): min=177, max=528K, avg=1400.23, stdev=3408.98
bw (KiB/s) : min=16792, max=994050, per=100.27%, avg=748936.28, stdev=118855.87
cpu : usr=0.10%, sys=40.61%, ctx=61875, majf=0, minf=271
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: total=98304/0, short=0/0
lat (usec): 250=47.94%, 500=21.04%, 750=2.84%, 1000=1.16%
lat (msec): 2=3.85%, 4=10.68%, 10=11.22%, 20=1.21%, 50=0.04%
lat (msec): 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
Run status group 0 (all jobs):
WRITE: io=98,304MiB, aggrb=612MiB/s, minb=612MiB/s, maxb=612MiB/s, mint=164567msec, maxt=164567msec
Run status group 1 (all jobs):
READ: io=49,152MiB, aggrb=102MiB/s, minb=102MiB/s, maxb=102MiB/s, mint=493992msec, maxt=493992msec
WRITE: io=49,152MiB, aggrb=102MiB/s, minb=102MiB/s, maxb=102MiB/s, mint=493789msec, maxt=493789msec
Run status group 2 (all jobs):
READ: io=98,304MiB, aggrb=729MiB/s, minb=729MiB/s, maxb=729MiB/s, mint=138010msec, maxt=138010msec
Disk stats (read/write):
md0: ios=1324262/12508426, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
Why the read and write are so different is troubling. The disks are definitely not idle during fio, and you can see the data flow rates from the tools. Unlike bonnie, which has widely varying rates. fio also lets me specify larger buffers, use direct IO, use a variety of buffering mechanisms, so I can use this to optimize IO. A good measurement tool gives you insight from your measurement. I am not getting insight from bonnie into the machine performance. Especially when bonnie thinks its working and the machine notes otherwise.