* 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 ` Jens Axboe
2013-05-17 10:48 ` Edoardo Comar
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 ` Jens Axboe
2013-05-17 10:48 ` Edoardo Comar
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
* Re: latency measurements when adding thinktime
2013-05-17 10:43 ` Jens Axboe
2013-05-17 10:48 ` Jens Axboe
@ 2013-05-17 10:48 ` Edoardo Comar
2013-05-17 10:50 ` 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
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 ` Jens Axboe
2013-05-17 10:48 ` Edoardo Comar
2013-05-17 10:50 ` Jens Axboe
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox