Re: latency measurements when adding thinktime

[Jens Axboe <axboe@kernel.dk>]

On Fri, May 17 2013, Edoardo Comar wrote:
> Hi
> I am running a very simple randrw workload
> 
> if I uncomment the thinktime line, the latencies reported become much 
> larger.
> It doesn't make senes to me that a lower disk load results in higher 
> latencies.
> 
> can anyone please tell me if I am wrongly interpreting the output ?
> thanks!!
> 
> [global]
> size=256m
> directory=/mnt/vda2/tmp
> invalidate=1
> runtime=90
> clat_percentiles=0
> #thinktime=10000
> 
> [bgupdater]
> rw=randrw
> ioengine=libaio
> direct=1
> iodepth=16
> 
> 
> without thinktime (high KB/s) - latency about 11ms (it's an ssd drive)
> 
> bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
> iodepth=16
> fio-2.1
> Starting 1 process
> Jobs: 1 (f=1): [m] [100.0% done] [2788KB/2836KB/0KB /s] [697/709/0 iops] 
> [eta 00m:00s]
> bgupdater: (groupid=0, jobs=1): err= 0: pid=2827: Fri May 17 00:40:18 2013
>   read : io=131220KB, bw=2718.5KB/s, iops=679, runt= 48270msec
>     slat (usec): min=3, max=22626, avg=25.35, stdev=196.44
>     clat (usec): min=68, max=42871, avg=11013.43, stdev=5577.65
>      lat (usec): min=337, max=42898, avg=11039.70, stdev=5577.81
>     bw (KB  /s): min= 2051, max= 3320, per=99.85%, avg=2713.95, 
> stdev=273.34
>   write: io=130924KB, bw=2712.4KB/s, iops=678, runt= 48270msec
>     slat (usec): min=5, max=22547, avg=27.85, stdev=169.45
>     clat (usec): min=792, max=40276, avg=12491.74, stdev=6069.90
>      lat (usec): min=806, max=47342, avg=12520.54, stdev=6072.64
>     bw (KB  /s): min= 2096, max= 3209, per=99.96%, avg=2710.88, 
> stdev=210.73
>     lat (usec) : 100=0.01%, 250=0.01%, 500=0.38%, 750=1.75%, 1000=0.50%
>     lat (msec) : 2=1.03%, 4=1.02%, 10=46.23%, 20=39.03%, 50=10.06%
>   cpu          : usr=1.50%, sys=5.51%, ctx=51567, majf=0, minf=24
>   IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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.1%, 32=0.0%, 64=0.0%, 
> >=64=0.0%
>      issued    : total=r=32805/w=32731/d=0, short=r=0/w=0/d=0
> 
> Run status group 0 (all jobs):
>    READ: io=131220KB, aggrb=2718KB/s, minb=2718KB/s, maxb=2718KB/s, 
> mint=48270msec, maxt=48270msec
>   WRITE: io=130924KB, aggrb=2712KB/s, minb=2712KB/s, maxb=2712KB/s, 
> mint=48270msec, maxt=48270msec
> 
> Disk stats (read/write):
>   vda: ios=32721/32686, merge=0/30, ticks=359611/407708, in_queue=767361, 
> util=99.87%
> 
> 
> re-runing after having introduced thinktime=10000
> much lower bandwitdh, but 152ms latency !
> 
> bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
> iodepth=16
> fio-2.1
> Starting 1 process
> Jobs: 1 (f=1): [m] [100.0% done] [200KB/192KB/0KB /s] [50/48/0 iops] [eta 
> 00m:00s]
> bgupdater: (groupid=0, jobs=1): err= 0: pid=2833: Fri May 17 00:43:21 2013
>   read : io=17768KB, bw=202135B/s, iops=49, runt= 90011msec
>     slat (usec): min=6, max=166, avg=29.62, stdev=15.64
>     clat (usec): min=632, max=157715, avg=152132.61, stdev=5965.84
>      lat (usec): min=797, max=157744, avg=152163.37, stdev=5965.66
>     bw (KB  /s): min=  102, max=  276, per=99.84%, avg=196.68, stdev=27.96
>   write: io=17720KB, bw=201589B/s, iops=49, runt= 90011msec
>     slat (usec): min=8, max=164, avg=34.02, stdev=16.60
>     clat (msec): min=20, max=157, avg=152.23, stdev= 4.09
>      lat (msec): min=20, max=157, avg=152.27, stdev= 4.09
>     bw (KB  /s): min=  118, max=  291, per=100.00%, avg=196.23, 
> stdev=27.95
>     lat (usec) : 750=0.01%
>     lat (msec) : 20=0.02%, 50=0.07%, 100=0.11%, 250=99.79%
>   cpu          : usr=0.12%, sys=0.36%, ctx=8891, majf=0, minf=24
>   IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.8%, 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.1%, 32=0.0%, 64=0.0%, 
> >=64=0.0%
>      issued    : total=r=4442/w=4430/d=0, short=r=0/w=0/d=0
> 
> Run status group 0 (all jobs):
>    READ: io=17768KB, aggrb=197KB/s, minb=197KB/s, maxb=197KB/s, 
> mint=90011msec, maxt=90011msec
>   WRITE: io=17720KB, aggrb=196KB/s, minb=196KB/s, maxb=196KB/s, 
> mint=90011msec, maxt=90011msec
> 
> Disk stats (read/write):
>   vda: ios=4441/4488, merge=0/34, ticks=2965/8118, in_queue=11083, 
> util=11.64%

Could be scheduling artifacts, the thinktime will generally cause the
process to be scheduled out (or put to sleep, at least). Try and use
thinktime_spin instead. If you set that to the same value as thinktime,
then fio will busy loop instead of going to sleep. If that changes the
picture, then it would indicate that it's related to be scheduled in and
out.

-- 
Jens Axboe