latency measurements when adding thinktime

Flexible I/O Tester development
 help / color / mirror / Atom feed

* latency measurements when adding thinktime
@ 2013-05-17  0:00 Edoardo Comar
  2013-05-17  7:47 ` Jens Axboe
  0 siblings, 1 reply; 9+ messages in thread
From: Edoardo Comar @ 2013-05-17  0:00 UTC (permalink / raw)
  To: fio

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%

--------------------------------------------------
regards,
Edoardo Comar
WebSphere Application Service Platform for Networks (ASPN)
ecomar@uk.ibm.com
+44 (0)1962 81 5576 
IBM UK Ltd, Hursley Park, SO21 2JN

Unless stated otherwise above:
IBM United Kingdom Limited - Registered in England and Wales with number 
741598. 
Registered office: PO Box 41, North Harbour, Portsmouth, Hampshire PO6 3AU


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17  0:00 latency measurements when adding thinktime Edoardo Comar
@ 2013-05-17  7:47 ` Jens Axboe
  2013-05-17  9:24   ` Edoardo Comar
  0 siblings, 1 reply; 9+ messages in thread
From: Jens Axboe @ 2013-05-17  7:47 UTC (permalink / raw)
  To: Edoardo Comar; +Cc: fio

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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17  7:47 ` Jens Axboe
@ 2013-05-17  9:24   ` Edoardo Comar
  2013-05-17 10:22     ` Jens Axboe
  0 siblings, 1 reply; 9+ messages in thread
From: Edoardo Comar @ 2013-05-17  9:24 UTC (permalink / raw)
  To: Jens Axboe, fio

Hi Jens,

thanks a lot, I tried your suggestion straight away: 
The cpu line in the output shows that the job has not been idle at all.
but even with thinktime_spin, the latency stays high at at 150ms.

Note also that if I increase thinktime & thinktime_spin by another 10000 
us
to a total of 20000, then the reported latency goes up another 150ms to a 
total of 300ms.
Could this be a bug?

regards,
Edoardo.


The system is a RHEL 64 VM running in KVM-QEMU on a Fedora18 Host.
# uname -a
Linux vm25 2.6.32-358.el6.x86_64 #1 SMP Tue Jan 29 11:47:41 EST 2013 
x86_64 x86_64 x86_64 GNU/Linux
----------------------------------------------------------------------------------------
# THINK=10000

# cat four-threads-randio-012.fio 
[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=90
#bs=8k
clat_percentiles=0
thinktime=10000
thinktime_spin=10000
#rate=300k

[bgupdater]
rw=randrw
ioengine=libaio
direct=1
iodepth=16


 #./fio four-threads-randio-012.fio 
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] [192KB/208KB/0KB /s] [48/52/0 iops] [eta 
00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=3102: Fri May 17 10:06:29 2013
  read : io=18012KB, bw=204929B/s, iops=50, runt= 90003msec
    slat (usec): min=6, max=111, avg=14.74, stdev= 6.01
    clat (usec): min=727, max=150438, avg=150061.39, stdev=5468.92
     lat (usec): min=823, max=150453, avg=150076.69, stdev=5468.58
    bw (KB  /s): min=  103, max=  272, per=99.64%, avg=199.28, stdev=28.41
  write: io=17972KB, bw=204474B/s, iops=49, runt= 90003msec
    slat (usec): min=9, max=85, avg=17.45, stdev= 6.01
    clat (msec): min=10, max=150, avg=150.08, stdev= 4.47
     lat (msec): min=10, max=150, avg=150.10, stdev= 4.47
    bw (KB  /s): min=  127, max=  295, per=99.94%, avg=198.88, stdev=28.25
    lat (usec) : 750=0.01%
    lat (msec) : 20=0.02%, 50=0.07%, 100=0.11%, 250=99.79%
  cpu          : usr=25.32%, sys=74.51%, ctx=9646, 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=4503/w=4493/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=18012KB, aggrb=200KB/s, minb=200KB/s, maxb=200KB/s, 
mint=90003msec, maxt=90003msec
  WRITE: io=17972KB, aggrb=199KB/s, minb=199KB/s, maxb=199KB/s, 
mint=90003msec, maxt=90003msec

Disk stats (read/write):
  vda: ios=4501/4551, merge=0/35, ticks=2337/7267, in_queue=9601, 
util=10.40%


------------------------------------------------------------------------------------------------------------------------------------
# THINK=20000

# cat four-threads-randio-012.fio 
[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=90
#bs=8k
clat_percentiles=0
thinktime=20000
thinktime_spin=20000
#rate=300k

[bgupdater]
rw=randrw
ioengine=libaio
direct=1
iodepth=16


./fio four-threads-randio-012.fio 
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] [128KB/72KB/0KB /s] [32/18/0 iops] [eta 
00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=3109: Fri May 17 10:19:17 2013
  read : io=9240.0KB, bw=105108B/s, iops=25, runt= 90019msec
    slat (usec): min=6, max=106, avg=14.51, stdev= 4.33
    clat (usec): min=592, max=300425, avg=299037.78, stdev=17053.15
     lat (usec): min=645, max=300443, avg=299052.89, stdev=17053.12
    bw (KB  /s): min=   56, max=  152, per=100.00%, avg=102.21, 
stdev=19.77
  write: io=8804.0KB, bw=100148B/s, iops=24, runt= 90019msec
    slat (usec): min=8, max=110, avg=17.58, stdev= 7.68
    clat (msec): min=20, max=300, avg=299.64, stdev=10.12
     lat (msec): min=20, max=300, avg=299.66, stdev=10.12
    bw (KB  /s): min=   48, max=  144, per=100.00%, avg=97.83, stdev=19.76
    lat (usec) : 750=0.02%
    lat (msec) : 50=0.09%, 100=0.09%, 250=0.35%, 500=99.45%
  cpu          : usr=25.09%, sys=74.74%, ctx=9647, majf=0, minf=24
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=99.7%, 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=2310/w=2201/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=9240KB, aggrb=102KB/s, minb=102KB/s, maxb=102KB/s, 
mint=90019msec, maxt=90019msec
  WRITE: io=8804KB, aggrb=97KB/s, minb=97KB/s, maxb=97KB/s, 
mint=90019msec, maxt=90019msec

Disk stats (read/write):
  vda: ios=2307/2257, merge=0/35, ticks=1228/3715, in_queue=4940, 
util=5.20%
--------------------------------------------------
regards,
Edoardo Comar
WebSphere Application Service Platform for Networks (ASPN)
ecomar@uk.ibm.com
+44 (0)1962 81 5576 
IBM UK Ltd, Hursley Park, SO21 2JN




From:   Jens Axboe <axboe@kernel.dk>
To:     Edoardo Comar/UK/IBM@IBMGB, 
Cc:     fio@vger.kernel.org
Date:   17/05/2013 08:47
Subject:        Re: latency measurements when adding thinktime



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



Unless stated otherwise above:
IBM United Kingdom Limited - Registered in England and Wales with number 
741598. 
Registered office: PO Box 41, North Harbour, Portsmouth, Hampshire PO6 3AU



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17  9:24   ` Edoardo Comar
@ 2013-05-17 10:22     ` Jens Axboe
  2013-05-17 10:38       ` Edoardo Comar
  2013-05-17 10:43       ` Jens Axboe
  0 siblings, 2 replies; 9+ messages in thread
From: Jens Axboe @ 2013-05-17 10:22 UTC (permalink / raw)
  To: Edoardo Comar; +Cc: fio

On Fri, May 17 2013, Edoardo Comar wrote:
> Hi Jens,
> 
> thanks a lot, I tried your suggestion straight away: 
> The cpu line in the output shows that the job has not been idle at all.
> but even with thinktime_spin, the latency stays high at at 150ms.
> 
> Note also that if I increase thinktime & thinktime_spin by another 10000 
> us
> to a total of 20000, then the reported latency goes up another 150ms to a 
> total of 300ms.
> Could this be a bug?

It certainly could. Let me take a look here and see if I can reproduce
it.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17 10:22     ` Jens Axboe
@ 2013-05-17 10:38       ` Edoardo Comar
  2013-05-17 10:43       ` Jens Axboe
  1 sibling, 0 replies; 9+ messages in thread
From: Edoardo Comar @ 2013-05-17 10:38 UTC (permalink / raw)
  To: Jens Axboe, fio

Thans Jens

FYI, I have run the load on the host too (previoulsy it was inside a VM), 
using the HDD and the SSD.
The effect on latency are essentially the same when thinktime and 
thinktime_spin are introduced
using both fio 2.0.13 and fio 2.1

THINK=0 HDD             read lat avg=21400.59 us
THINK=10000 HDD         read lat avg=149.99 ms
THINK=20000 HDD read lat avg=299.33 ms
THINK=0         SDD     read lat avg=1998.09 us
THINK=20000 SDD read lat avg=299.33 ms


[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=90
#bs=8k
clat_percentiles=0
thinktime=20000
thinktime_spin=20000
#rate=300k

[bgupdater]
rw=randrw
ioengine=libaio
direct=1
iodepth=16



==================================

THINK=0 HDD
[root@twix0208 fio]# ./fio four-threads-randio-012.fio 
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
iodepth=16
fio-2.0.13
Starting 1 process
bgupdater: Laying out IO file(s) (1 file(s) / 256MB)
Jobs: 1 (f=1): [m] [100.0% done] [1202K/1086K/0K /s] [300 /271 /0  iops] 
[eta 00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=21936: Fri May 17 10:37:12 
2013
  read : io=107324KB, bw=1191.1KB/s, iops=297 , runt= 90042msec
    slat (usec): min=5 , max=62744 , avg=36.99, stdev=705.24
    clat (usec): min=39 , max=719439 , avg=21363.06, stdev=37310.18
     lat (usec): min=346 , max=719470 , avg=21400.59, stdev=37313.22
    bw (KB/s)  : min=  846, max= 1440, per=100.00%, avg=1192.70, 
stdev=101.75
  write: io=109204KB, bw=1212.9KB/s, iops=303 , runt= 90042msec
    slat (usec): min=6 , max=142595 , avg=48.04, stdev=1341.40
    clat (usec): min=861 , max=997553 , avg=31676.66, stdev=48625.06
     lat (usec): min=888 , max=997583 , avg=31725.21, stdev=48655.16
    bw (KB/s)  : min=  910, max= 1440, per=100.00%, avg=1214.42, 
stdev=96.44
    lat (usec) : 50=0.01%, 100=0.01%, 250=0.01%, 500=0.01%, 1000=0.04%
    lat (msec) : 2=2.36%, 4=12.19%, 10=29.96%, 20=21.36%, 50=20.79%
    lat (msec) : 100=8.03%, 250=4.61%, 500=0.60%, 750=0.04%, 1000=0.01%
  cpu          : usr=0.48%, sys=1.73%, ctx=55440, majf=0, minf=21
  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=26831/w=27301/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=107324KB, aggrb=1191KB/s, minb=1191KB/s, maxb=1191KB/s, 
mint=90042msec, maxt=90042msec
  WRITE: io=109204KB, aggrb=1212KB/s, minb=1212KB/s, maxb=1212KB/s, 
mint=90042msec, maxt=90042msec

Disk stats (read/write):
    dm-1: ios=26829/27522, merge=0/0, ticks=569051/1195726, 
in_queue=1765761, util=99.99%, aggrios=26830/27415, aggrmerge=1/118, 
aggrticks=569586/1150587, aggrin_queue=1720087, aggrutil=99.97%
  sda: ios=26830/27415, merge=1/118, ticks=569586/1150587, 
in_queue=1720087, util=99.97%
============================================================================
THINK=10000 HDD
[root@twix0208 fio]# ./fio four-threads-randio-012.fio 
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
iodepth=16
fio-2.0.13
Starting 1 process
Jobs: 1 (f=1): [m] [100.0% done] [212K/188K/0K /s] [53 /47 /0  iops] [eta 
00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=23668: Fri May 17 11:06:01 
2013
  read : io=18052KB, bw=205368 B/s, iops=50 , runt= 90010msec
    slat (usec): min=7 , max=5130 , avg=11.93, stdev=93.13
    clat (msec): min=10 , max=196 , avg=149.98, stdev= 4.92
     lat (msec): min=10 , max=196 , avg=149.99, stdev= 4.92
    bw (KB/s)  : min=  136, max=  280, per=100.00%, avg=200.20, 
stdev=30.23
  write: io=17956KB, bw=204276 B/s, iops=49 , runt= 90010msec
    slat (usec): min=9 , max=3915 , avg=12.88, stdev=72.14
    clat (msec): min=6 , max=170 , avg=149.98, stdev= 5.01
     lat (msec): min=6 , max=170 , avg=149.99, stdev= 5.01
    bw (KB/s)  : min=  120, max=  264, per=100.00%, avg=199.70, 
stdev=30.26
    lat (msec) : 10=0.01%, 20=0.02%, 50=0.07%, 100=0.12%, 250=99.78%
  cpu          : usr=96.46%, sys=0.10%, ctx=9362, majf=0, minf=22
  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=4513/w=4489/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=18052KB, aggrb=200KB/s, minb=200KB/s, maxb=200KB/s, 
mint=90010msec, maxt=90010msec
  WRITE: io=17956KB, aggrb=199KB/s, minb=199KB/s, maxb=199KB/s, 
mint=90010msec, maxt=90010msec

Disk stats (read/write):
    dm-1: ios=4510/4594, merge=0/0, ticks=19925/22423, in_queue=42352, 
util=44.90%, aggrios=4513/4566, aggrmerge=0/36, aggrticks=19948/22446, 
aggrin_queue=42387, aggrutil=45.09%
  sda: ios=4513/4566, merge=0/36, ticks=19948/22446, in_queue=42387, 
util=45.09%
============================================================================
THINK=20000 HDD

bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
iodepth=16
fio-2.0.13
Starting 1 process
Jobs: 1 (f=1): [m] [100.0% done] [128K/72K/0K /s] [32 /18 /0  iops] [eta 
00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=24131: Fri May 17 11:14:57 
2013
  read : io=8984.0KB, bw=102203 B/s, iops=24 , runt= 90013msec
    slat (usec): min=8 , max=57 , avg=10.84, stdev= 3.80
    clat (msec): min=7 , max=327 , avg=299.32, stdev=13.73
     lat (msec): min=7 , max=327 , avg=299.33, stdev=13.73
    bw (KB/s)  : min=   48, max=  152, per=100.00%, avg=99.47, stdev=20.04
  write: io=9064.0KB, bw=103113 B/s, iops=25 , runt= 90013msec
    slat (usec): min=10 , max=57 , avg=12.33, stdev= 3.54
    clat (msec): min=27 , max=307 , avg=299.16, stdev=14.03
     lat (msec): min=27 , max=307 , avg=299.18, stdev=14.03
    bw (KB/s)  : min=   48, max=  152, per=100.00%, avg=100.55, 
stdev=20.02
    lat (msec) : 10=0.02%, 50=0.09%, 100=0.09%, 250=0.35%, 500=99.45%
  cpu          : usr=96.76%, sys=0.08%, ctx=13629, majf=0, minf=22
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=99.7%, 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=2246/w=2266/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=8984KB, aggrb=99KB/s, minb=99KB/s, maxb=99KB/s, 
mint=90013msec, maxt=90013msec
  WRITE: io=9064KB, aggrb=100KB/s, minb=100KB/s, maxb=100KB/s, 
mint=90013msec, maxt=90013msec

Disk stats (read/write):
    dm-1: ios=2245/2367, merge=0/0, ticks=9778/11313, in_queue=21091, 
util=22.53%, aggrios=2246/2344, aggrmerge=0/34, aggrticks=9786/11171, 
aggrin_queue=20954, aggrutil=22.62%
  sda: ios=2246/2344, merge=0/34, ticks=9786/11171, in_queue=20954, 
util=22.62%

============================================================================
THINK=20000 SDD

bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, 
iodepth=16
fio-2.1
Starting 1 process
bgupdater: Laying out IO file(s) (1 file(s) / 256MB)
Jobs: 1 (f=1): [m] [100.0% done] [104KB/96KB/0KB /s] [26/24/0 iops] [eta 
00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=24593: Fri May 17 11:20:57 
2013
  read : io=9240.0KB, bw=105123B/s, iops=25, runt= 90006msec
    slat (usec): min=7, max=57, avg= 9.86, stdev= 4.12
    clat (usec): min=268, max=300293, avg=299101.30, stdev=15596.56
     lat (usec): min=310, max=300302, avg=299111.39, stdev=15596.30
    bw (KB  /s): min=   56, max=  152, per=100.00%, avg=102.21, 
stdev=19.77
  write: io=8808.0KB, bw=100208B/s, iops=24, runt= 90006msec
    slat (usec): min=12, max=60, avg=14.21, stdev= 4.06
    clat (msec): min=20, max=300, avg=299.35, stdev=12.36
     lat (msec): min=20, max=300, avg=299.36, stdev=12.36
    bw (KB  /s): min=   48, max=  144, per=100.00%, avg=97.83, stdev=19.76
    lat (usec) : 500=0.02%
    lat (msec) : 50=0.09%, 100=0.09%, 250=0.35%, 500=99.45%
  cpu          : usr=96.37%, sys=0.10%, ctx=13480, majf=0, minf=24
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=99.7%, 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=2310/w=2202/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=9240KB, aggrb=102KB/s, minb=102KB/s, maxb=102KB/s, 
mint=90006msec, maxt=90006msec
  WRITE: io=8808KB, aggrb=97KB/s, minb=97KB/s, maxb=97KB/s, 
mint=90006msec, maxt=90006msec

Disk stats (read/write):
  sdb: ios=2306/2316, merge=0/30, ticks=410/2881, in_queue=3288, 
util=3.57%
============================================================================
THINK=0 SDD
[root@twix0208 fio]# ./fio21 four-threads-randio-012.fio 
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] [12696KB/12580KB/0KB /s] [3174/3145/0 
iops] [eta 00m:00s]
bgupdater: (groupid=0, jobs=1): err= 0: pid=25111: Fri May 17 11:28:44 
2013
  read : io=131220KB, bw=13104KB/s, iops=3275, runt= 10014msec
    slat (usec): min=4, max=2132, avg=15.77, stdev=16.28
    clat (usec): min=151, max=9335, avg=1981.99, stdev=1250.96
     lat (usec): min=210, max=9357, avg=1998.09, stdev=1250.85
    bw (KB  /s): min=12184, max=13912, per=100.00%, avg=13112.15, 
stdev=436.14
  write: io=130924KB, bw=13074KB/s, iops=3268, runt= 10014msec
    slat (usec): min=6, max=3283, avg=21.15, stdev=22.14
    clat (usec): min=604, max=11033, avg=2864.34, stdev=1589.82
     lat (usec): min=621, max=11045, avg=2885.85, stdev=1589.91
    bw (KB  /s): min=12048, max=14256, per=100.00%, avg=13082.20, 
stdev=529.54
    lat (usec) : 250=0.03%, 500=1.59%, 750=3.51%, 1000=8.56%
    lat (msec) : 2=39.75%, 4=29.36%, 10=17.20%, 20=0.01%
  cpu          : usr=2.59%, sys=11.36%, ctx=25119, 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=13103KB/s, minb=13103KB/s, maxb=13103KB/s, 
mint=10014msec, maxt=10014msec
  WRITE: io=130924KB, aggrb=13074KB/s, minb=13074KB/s, maxb=13074KB/s, 
mint=10014msec, maxt=10014msec

Disk stats (read/write):
  sdb: ios=32407/32402, merge=6/9, ticks=63329/91775, in_queue=155061, 
util=99.07%









From:   Jens Axboe <axboe@kernel.dk>
To:     Edoardo Comar/UK/IBM@IBMGB, 
Cc:     fio@vger.kernel.org
Date:   17/05/2013 11:22
Subject:        Re: latency measurements when adding thinktime
Sent by:        fio-owner@vger.kernel.org



On Fri, May 17 2013, Edoardo Comar wrote:
> Hi Jens,
> 
> thanks a lot, I tried your suggestion straight away: 
> The cpu line in the output shows that the job has not been idle at all.
> but even with thinktime_spin, the latency stays high at at 150ms.
> 
> Note also that if I increase thinktime & thinktime_spin by another 10000 

> us
> to a total of 20000, then the reported latency goes up another 150ms to 
a 
> total of 300ms.
> Could this be a bug?

It certainly could. Let me take a look here and see if I can reproduce
it.

-- 
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe fio" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html



Unless stated otherwise above:
IBM United Kingdom Limited - Registered in England and Wales with number 
741598. 
Registered office: PO Box 41, North Harbour, Portsmouth, Hampshire PO6 3AU



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17 10:22     ` Jens Axboe
  2013-05-17 10:38       ` Edoardo Comar
@ 2013-05-17 10:43       ` Jens Axboe
  2013-05-17 10:48         ` Edoardo Comar
  2013-05-17 10:48         ` Jens Axboe
  1 sibling, 2 replies; 9+ messages in thread
From: Jens Axboe @ 2013-05-17 10:43 UTC (permalink / raw)
  To: Edoardo Comar; +Cc: fio

On Fri, May 17 2013, Jens Axboe wrote:
> On Fri, May 17 2013, Edoardo Comar wrote:
> > Hi Jens,
> > 
> > thanks a lot, I tried your suggestion straight away: 
> > The cpu line in the output shows that the job has not been idle at all.
> > but even with thinktime_spin, the latency stays high at at 150ms.
> > 
> > Note also that if I increase thinktime & thinktime_spin by another 10000 
> > us
> > to a total of 20000, then the reported latency goes up another 150ms to a 
> > total of 300ms.
> > Could this be a bug?
> 
> It certainly could. Let me take a look here and see if I can reproduce
> it.

And it was... Basically the same issue that was fixed for rate limiting.
When going to sleep or spinning, ensure that we have all IOs flushed.
Otherwise we could unfairly attribute the sleep towards the completion
latencies.

Fixed here:

http://git.kernel.dk/?p=fio.git;a=commit;h=002e7183cb86d6100efef690b6fa90bf0988b084

or just git pull and you'll get the fix.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17 10:43       ` Jens Axboe
@ 2013-05-17 10:48         ` Edoardo Comar
  2013-05-17 10:50           ` Jens Axboe
  2013-05-17 10:48         ` Jens Axboe
  1 sibling, 1 reply; 9+ messages in thread
From: Edoardo Comar @ 2013-05-17 10:48 UTC (permalink / raw)
  To: Jens Axboe; +Cc: fio

Many thanks !!!!!!!!!!!

looking at the history of changes I had spotted that there was a fix for 
latency reports using rate
and that is what made me move from 2.0.13 to 2.1

--------------------------------------------------
regards,
Edoardo Comar
WebSphere Application Service Platform for Networks (ASPN)
ecomar@uk.ibm.com
+44 (0)1962 81 5576 
IBM UK Ltd, Hursley Park, SO21 2JN




From:   Jens Axboe <axboe@kernel.dk>
To:     Edoardo Comar/UK/IBM@IBMGB, 
Cc:     fio@vger.kernel.org
Date:   17/05/2013 11:43
Subject:        Re: latency measurements when adding thinktime



On Fri, May 17 2013, Jens Axboe wrote:
> On Fri, May 17 2013, Edoardo Comar wrote:
> > Hi Jens,
> > 
> > thanks a lot, I tried your suggestion straight away: 
> > The cpu line in the output shows that the job has not been idle at 
all.
> > but even with thinktime_spin, the latency stays high at at 150ms.
> > 
> > Note also that if I increase thinktime & thinktime_spin by another 
10000 
> > us
> > to a total of 20000, then the reported latency goes up another 150ms 
to a 
> > total of 300ms.
> > Could this be a bug?
> 
> It certainly could. Let me take a look here and see if I can reproduce
> it.

And it was... Basically the same issue that was fixed for rate limiting.
When going to sleep or spinning, ensure that we have all IOs flushed.
Otherwise we could unfairly attribute the sleep towards the completion
latencies.

Fixed here:

http://git.kernel.dk/?p=fio.git;a=commit;h=002e7183cb86d6100efef690b6fa90bf0988b084


or just git pull and you'll get the fix.

-- 
Jens Axboe



Unless stated otherwise above:
IBM United Kingdom Limited - Registered in England and Wales with number 
741598. 
Registered office: PO Box 41, North Harbour, Portsmouth, Hampshire PO6 3AU



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17 10:48         ` Edoardo Comar
@ 2013-05-17 10:50           ` Jens Axboe
  0 siblings, 0 replies; 9+ messages in thread
From: Jens Axboe @ 2013-05-17 10:50 UTC (permalink / raw)
  To: Edoardo Comar; +Cc: fio

On Fri, May 17 2013, Edoardo Comar wrote:
> Many thanks !!!!!!!!!!!
> 
> looking at the history of changes I had spotted that there was a fix for 
> latency reports using rate
> and that is what made me move from 2.0.13 to 2.1

Right, this is essentially the very same bug. Before sleeping, ensure
currently submitted IO have been completed.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: latency measurements when adding thinktime
  2013-05-17 10:43       ` Jens Axboe
  2013-05-17 10:48         ` Edoardo Comar
@ 2013-05-17 10:48         ` Jens Axboe
  1 sibling, 0 replies; 9+ messages in thread
From: Jens Axboe @ 2013-05-17 10:48 UTC (permalink / raw)
  To: Edoardo Comar; +Cc: fio

On Fri, May 17 2013, Jens Axboe wrote:
> On Fri, May 17 2013, Jens Axboe wrote:
> > On Fri, May 17 2013, Edoardo Comar wrote:
> > > Hi Jens,
> > > 
> > > thanks a lot, I tried your suggestion straight away: 
> > > The cpu line in the output shows that the job has not been idle at all.
> > > but even with thinktime_spin, the latency stays high at at 150ms.
> > > 
> > > Note also that if I increase thinktime & thinktime_spin by another 10000 
> > > us
> > > to a total of 20000, then the reported latency goes up another 150ms to a 
> > > total of 300ms.
> > > Could this be a bug?
> > 
> > It certainly could. Let me take a look here and see if I can reproduce
> > it.
> 
> And it was... Basically the same issue that was fixed for rate limiting.
> When going to sleep or spinning, ensure that we have all IOs flushed.
> Otherwise we could unfairly attribute the sleep towards the completion
> latencies.
> 
> Fixed here:
> 
> http://git.kernel.dk/?p=fio.git;a=commit;h=002e7183cb86d6100efef690b6fa90bf0988b084
> 
> or just git pull and you'll get the fix.

Also note this:

http://git.kernel.dk/?p=fio.git;a=commit;h=4d01ece69f7b4d7bd56210e0f839944a91c5679f

which explains how thinktime_blocks will effectively reduce iodepth=, if
the former is smaller. So if you want a larger queue depth with
thinktime being set, consider setting thinktime_blocks= to only wait
every X blocks instead. Or keep it at 1, but do realize that this then
caps your effective device queue depth to 1.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2013-05-17 10:50 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-05-17  0:00 latency measurements when adding thinktime Edoardo Comar
2013-05-17  7:47 ` Jens Axboe
2013-05-17  9:24   ` Edoardo Comar
2013-05-17 10:22     ` Jens Axboe
2013-05-17 10:38       ` Edoardo Comar
2013-05-17 10:43       ` Jens Axboe
2013-05-17 10:48         ` Edoardo Comar
2013-05-17 10:50           ` Jens Axboe
2013-05-17 10:48         ` Jens Axboe

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox