Bonnie isn't that good at characterizing system IO rates

By joe

July 11, 2009 - 4 minutes read - 850 words

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