fio test

gistfile1.txt

2 problems:

1. ignores runtime
2. doesn't output actual measurements (other than issued total)

[~/fio-2.0.13]# time ./fio --name=randread --rw=randread --random_distribution=pareto:0.5 --size=1g --bs=8k --runtime=10 --time_based --filename=fio.tmp 
randread: (g=0): rw=randread, bs=8K-8K/8K-8K/8K-8K, ioengine=sync, iodepth=1
fio-2.0.13
Starting 1 process
^C
fio: terminating on signal 2

randread: (groupid=0, jobs=1): err= 0: pid=18537: Sat Feb  2 02:50:03 2013
    lat (usec) : 2=100.00%
  cpu          : usr=0.00%, sys=0.00%, ctx=4776, majf=0, minf=0
  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=2274693/w=0/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):

real    0m28.465s
user    0m5.731s
sys     0m20.696s

latest version of fio (git://git.kernel.dk/fio.git) fixed many problems; --clocksource=clock_gettime fixed the runtime.

Note that this does mean a high rate of gettime calls:

# dtrace -n 'syscall:::entry /execname == "fio"/ { @[probefunc] = count(); }'
dtrace: description 'syscall:::entry ' matched 234 probes
^C

  write                                                             2
  ioctl                                                             8
  waitsys                                                         200
  nanosleep                                                       208
  llseek                                                        85056
  read                                                          85057
  clock_gettime                                                340261

Although, the CPU cost is only about 10% for this particular workload (8k random read cached), so, not as bad as the syscall count would suggest:

# dtrace -n 'syscall:::entry /execname == "fio"/ { self->ts = vtimestamp; } syscall:::return /self->ts/ { @[probefunc] = sum(vtimestamp - self->ts); self->ts = 0; }'
dtrace: description 'syscall:::entry ' matched 468 probes
^C

  write                                                        155539
  ioctl                                                        734339
  waitsys                                                     1453280
  nanosleep                                                   7008990
  llseek                                                     98417743
  clock_gettime                                             238765014
  read                                                     1842462503

It's spending most of its CPU time in read(), which is good. Numbers are nanosecond sums of CPU time during syscalls. YMMV. I should also sample this as well (other than tracing) to double check.