* output - aggregate read bandwitdh
@ 2013-05-18 1:28 Edoardo Comar
2013-05-18 6:53 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 1:28 UTC (permalink / raw)
To: fio
I have a problem with fio built today from GIT
running the jobfile below, the aggregate bandwidth for 'read' output by
the latest fio is excessive
while it seems reasonable with an older fio version.
fio-2.0.13 READ: io=51500KB, aggrb=857KB/s,
fio-2.1-6-g4d01 READ: io=31057MB, aggrb=530017KB/s,
You should easily reproduce this with the data below.
I have reproduced it on my laptop (RHEL 6.4) as well as on other RHEL
systems.
on my laptop
READ: io=13028KB, aggrb=216KB/s,
or
READ: io=33204MB, aggrb=566519KB/s,
running the same configuration
I believe this to be a bug.
=========================================
# less four-threads-randio-016.fio
[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=60
time_based
ramp_time=5
clat_percentiles=0
direct=1
[bgwriter]
rw=randwrite
iodepth=32
ioengine=libaio
[queryA]
rw=randread
ioengine=mmap
thinktime=3
[queryB]
rw=randread
ioengine=mmap
thinktime=5
[bgupdater]
rw=randrw
ioengine=libaio
iodepth=16
size=64m
thinktime=5
# ./fio-2.0.13 four-threads-randio-016.fio
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
Jobs: 2 (f=2): [w_Em] [52.8% done] [1188K/1828K/0K /s] [297 /457 /0 iops]
[eta 00m:59s]
bgwriter: (groupid=0, jobs=1): err= 0: pid=3996: Sat May 18 02:10:35 2013
write: io=89096KB, bw=1482.4KB/s, iops=370 , runt= 60104msec
slat (usec): min=9 , max=142732 , avg=57.41, stdev=1503.15
clat (msec): min=1 , max=1157 , avg=86.33, stdev=108.57
lat (msec): min=1 , max=1157 , avg=86.39, stdev=108.59
bw (KB/s) : min= 0, max= 3065, per=68.91%, avg=1485.70,
stdev=586.92
lat (msec) : 2=0.27%, 4=4.81%, 10=12.00%, 20=13.52%, 50=21.67%
lat (msec) : 100=18.53%, 250=21.81%, 500=6.29%, 750=1.08%, 1000=0.15%
lat (msec) : 2000=0.01%
cpu : usr=0.39%, sys=1.48%, ctx=19840, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=108.5%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=22243/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=3997: Sat May 18 02:10:35 2013
read : io=6744.0KB, bw=115045 B/s, iops=28 , runt= 60027msec
clat (msec): min=1 , max=640 , avg=35.59, stdev=51.42
lat (msec): min=1 , max=640 , avg=35.59, stdev=51.42
bw (KB/s) : min= 0, max= 261, per=13.19%, avg=113.07, stdev=49.88
lat (msec) : 2=0.53%, 4=11.21%, 10=25.74%, 20=19.34%, 50=22.24%
lat (msec) : 100=11.86%, 250=8.24%, 500=0.71%, 750=0.12%
cpu : usr=0.07%, sys=0.14%, ctx=1832, majf=1832, minf=28
IO depths : 1=108.7%, 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=1686/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=3998: Sat May 18 02:10:35 2013
read : io=4404.0KB, bw=75152 B/s, iops=18 , runt= 60007msec
clat (msec): min=1 , max=868 , avg=54.49, stdev=73.56
lat (msec): min=1 , max=868 , avg=54.49, stdev=73.56
bw (KB/s) : min= 0, max= 193, per=8.60%, avg=73.68, stdev=33.09
lat (msec) : 2=0.27%, 4=5.90%, 10=19.07%, 20=14.99%, 50=25.79%
lat (msec) : 100=16.62%, 250=14.62%, 500=2.45%, 750=0.18%, 1000=0.09%
cpu : usr=0.05%, sys=0.09%, ctx=1167, majf=1167, minf=28
IO depths : 1=106.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=1101/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=3999: Sat May 18 02:10:35 2013
read : io=40352KB, bw=687677 B/s, iops=167 , runt= 60087msec
slat (usec): min=4 , max=106229 , avg=56.91, stdev=1603.60
clat (usec): min=83 , max=1022.8K, avg=29250.78, stdev=50020.33
lat (usec): min=704 , max=1022.2K, avg=29311.02, stdev=50035.27
bw (KB/s) : min= 0, max= 1976, per=79.02%, avg=677.21,
stdev=347.75
write: io=40500KB, bw=690199 B/s, iops=168 , runt= 60087msec
slat (usec): min=7 , max=166544 , avg=61.96, stdev=1985.57
clat (msec): min=1 , max=1340 , avg=65.87, stdev=108.26
lat (msec): min=1 , max=1340 , avg=65.94, stdev=108.29
bw (KB/s) : min= 68, max= 1384, per=31.81%, avg=685.93,
stdev=321.85
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=2.53%, 4=11.45%, 10=24.13%, 20=17.43%, 50=18.92%
lat (msec) : 100=11.95%, 250=10.65%, 500=2.35%, 750=0.42%, 1000=0.13%
lat (msec) : 2000=0.08%
cpu : usr=0.59%, sys=1.87%, ctx=21168, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=107.9%, 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=10084/w=10114/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=51500KB, aggrb=857KB/s, minb=73KB/s, maxb=671KB/s,
mint=60007msec, maxt=60087msec
WRITE: io=129596KB, aggrb=2156KB/s, minb=674KB/s, maxb=1482KB/s,
mint=60087msec, maxt=60104msec
Disk stats (read/write):
vda: ios=13899/35117, merge=0/1319, ticks=441967/2796528,
in_queue=3239663, util=99.93%
===============================================================
removing files
# rm -rf /mnt/vda2/tmp/*
==============================================================
fio-2.1-6-g4d01
# ./fio four-threads-randio-016.fio
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-6-g4d01
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
Jobs: 4 (f=4): [wrrm] [100.0% done] [514.5MB/3052KB/0KB /s] [132K/763/0
iops] [eta 00m:00s]
bgwriter: (groupid=0, jobs=1): err= 0: pid=3983: Sat May 18 02:06:43 2013
write: io=176768KB, bw=2942.8KB/s, iops=735, runt= 60069msec
slat (usec): min=5, max=104922, avg=33.86, stdev=1148.48
clat (msec): min=1, max=515, avg=43.50, stdev=45.18
lat (msec): min=1, max=515, avg=43.54, stdev=45.19
bw (KB /s): min= 0, max= 3304, per=98.86%, avg=2927.14,
stdev=355.37
lat (msec) : 2=0.37%, 4=5.84%, 10=15.68%, 20=17.56%, 50=29.64%
lat (msec) : 100=20.39%, 250=10.19%, 500=0.40%, 750=0.01%
cpu : usr=0.35%, sys=1.49%, ctx=38606, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=108.4%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=44161/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=3984: Sat May 18 02:06:43 2013
read : io=17682MB, bw=301761KB/s, iops=75440, runt= 60001msec
clat (usec): min=0, max=6221, avg= 4.31, stdev=72.40
lat (usec): min=1, max=6222, avg= 5.38, stdev=76.02
bw (KB /s): min= 0, max=315120, per=56.49%, avg=299399.30,
stdev=27955.81
lat (usec) : 2=22.24%, 4=76.97%, 10=0.22%, 20=0.23%, 50=0.05%
lat (usec) : 100=0.17%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.06%, 4=0.04%, 10=0.01%
cpu : usr=19.85%, sys=32.86%, ctx=24374, majf=0, minf=4634040
IO depths : 1=108.3%, 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=4526495/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=3985: Sat May 18 02:06:43 2013
read : io=13374MB, bw=228239KB/s, iops=57059, runt= 60002msec
clat (usec): min=0, max=6019, avg= 3.57, stdev=69.08
lat (usec): min=1, max=6020, avg= 4.65, stdev=73.08
bw (KB /s): min= 0, max=237544, per=42.73%, avg=226467.66,
stdev=21075.51
lat (usec) : 2=60.11%, 4=39.20%, 10=0.18%, 20=0.21%, 50=0.05%
lat (usec) : 100=0.15%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.05%, 4=0.04%, 10=0.01%
cpu : usr=17.12%, sys=35.60%, ctx=24353, majf=0, minf=3553602
IO depths : 1=108.4%, 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=3423692/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=3986: Sat May 18 02:06:43 2013
read : io=1356.0KB, bw=23141B/s, iops=5, runt= 60002msec
slat (usec): min=6, max=59176, avg=392.16, stdev=3738.80
clat (usec): min=3, max=353515, avg=46969.04, stdev=52753.16
lat (msec): min=1, max=353, avg=47.40, stdev=52.55
bw (KB /s): min= 0, max= 86, per=0.00%, avg=24.35, stdev=17.97
write: io=1132.0KB, bw=19318B/s, iops=4, runt= 60002msec
slat (usec): min=10, max=62967, avg=617.02, stdev=4925.46
clat (msec): min=2, max=992, avg=154.51, stdev=171.20
lat (msec): min=2, max=992, avg=155.21, stdev=170.84
bw (KB /s): min= 4, max= 63, per=0.64%, avg=18.95, stdev=11.05
lat (usec) : 4=0.32%, 1000=0.16%
lat (msec) : 2=0.16%, 4=4.18%, 10=14.47%, 20=12.38%, 50=19.29%
lat (msec) : 100=20.42%, 250=18.01%, 500=8.68%, 750=1.13%, 1000=0.80%
cpu : usr=0.01%, sys=0.04%, ctx=702, majf=0, minf=22
IO depths : 1=110.1%, 2=0.3%, 4=0.6%, 8=1.3%, 16=0.2%, 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=339/w=283/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=31057MB, aggrb=530017KB/s, minb=22KB/s, maxb=301761KB/s,
mint=60001msec, maxt=60002msec
WRITE: io=177900KB, aggrb=2961KB/s, minb=18KB/s, maxb=2942KB/s,
mint=60002msec, maxt=60069msec
Disk stats (read/write):
vda: ios=375/48235, merge=0/1782, ticks=17222/2117780, in_queue=2136170,
util=99.91%
--------------------------------------------------
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 1:28 output - aggregate read bandwitdh Edoardo Comar
@ 2013-05-18 6:53 ` Jens Axboe
2013-05-18 7:01 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-18 6:53 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Sat, May 18 2013, Edoardo Comar wrote:
> I have a problem with fio built today from GIT
> running the jobfile below, the aggregate bandwidth for 'read' output by
> the latest fio is excessive
> while it seems reasonable with an older fio version.
>
> fio-2.0.13 READ: io=51500KB, aggrb=857KB/s,
>
> fio-2.1-6-g4d01 READ: io=31057MB, aggrb=530017KB/s,
>
>
> You should easily reproduce this with the data below.
> I have reproduced it on my laptop (RHEL 6.4) as well as on other RHEL
> systems.
> on my laptop
> READ: io=13028KB, aggrb=216KB/s,
> or
> READ: io=33204MB, aggrb=566519KB/s,
>
> running the same configuration
>
> I believe this to be a bug.
I wonder if this is a regression from 2.0.15 to 2.1. The gfio stuff got
merged in along the way, could definitely be an accounting issue
introduced there. I'll take a look.
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 6:53 ` Jens Axboe
@ 2013-05-18 7:01 ` Jens Axboe
2013-05-18 10:52 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-18 7:01 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Sat, May 18 2013, Jens Axboe wrote:
> On Sat, May 18 2013, Edoardo Comar wrote:
> > I have a problem with fio built today from GIT
> > running the jobfile below, the aggregate bandwidth for 'read' output by
> > the latest fio is excessive
> > while it seems reasonable with an older fio version.
> >
> > fio-2.0.13 READ: io=51500KB, aggrb=857KB/s,
> >
> > fio-2.1-6-g4d01 READ: io=31057MB, aggrb=530017KB/s,
> >
> >
> > You should easily reproduce this with the data below.
> > I have reproduced it on my laptop (RHEL 6.4) as well as on other RHEL
> > systems.
> > on my laptop
> > READ: io=13028KB, aggrb=216KB/s,
> > or
> > READ: io=33204MB, aggrb=566519KB/s,
> >
> > running the same configuration
> >
> > I believe this to be a bug.
>
> I wonder if this is a regression from 2.0.15 to 2.1. The gfio stuff got
> merged in along the way, could definitely be an accounting issue
> introduced there. I'll take a look.
Doesn't reproduce here for me. Could you try a make clean, the configure
and make again? Just to be on the safe side...
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 7:01 ` Jens Axboe
@ 2013-05-18 10:52 ` Edoardo Comar
2013-05-18 11:02 ` Edoardo Comar
[not found] ` <OFEF259463.FACECBD6-ON80257B6F.003C54FB-80257B6F.003CA237@LocalDomain>
0 siblings, 2 replies; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 10:52 UTC (permalink / raw)
To: Jens Axboe, fio
Thanks Jens
I did :
$ git pull
$ make clean
$ ./configure
$ make
$ sudo make install
then :
#to remove old files
$ rm -rf /mnt/vda2/tmp/*
# causing the new fio to lay the files out
$ fio -output output-fio-2.1-8-gb2c77.txt four-threads-randio-016.fio
# then reusing them for the old fio version
$ /usr/bin/fio -output output-fio-2.0.13.txt four-threads-randio-016.fio
and I reproduced the problem on my laptop
[ecomar@edow500 devel]$ uname -a
Linux edow500.hursley.ibm.com 2.6.32-358.6.1.el6.x86_64 #1 SMP Fri Mar 29
16:51:51 EDT 2013 x86_64 x86_64 x86_64 GNU/Linux
full results below
HTH
Edo
============================================================================
#config-host.h
/*
* Automatically generated by configure - do not modify
* Configured with: * './configure'
*/
#define CONFIG_64BIT
#define CONFIG_LITTLE_ENDIAN
#define CONFIG_ZLIB
#define CONFIG_LIBAIO
#define CONFIG_POSIXAIO
#define CONFIG_POSIXAIO_FSYNC
#define CONFIG_LINUX_FALLOCATE
#define CONFIG_POSIX_FALLOCATE
#define CONFIG_FDATASYNC
#define CONFIG_SYNC_FILE_RANGE
#define CONFIG_SFAA
#define CONFIG_CLOCK_GETTIME
#define CONFIG_CLOCK_MONOTONIC
#define CONFIG_GETTIMEOFDAY
#define CONFIG_POSIX_FADVISE
#define CONFIG_3ARG_AFFINITY
#define CONFIG_STRSEP
#define CONFIG_STRCASESTR
#define CONFIG_GETOPT_LONG_ONLY
#define CONFIG_INET_ATON
#define CONFIG_SOCKLEN_T
#define CONFIG_LINUX_EXT4_MOVE_EXTENT
#define CONFIG_LINUX_SPLICE
#define CONFIG_TLS_THREAD
#define CONFIG_RUSAGE_THREAD
#define CONFIG_SCHED_IDLE
#define CONFIG_TCP_NODELAY
#define CONFIG_RLIMIT_MEMLOCK
#define CONFIG_PWRITEV
============================================================================
#cat four-threads-randio-016.fio
[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=60
time_based
ramp_time=5
clat_percentiles=0
direct=1
[bgwriter]
rw=randwrite
iodepth=32
ioengine=libaio
[queryA]
rw=randread
ioengine=mmap
thinktime=3
[queryB]
rw=randread
ioengine=mmap
thinktime=5
[bgupdater]
rw=randrw
ioengine=libaio
iodepth=16
size=64m
thinktime=5
============================================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
bgwriter: (groupid=0, jobs=1): err= 0: pid=3745: Sat May 18 11:41:08 2013
write: io=41164KB, bw=701900B/s, iops=170, runt= 60054msec
slat (usec): min=11, max=412874, avg=184.80, stdev=6240.48
clat (msec): min=3, max=826, avg=186.62, stdev=115.32
lat (msec): min=3, max=826, avg=186.82, stdev=115.72
bw (KB /s): min= 0, max= 1230, per=98.55%, avg=690.82,
stdev=231.61
lat (msec) : 4=0.02%, 10=0.12%, 20=0.49%, 50=8.64%, 100=19.43%
lat (msec) : 250=39.74%, 500=30.81%, 750=1.04%, 1000=0.02%
cpu : usr=0.22%, sys=0.45%, ctx=10821, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=109.8%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=10260/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=3746: Sat May 18 11:41:08 2013
read : io=17482MB, bw=298351KB/s, iops=74587, runt= 60001msec
clat (usec): min=1, max=11446, avg= 3.92, stdev=29.76
lat (usec): min=2, max=12278, avg= 5.37, stdev=34.68
bw (KB /s): min= 0, max=335136, per=54.65%, avg=295877.00,
stdev=34918.18
lat (usec) : 2=0.01%, 4=44.30%, 10=55.26%, 20=0.32%, 50=0.07%
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=87.11%, sys=12.06%, ctx=22949, majf=0, minf=4549229
IO depths : 1=107.7%, 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=4475343/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=3747: Sat May 18 11:41:08 2013
read : io=14257MB, bw=243312KB/s, iops=60828, runt= 60001msec
clat (usec): min=1, max=18287, avg= 4.18, stdev=37.17
lat (usec): min=2, max=18288, avg= 5.64, stdev=44.27
bw (KB /s): min= 0, max=270139, per=44.59%, avg=241370.27,
stdev=34771.40
lat (usec) : 2=0.01%, 4=41.55%, 10=57.84%, 20=0.33%, 50=0.15%
lat (usec) : 100=0.02%, 250=0.07%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=84.55%, sys=10.57%, ctx=38532, majf=0, minf=3774059
IO depths : 1=108.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=3649742/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=3748: Sat May 18 11:41:08 2013
read : io=1092.0KB, bw=18625B/s, iops=4, runt= 60036msec
slat (usec): min=9, max=104109, avg=710.32, stdev=6958.17
clat (usec): min=350, max=435402, avg=123958.98, stdev=125840.77
lat (usec): min=381, max=435421, avg=124738.53, stdev=126435.26
bw (KB /s): min= 0, max= 71, per=0.00%, avg=18.15, stdev=12.30
write: io=974848B, bw=16237B/s, iops=3, runt= 60036msec
slat (usec): min=12, max=98337, avg=1542.04, stdev=8831.57
clat (msec): min=11, max=453, avg=107.43, stdev=89.92
lat (msec): min=11, max=546, avg=109.14, stdev=95.59
bw (KB /s): min= 5, max= 43, per=2.23%, avg=15.60, stdev= 6.84
lat (usec) : 500=0.59%, 750=0.20%, 1000=0.20%
lat (msec) : 4=5.09%, 10=17.03%, 20=4.31%, 50=10.18%, 100=20.94%
lat (msec) : 250=25.05%, 500=16.44%
cpu : usr=0.02%, sys=0.04%, ctx=587, majf=0, minf=21
IO depths : 1=107.4%, 2=0.4%, 4=0.8%, 8=1.6%, 16=0.2%, 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=273/w=238/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=31740MB, aggrb=541365KB/s, minb=18KB/s, maxb=298351KB/s,
mint=60001msec, maxt=60036msec
WRITE: io=42116KB, aggrb=701KB/s, minb=15KB/s, maxb=685KB/s,
mint=60036msec, maxt=60054msec
Disk stats (read/write):
dm-1: ios=298/13834, merge=0/0, ticks=37382/2405825, in_queue=2449686,
util=99.95%, aggrios=300/13851, aggrmerge=0/0, aggrticks=37638/2414256,
aggrin_queue=2451895, aggrutil=99.93%
dm-0: ios=300/13851, merge=0/0, ticks=37638/2414256, in_queue=2451895,
util=99.93%, aggrios=300/11782, aggrmerge=0/2069, aggrticks=37583/2145209,
aggrin_queue=2182787, aggrutil=99.93%
sda: ios=300/11782, merge=0/2069, ticks=37583/2145209, in_queue=2182787,
util=99.93%
============================================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=11660: Sat May 18 11:43:49 2013
write: io=21908KB, bw=372270 B/s, iops=90 , runt= 60262msec
slat (usec): min=9 , max=385032 , avg=502.70, stdev=12025.44
clat (msec): min=4 , max=1755 , avg=353.33, stdev=257.27
lat (msec): min=4 , max=1755 , avg=353.83, stdev=257.85
bw (KB/s) : min= 0, max= 780, per=74.19%, avg=369.45,
stdev=156.04
lat (msec) : 10=0.77%, 20=3.56%, 50=9.93%, 100=8.46%, 250=11.42%
lat (msec) : 500=41.28%, 750=17.15%, 1000=5.99%, 2000=2.00%
cpu : usr=0.15%, sys=0.31%, ctx=5633, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.3%, 32=109.5%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=5446/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=11661: Sat May 18 11:43:49 2013
read : io=2232.0KB, bw=37939 B/s, iops=9 , runt= 60242msec
clat (msec): min=3 , max=881 , avg=107.95, stdev=139.78
lat (msec): min=3 , max=881 , avg=107.95, stdev=139.78
bw (KB/s) : min= 0, max= 102, per=17.30%, avg=36.84, stdev=20.55
lat (msec) : 4=0.18%, 10=3.94%, 20=35.66%, 50=21.51%, 100=7.71%
lat (msec) : 250=10.75%, 500=19.00%, 750=0.90%, 1000=0.36%
cpu : usr=0.01%, sys=0.12%, ctx=686, majf=610, minf=26
IO depths : 1=109.3%, 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=558/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=11662: Sat May 18 11:43:49 2013
read : io=2444.0KB, bw=41541 B/s, iops=10 , runt= 60245msec
clat (msec): min=4 , max=932 , avg=98.59, stdev=135.55
lat (msec): min=4 , max=932 , avg=98.59, stdev=135.55
bw (KB/s) : min= 0, max= 107, per=19.13%, avg=40.75, stdev=20.82
lat (msec) : 10=4.75%, 20=39.12%, 50=20.62%, 100=7.53%, 250=10.47%
lat (msec) : 500=16.37%, 750=0.98%, 1000=0.16%
cpu : usr=0.03%, sys=0.11%, ctx=690, majf=657, minf=26
IO depths : 1=107.5%, 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=611/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=11663: Sat May 18 11:43:49
2013
read : io=8180.0KB, bw=138901 B/s, iops=33 , runt= 60304msec
slat (usec): min=6 , max=181007 , avg=146.99, stdev=4496.16
clat (usec): min=80 , max=961158 , avg=178582.45, stdev=147791.89
lat (msec): min=3 , max=961 , avg=178.74, stdev=147.69
bw (KB/s) : min= 0, max= 345, per=66.90%, avg=142.51, stdev=78.70
write: io=8140.0KB, bw=138222 B/s, iops=33 , runt= 60304msec
slat (usec): min=8 , max=391440 , avg=1030.35, stdev=15704.22
clat (msec): min=4 , max=1307 , avg=293.98, stdev=215.99
lat (msec): min=4 , max=1307 , avg=295.05, stdev=217.49
bw (KB/s) : min= 6, max= 333, per=27.86%, avg=138.72, stdev=62.52
lat (usec) : 100=0.02%, 250=0.02%
lat (msec) : 4=0.07%, 10=1.43%, 20=6.72%, 50=11.34%, 100=12.32%
lat (msec) : 250=24.85%, 500=34.10%, 750=7.95%, 1000=1.35%, 2000=0.20%
cpu : usr=0.16%, sys=0.22%, ctx=4230, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=108.6%, 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=2036/w=2029/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=12856KB, aggrb=213KB/s, minb=37KB/s, maxb=135KB/s,
mint=60242msec, maxt=60304msec
WRITE: io=30048KB, aggrb=498KB/s, minb=134KB/s, maxb=363KB/s,
mint=60262msec, maxt=60304msec
Disk stats (read/write):
dm-1: ios=3495/9099, merge=0/0, ticks=517051/2958255,
in_queue=3476437, util=99.97%, aggrios=3495/9115, aggrmerge=0/0,
aggrticks=518008/2959075, aggrin_queue=3477084, aggrutil=99.95%
dm-0: ios=3495/9115, merge=0/0, ticks=518008/2959075,
in_queue=3477084, util=99.95%, aggrios=3493/8375, aggrmerge=2/740,
aggrticks=516946/2742061, aggrin_queue=3259004, aggrutil=99.95%
sda: ios=3493/8375, merge=2/740, ticks=516946/2742061, in_queue=3259004,
util=99.95%
From: Jens Axboe <axboe@kernel.dk>
To: Edoardo Comar/UK/IBM@IBMGB,
Cc: fio@vger.kernel.org
Date: 18/05/2013 08:01
Subject: Re: output - aggregate read bandwitdh
Sent by: fio-owner@vger.kernel.org
On Sat, May 18 2013, Jens Axboe wrote:
> On Sat, May 18 2013, Edoardo Comar wrote:
> > I have a problem with fio built today from GIT
> > running the jobfile below, the aggregate bandwidth for 'read' output
by
> > the latest fio is excessive
> > while it seems reasonable with an older fio version.
> >
> > fio-2.0.13 READ: io=51500KB, aggrb=857KB/s,
> >
> > fio-2.1-6-g4d01 READ: io=31057MB, aggrb=530017KB/s,
> >
> >
> > You should easily reproduce this with the data below.
> > I have reproduced it on my laptop (RHEL 6.4) as well as on other RHEL
> > systems.
> > on my laptop
> > READ: io=13028KB, aggrb=216KB/s,
> > or
> > READ: io=33204MB, aggrb=566519KB/s,
> >
> > running the same configuration
> >
> > I believe this to be a bug.
>
> I wonder if this is a regression from 2.0.15 to 2.1. The gfio stuff got
> merged in along the way, could definitely be an accounting issue
> introduced there. I'll take a look.
Doesn't reproduce here for me. Could you try a make clean, the configure
and make again? Just to be on the safe side...
--
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 10:52 ` Edoardo Comar
@ 2013-05-18 11:02 ` Edoardo Comar
[not found] ` <OFEF259463.FACECBD6-ON80257B6F.003C54FB-80257B6F.003CA237@LocalDomain>
1 sibling, 0 replies; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 11:02 UTC (permalink / raw)
To: Jens Axboe, fio
Hi Jens,
if you perform the steps in reverse, i.e.
remove the output files,
run the old fio (thus have the file generated)
the run the freshly built fio (thus reusing the output files)
the problem does not show
so to me it looks like the accounting lost the plot by having created the
files ?
HTH
===================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
bgwriter: (groupid=0, jobs=1): err= 0: pid=15702: Sat May 18 11:55:16 2013
write: io=16808KB, bw=285457 B/s, iops=69 , runt= 60294msec
slat (usec): min=11 , max=888637 , avg=517.21, stdev=19705.69
clat (msec): min=4 , max=2736 , avg=460.42, stdev=366.02
lat (msec): min=4 , max=2736 , avg=460.99, stdev=366.53
bw (KB/s) : min= 0, max= 870, per=73.62%, avg=289.33,
stdev=156.06
lat (msec) : 10=1.46%, 20=4.51%, 50=7.62%, 100=5.20%, 250=7.55%
lat (msec) : 500=38.29%, 750=18.39%, 1000=7.86%, 2000=9.69%,
>=2000=0.17%
cpu : usr=0.11%, sys=0.21%, ctx=3726, majf=0, minf=22
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=0.4%, 32=110.4%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=4171/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=15703: Sat May 18 11:55:16 2013
read : io=1924.0KB, bw=32765 B/s, iops=7 , runt= 60129msec
clat (msec): min=1 , max=833 , avg=124.99, stdev=159.31
lat (msec): min=1 , max=833 , avg=125.00, stdev=159.31
bw (KB/s) : min= 0, max= 91, per=18.01%, avg=32.96, stdev=17.98
lat (msec) : 2=0.21%, 10=1.25%, 20=32.43%, 50=21.21%, 100=11.23%
lat (msec) : 250=12.89%, 500=17.46%, 750=2.91%, 1000=0.42%
cpu : usr=0.02%, sys=0.03%, ctx=520, majf=519, minf=27
IO depths : 1=107.9%, 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=481/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=15704: Sat May 18 11:55:16 2013
read : io=2304.0KB, bw=39234 B/s, iops=9 , runt= 60133msec
clat (msec): min=3 , max=796 , avg=104.38, stdev=143.78
lat (msec): min=3 , max=796 , avg=104.38, stdev=143.78
bw (KB/s) : min= 0, max= 103, per=21.36%, avg=39.10, stdev=19.61
lat (msec) : 4=0.17%, 10=5.21%, 20=32.81%, 50=25.00%, 100=8.33%
lat (msec) : 250=10.42%, 500=15.80%, 750=2.08%, 1000=0.17%
cpu : usr=0.02%, sys=0.03%, ctx=630, majf=629, minf=27
IO depths : 1=109.2%, 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=576/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=15705: Sat May 18 11:55:16
2013
read : io=6852.0KB, bw=116308 B/s, iops=28 , runt= 60326msec
slat (usec): min=5 , max=529234 , avg=1241.91, stdev=18167.48
clat (usec): min=5 , max=1280.3K, avg=237605.15, stdev=206635.27
lat (msec): min=2 , max=1280 , avg=238.99, stdev=206.02
bw (KB/s) : min= 0, max= 396, per=64.92%, avg=118.80, stdev=67.68
write: io=6948.0KB, bw=117938 B/s, iops=28 , runt= 60326msec
slat (usec): min=8 , max=825689 , avg=2209.25, stdev=27458.48
clat (msec): min=5 , max=1578 , avg=319.33, stdev=261.16
lat (msec): min=5 , max=1578 , avg=321.77, stdev=264.30
bw (KB/s) : min= 15, max= 261, per=30.40%, avg=119.48, stdev=54.96
lat (usec) : 10=0.03%, 50=0.03%, 100=0.06%, 250=0.17%, 500=0.06%
lat (msec) : 4=0.15%, 10=1.83%, 20=6.64%, 50=9.34%, 100=10.25%
lat (msec) : 250=20.79%, 500=36.36%, 750=10.89%, 1000=1.80%,
2000=2.04%
cpu : usr=0.12%, sys=0.17%, ctx=3311, majf=0, minf=22
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=111.1%, 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=1712/w=1723/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=11080KB, aggrb=183KB/s, minb=31KB/s, maxb=113KB/s,
mint=60129msec, maxt=60326msec
WRITE: io=23756KB, aggrb=393KB/s, minb=115KB/s, maxb=278KB/s,
mint=60294msec, maxt=60326msec
Disk stats (read/write):
dm-1: ios=3253/10771, merge=0/0, ticks=559883/4212209,
in_queue=4777400, util=99.97%, aggrios=3255/10882, aggrmerge=0/0,
aggrticks=559956/4221317, aggrin_queue=4781292, aggrutil=99.97%
dm-0: ios=3255/10882, merge=0/0, ticks=559956/4221317,
in_queue=4781292, util=99.97%, aggrios=3249/7719, aggrmerge=6/3162,
aggrticks=554975/3062598, aggrin_queue=3617588, aggrutil=99.97%
sda: ios=3249/7719, merge=6/3162, ticks=554975/3062598,
in_queue=3617588, util=99.97%
================================================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=20441: Sat May 18 11:56:50 2013
write: io=28068KB, bw=476028B/s, iops=115, runt= 60378msec
slat (usec): min=9, max=947265, avg=402.78, stdev=14178.87
clat (msec): min=3, max=1635, avg=276.89, stdev=209.31
lat (msec): min=3, max=1635, avg=277.33, stdev=210.07
bw (KB /s): min= 0, max= 1019, per=98.32%, avg=466.03,
stdev=150.91
lat (msec) : 4=0.01%, 10=1.83%, 20=4.75%, 50=14.50%, 100=11.21%
lat (msec) : 250=5.22%, 500=52.95%, 750=7.29%, 1000=1.95%, 2000=0.73%
cpu : usr=0.19%, sys=0.40%, ctx=7319, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=109.5%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=6986/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=20442: Sat May 18 11:56:50 2013
read : io=3940.0KB, bw=66862B/s, iops=16, runt= 60341msec
clat (msec): min=6, max=762, avg=61.25, stdev=101.94
lat (msec): min=6, max=762, avg=61.25, stdev=101.94
bw (KB /s): min= 0, max= 133, per=45.87%, avg=64.67, stdev=23.10
lat (msec) : 10=2.44%, 20=55.43%, 50=24.77%, 100=1.22%, 250=3.65%
lat (msec) : 500=12.18%, 750=0.20%, 1000=0.10%
cpu : usr=0.03%, sys=0.06%, ctx=1076, majf=1075, minf=542
IO depths : 1=161.3%, 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=985/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=20443: Sat May 18 11:56:50 2013
read : io=3968.0KB, bw=67317B/s, iops=16, runt= 60359msec
clat (msec): min=4, max=781, avg=60.83, stdev=102.14
lat (msec): min=4, max=781, avg=60.83, stdev=102.14
bw (KB /s): min= 0, max= 143, per=46.11%, avg=65.02, stdev=23.70
lat (msec) : 10=3.83%, 20=55.04%, 50=23.59%, 100=1.31%, 250=3.23%
lat (msec) : 500=12.80%, 750=0.10%, 1000=0.10%
cpu : usr=0.05%, sys=0.05%, ctx=1084, majf=1081, minf=654
IO depths : 1=172.1%, 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=992/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=20444: Sat May 18 11:56:50
2013
read : io=671744B, bw=11149B/s, iops=2, runt= 60249msec
slat (usec): min=11, max=2602, avg=66.32, stdev=294.44
clat (msec): min=5, max=759, avg=123.67, stdev=127.15
lat (msec): min=5, max=759, avg=123.74, stdev=127.24
bw (KB /s): min= 3, max= 54, per=9.89%, avg=13.94, stdev=10.61
write: io=577536B, bw=9585B/s, iops=2, runt= 60249msec
slat (usec): min=9, max=774595, avg=7006.26, stdev=62617.17
clat (msec): min=32, max=837, avg=275.34, stdev=170.22
lat (msec): min=33, max=900, avg=283.34, stdev=179.59
bw (KB /s): min= 0, max= 16, per=1.93%, avg= 9.13, stdev= 3.62
lat (msec) : 10=2.30%, 20=17.05%, 50=8.52%, 100=6.23%, 250=34.10%
lat (msec) : 500=27.87%, 750=2.95%, 1000=0.98%
cpu : usr=0.01%, sys=0.02%, ctx=373, majf=0, minf=21
IO depths : 1=109.8%, 2=0.7%, 4=1.3%, 8=2.6%, 16=0.3%, 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=164/w=141/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=8564KB, aggrb=141KB/s, minb=10KB/s, maxb=65KB/s,
mint=60249msec, maxt=60359msec
WRITE: io=28632KB, aggrb=474KB/s, minb=9KB/s, maxb=464KB/s,
mint=60249msec, maxt=60378msec
Disk stats (read/write):
dm-1: ios=2345/12102, merge=0/0, ticks=153582/7496914,
in_queue=7659457, util=99.97%, aggrios=2345/12119, aggrmerge=0/0,
aggrticks=154444/7512052, aggrin_queue=7666496, aggrutil=99.95%
dm-0: ios=2345/12119, merge=0/0, ticks=154444/7512052,
in_queue=7666496, util=99.95%, aggrios=2345/8178, aggrmerge=0/3941,
aggrticks=153937/2410287, aggrin_queue=2564220, aggrutil=99.95%
sda: ios=2345/8178, merge=0/3941, ticks=153937/2410287,
in_queue=2564220, util=99.95%
--------------------------------------------------
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
[not found] ` <OFEF259463.FACECBD6-ON80257B6F.003C54FB-80257B6F.003CA237@LocalDomain>
@ 2013-05-18 11:18 ` Edoardo Comar
2013-05-18 12:22 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 11:18 UTC (permalink / raw)
To: Jens Axboe, fio
In any case, even excluding the alleged bug, the difference in aggrb
between the runs is very significant.
fio-2.1-8-gb2c77 - run laying out the files (where I think we have a bug)
Run status group 0 (all jobs):
READ: io=31740MB, aggrb=541365KB/s, minb=18KB/s, maxb=298351KB/s,
mint=60001msec, maxt=60036msec
WRITE: io=42116KB, aggrb=701KB/s, minb=15KB/s, maxb=685KB/s,
mint=60036msec, maxt=60054msec
fio-2.0.13 - run reusing the files
Run status group 0 (all jobs):
READ: io=12856KB, aggrb=213KB/s, minb=37KB/s, maxb=135KB/s,
mint=60242msec, maxt=60304msec
WRITE: io=30048KB, aggrb=498KB/s, minb=134KB/s, maxb=363KB/s,
mint=60262msec, maxt=60304msec
===========
fio-2.0.13 - run laying out the files
Run status group 0 (all jobs):
READ: io=11080KB, aggrb=183KB/s, minb=31KB/s, maxb=113KB/s,
mint=60129msec, maxt=60326msec
WRITE: io=23756KB, aggrb=393KB/s, minb=115KB/s, maxb=278KB/s,
mint=60294msec, maxt=60326msec
fio-2.1-8-gb2c77 - run reusing the files
Run status group 0 (all jobs):
READ: io=8564KB, aggrb=141KB/s, minb=10KB/s, maxb=65KB/s,
mint=60249msec, maxt=60359msec
WRITE: io=28632KB, aggrb=474KB/s, minb=9KB/s, maxb=464KB/s,
mint=60249msec, maxt=60378msec
===========
if I run again reusing the existing files I get quite consistent results
(within 5% which is ok over just a minute, IMHO)
with the previous run of the same fio version that also reused the files.
but the two versions report figures that are significantly different, the
new fio is consistently slower.
fio-2.0.13 - run reusing the files again
Run status group 0 (all jobs):
READ: io=12844KB, aggrb=212KB/s, minb=31KB/s, maxb=143KB/s,
mint=60148msec, maxt=60316msec
WRITE: io=30380KB, aggrb=503KB/s, minb=138KB/s, maxb=365KB/s,
mint=60163msec, maxt=60316msec
fio-2.1-8-gb2c77 - run reusing the files again
Run status group 0 (all jobs):
READ: io=8308KB, aggrb=137KB/s, minb=10KB/s, maxb=63KB/s,
mint=60010msec, maxt=60207msec
WRITE: io=27672KB, aggrb=459KB/s, minb=8KB/s, maxb=450KB/s,
mint=60162msec, maxt=60268msec
fio-2.0.13 - run reusing the files again
Run status group 0 (all jobs):
READ: io=11976KB, aggrb=198KB/s, minb=31KB/s, maxb=129KB/s,
mint=60332msec, maxt=60442msec
WRITE: io=29012KB, aggrb=479KB/s, minb=127KB/s, maxb=351KB/s,
mint=60442msec, maxt=60484msec
fio-2.1-8-gb2c77 - run reusing the files again
Run status group 0 (all jobs):
READ: io=8496KB, aggrb=141KB/s, minb=10KB/s, maxb=66KB/s,
mint=60005msec, maxt=60029msec
WRITE: io=27320KB, aggrb=454KB/s, minb=8KB/s, maxb=445KB/s,
mint=60005msec, maxt=60112msec
... which should I trust ?
--------------------------------------------------
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: Edoardo Comar/UK/IBM
To: Jens Axboe <axboe@kernel.dk>, fio@vger.kernel.org,
Date: 18/05/2013 12:02
Subject: Re: output - aggregate read bandwitdh
Hi Jens,
if you perform the steps in reverse, i.e.
remove the output files,
run the old fio (thus have the file generated)
the run the freshly built fio (thus reusing the output files)
the problem does not show
so to me it looks like the accounting lost the plot by having created the
files ?
HTH
===================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
bgwriter: (groupid=0, jobs=1): err= 0: pid=15702: Sat May 18 11:55:16 2013
write: io=16808KB, bw=285457 B/s, iops=69 , runt= 60294msec
slat (usec): min=11 , max=888637 , avg=517.21, stdev=19705.69
clat (msec): min=4 , max=2736 , avg=460.42, stdev=366.02
lat (msec): min=4 , max=2736 , avg=460.99, stdev=366.53
bw (KB/s) : min= 0, max= 870, per=73.62%, avg=289.33,
stdev=156.06
lat (msec) : 10=1.46%, 20=4.51%, 50=7.62%, 100=5.20%, 250=7.55%
lat (msec) : 500=38.29%, 750=18.39%, 1000=7.86%, 2000=9.69%,
>=2000=0.17%
cpu : usr=0.11%, sys=0.21%, ctx=3726, majf=0, minf=22
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=0.4%, 32=110.4%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=4171/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=15703: Sat May 18 11:55:16 2013
read : io=1924.0KB, bw=32765 B/s, iops=7 , runt= 60129msec
clat (msec): min=1 , max=833 , avg=124.99, stdev=159.31
lat (msec): min=1 , max=833 , avg=125.00, stdev=159.31
bw (KB/s) : min= 0, max= 91, per=18.01%, avg=32.96, stdev=17.98
lat (msec) : 2=0.21%, 10=1.25%, 20=32.43%, 50=21.21%, 100=11.23%
lat (msec) : 250=12.89%, 500=17.46%, 750=2.91%, 1000=0.42%
cpu : usr=0.02%, sys=0.03%, ctx=520, majf=519, minf=27
IO depths : 1=107.9%, 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=481/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=15704: Sat May 18 11:55:16 2013
read : io=2304.0KB, bw=39234 B/s, iops=9 , runt= 60133msec
clat (msec): min=3 , max=796 , avg=104.38, stdev=143.78
lat (msec): min=3 , max=796 , avg=104.38, stdev=143.78
bw (KB/s) : min= 0, max= 103, per=21.36%, avg=39.10, stdev=19.61
lat (msec) : 4=0.17%, 10=5.21%, 20=32.81%, 50=25.00%, 100=8.33%
lat (msec) : 250=10.42%, 500=15.80%, 750=2.08%, 1000=0.17%
cpu : usr=0.02%, sys=0.03%, ctx=630, majf=629, minf=27
IO depths : 1=109.2%, 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=576/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=15705: Sat May 18 11:55:16
2013
read : io=6852.0KB, bw=116308 B/s, iops=28 , runt= 60326msec
slat (usec): min=5 , max=529234 , avg=1241.91, stdev=18167.48
clat (usec): min=5 , max=1280.3K, avg=237605.15, stdev=206635.27
lat (msec): min=2 , max=1280 , avg=238.99, stdev=206.02
bw (KB/s) : min= 0, max= 396, per=64.92%, avg=118.80, stdev=67.68
write: io=6948.0KB, bw=117938 B/s, iops=28 , runt= 60326msec
slat (usec): min=8 , max=825689 , avg=2209.25, stdev=27458.48
clat (msec): min=5 , max=1578 , avg=319.33, stdev=261.16
lat (msec): min=5 , max=1578 , avg=321.77, stdev=264.30
bw (KB/s) : min= 15, max= 261, per=30.40%, avg=119.48, stdev=54.96
lat (usec) : 10=0.03%, 50=0.03%, 100=0.06%, 250=0.17%, 500=0.06%
lat (msec) : 4=0.15%, 10=1.83%, 20=6.64%, 50=9.34%, 100=10.25%
lat (msec) : 250=20.79%, 500=36.36%, 750=10.89%, 1000=1.80%,
2000=2.04%
cpu : usr=0.12%, sys=0.17%, ctx=3311, majf=0, minf=22
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=111.1%, 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=1712/w=1723/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=11080KB, aggrb=183KB/s, minb=31KB/s, maxb=113KB/s,
mint=60129msec, maxt=60326msec
WRITE: io=23756KB, aggrb=393KB/s, minb=115KB/s, maxb=278KB/s,
mint=60294msec, maxt=60326msec
Disk stats (read/write):
dm-1: ios=3253/10771, merge=0/0, ticks=559883/4212209,
in_queue=4777400, util=99.97%, aggrios=3255/10882, aggrmerge=0/0,
aggrticks=559956/4221317, aggrin_queue=4781292, aggrutil=99.97%
dm-0: ios=3255/10882, merge=0/0, ticks=559956/4221317,
in_queue=4781292, util=99.97%, aggrios=3249/7719, aggrmerge=6/3162,
aggrticks=554975/3062598, aggrin_queue=3617588, aggrutil=99.97%
sda: ios=3249/7719, merge=6/3162, ticks=554975/3062598,
in_queue=3617588, util=99.97%
================================================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=20441: Sat May 18 11:56:50 2013
write: io=28068KB, bw=476028B/s, iops=115, runt= 60378msec
slat (usec): min=9, max=947265, avg=402.78, stdev=14178.87
clat (msec): min=3, max=1635, avg=276.89, stdev=209.31
lat (msec): min=3, max=1635, avg=277.33, stdev=210.07
bw (KB /s): min= 0, max= 1019, per=98.32%, avg=466.03,
stdev=150.91
lat (msec) : 4=0.01%, 10=1.83%, 20=4.75%, 50=14.50%, 100=11.21%
lat (msec) : 250=5.22%, 500=52.95%, 750=7.29%, 1000=1.95%, 2000=0.73%
cpu : usr=0.19%, sys=0.40%, ctx=7319, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=109.5%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=6986/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=20442: Sat May 18 11:56:50 2013
read : io=3940.0KB, bw=66862B/s, iops=16, runt= 60341msec
clat (msec): min=6, max=762, avg=61.25, stdev=101.94
lat (msec): min=6, max=762, avg=61.25, stdev=101.94
bw (KB /s): min= 0, max= 133, per=45.87%, avg=64.67, stdev=23.10
lat (msec) : 10=2.44%, 20=55.43%, 50=24.77%, 100=1.22%, 250=3.65%
lat (msec) : 500=12.18%, 750=0.20%, 1000=0.10%
cpu : usr=0.03%, sys=0.06%, ctx=1076, majf=1075, minf=542
IO depths : 1=161.3%, 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=985/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=20443: Sat May 18 11:56:50 2013
read : io=3968.0KB, bw=67317B/s, iops=16, runt= 60359msec
clat (msec): min=4, max=781, avg=60.83, stdev=102.14
lat (msec): min=4, max=781, avg=60.83, stdev=102.14
bw (KB /s): min= 0, max= 143, per=46.11%, avg=65.02, stdev=23.70
lat (msec) : 10=3.83%, 20=55.04%, 50=23.59%, 100=1.31%, 250=3.23%
lat (msec) : 500=12.80%, 750=0.10%, 1000=0.10%
cpu : usr=0.05%, sys=0.05%, ctx=1084, majf=1081, minf=654
IO depths : 1=172.1%, 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=992/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=20444: Sat May 18 11:56:50
2013
read : io=671744B, bw=11149B/s, iops=2, runt= 60249msec
slat (usec): min=11, max=2602, avg=66.32, stdev=294.44
clat (msec): min=5, max=759, avg=123.67, stdev=127.15
lat (msec): min=5, max=759, avg=123.74, stdev=127.24
bw (KB /s): min= 3, max= 54, per=9.89%, avg=13.94, stdev=10.61
write: io=577536B, bw=9585B/s, iops=2, runt= 60249msec
slat (usec): min=9, max=774595, avg=7006.26, stdev=62617.17
clat (msec): min=32, max=837, avg=275.34, stdev=170.22
lat (msec): min=33, max=900, avg=283.34, stdev=179.59
bw (KB /s): min= 0, max= 16, per=1.93%, avg= 9.13, stdev= 3.62
lat (msec) : 10=2.30%, 20=17.05%, 50=8.52%, 100=6.23%, 250=34.10%
lat (msec) : 500=27.87%, 750=2.95%, 1000=0.98%
cpu : usr=0.01%, sys=0.02%, ctx=373, majf=0, minf=21
IO depths : 1=109.8%, 2=0.7%, 4=1.3%, 8=2.6%, 16=0.3%, 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=164/w=141/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=8564KB, aggrb=141KB/s, minb=10KB/s, maxb=65KB/s,
mint=60249msec, maxt=60359msec
WRITE: io=28632KB, aggrb=474KB/s, minb=9KB/s, maxb=464KB/s,
mint=60249msec, maxt=60378msec
Disk stats (read/write):
dm-1: ios=2345/12102, merge=0/0, ticks=153582/7496914,
in_queue=7659457, util=99.97%, aggrios=2345/12119, aggrmerge=0/0,
aggrticks=154444/7512052, aggrin_queue=7666496, aggrutil=99.95%
dm-0: ios=2345/12119, merge=0/0, ticks=154444/7512052,
in_queue=7666496, util=99.95%, aggrios=2345/8178, aggrmerge=0/3941,
aggrticks=153937/2410287, aggrin_queue=2564220, aggrutil=99.95%
sda: ios=2345/8178, merge=0/3941, ticks=153937/2410287,
in_queue=2564220, util=99.95%
--------------------------------------------------
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
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 11:18 ` Edoardo Comar
@ 2013-05-18 12:22 ` Jens Axboe
2013-05-18 17:03 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-18 12:22 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Sat, May 18 2013, Edoardo Comar wrote:
> In any case, even excluding the alleged bug, the difference in aggrb
> between the runs is very significant.
>
> fio-2.1-8-gb2c77 - run laying out the files (where I think we have a bug)
> Run status group 0 (all jobs):
> READ: io=31740MB, aggrb=541365KB/s, minb=18KB/s, maxb=298351KB/s,
> mint=60001msec, maxt=60036msec
> WRITE: io=42116KB, aggrb=701KB/s, minb=15KB/s, maxb=685KB/s,
> mint=60036msec, maxt=60054msec
>
> fio-2.0.13 - run reusing the files
> Run status group 0 (all jobs):
> READ: io=12856KB, aggrb=213KB/s, minb=37KB/s, maxb=135KB/s,
> mint=60242msec, maxt=60304msec
> WRITE: io=30048KB, aggrb=498KB/s, minb=134KB/s, maxb=363KB/s,
> mint=60262msec, maxt=60304msec
>
> ===========
>
> fio-2.0.13 - run laying out the files
> Run status group 0 (all jobs):
> READ: io=11080KB, aggrb=183KB/s, minb=31KB/s, maxb=113KB/s,
> mint=60129msec, maxt=60326msec
> WRITE: io=23756KB, aggrb=393KB/s, minb=115KB/s, maxb=278KB/s,
> mint=60294msec, maxt=60326msec
>
> fio-2.1-8-gb2c77 - run reusing the files
> Run status group 0 (all jobs):
> READ: io=8564KB, aggrb=141KB/s, minb=10KB/s, maxb=65KB/s,
> mint=60249msec, maxt=60359msec
> WRITE: io=28632KB, aggrb=474KB/s, minb=9KB/s, maxb=464KB/s,
> mint=60249msec, maxt=60378msec
>
> ===========
>
> if I run again reusing the existing files I get quite consistent results
> (within 5% which is ok over just a minute, IMHO)
> with the previous run of the same fio version that also reused the files.
> but the two versions report figures that are significantly different, the
> new fio is consistently slower.
>
> fio-2.0.13 - run reusing the files again
> Run status group 0 (all jobs):
> READ: io=12844KB, aggrb=212KB/s, minb=31KB/s, maxb=143KB/s,
> mint=60148msec, maxt=60316msec
> WRITE: io=30380KB, aggrb=503KB/s, minb=138KB/s, maxb=365KB/s,
> mint=60163msec, maxt=60316msec
>
> fio-2.1-8-gb2c77 - run reusing the files again
> Run status group 0 (all jobs):
> READ: io=8308KB, aggrb=137KB/s, minb=10KB/s, maxb=63KB/s,
> mint=60010msec, maxt=60207msec
> WRITE: io=27672KB, aggrb=459KB/s, minb=8KB/s, maxb=450KB/s,
> mint=60162msec, maxt=60268msec
>
>
> fio-2.0.13 - run reusing the files again
> Run status group 0 (all jobs):
> READ: io=11976KB, aggrb=198KB/s, minb=31KB/s, maxb=129KB/s,
> mint=60332msec, maxt=60442msec
> WRITE: io=29012KB, aggrb=479KB/s, minb=127KB/s, maxb=351KB/s,
> mint=60442msec, maxt=60484msec
>
> fio-2.1-8-gb2c77 - run reusing the files again
> Run status group 0 (all jobs):
> READ: io=8496KB, aggrb=141KB/s, minb=10KB/s, maxb=66KB/s,
> mint=60005msec, maxt=60029msec
> WRITE: io=27320KB, aggrb=454KB/s, minb=8KB/s, maxb=445KB/s,
> mint=60005msec, maxt=60112msec
>
> ... which should I trust ?
Very odd, it seems consistent for me with fio off git, both for initial
run and repeat runs (with existing files). I wonder if it's the clock.
Please send me the output of --cpuclock-test and also repeat your run
(both fresh and reuse) with clocksource=clock_gettime added to your
config file.
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 12:22 ` Jens Axboe
@ 2013-05-18 17:03 ` Edoardo Comar
2013-05-18 23:15 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 17:03 UTC (permalink / raw)
To: Jens Axboe, fio
>
> Very odd, it seems consistent for me with fio off git, both for initial
> run and repeat runs (with existing files). I wonder if it's the clock.
> Please send me the output of --cpuclock-test and also repeat your run
> (both fresh and reuse) with clocksource=clock_gettime added to your
> config file.
>
> --
> Jens Axboe
Hi Jens,
I am now using my laptop to generate the output I post here,
however the problem in the read value of aggrb being sky-high when files
were created,
occurred to me on a server machine.
I now noticed that if I keep running fio-2.1-8-gb2c77
I am getting too consistent results (please see below ) but with the
sky-high value for aggrb read.
If I run the 2.0.1.3 version (over the existsing files created by
fio-2.1-8-gb2c77) the value reported is 'normal'
and after that I can run fio-2.1-8-gb2c77 and it too reports normal values
!!!
so to be clear, I have now ran in this sequence
output-fio-2.1-8-gb2c77-clocksource-run01.txt //new files, read aggrb
skyhigh 563220KB/s
output-fio-2.1-8-gb2c77-clocksource-run02.txt //existing files, read
aggrb skyhigh 510402KB/s
output-fio-2.1-8-gb2c77-clocksource-run03.txt //existing files, read
aggrb skyhigh 550064KB/s
output-fio-2.0.1.3-clocksource.txt //existing files,
read aggrb normal 197KB/s
output-fio-2.1-8-gb2c77-clocksource-run04.txt //existing files, read
aggrb normal-ish 147KB/s
// but the
values is much lower than 2.0.1.3
//too hard
for me to know which one to trust !
HTH,
Edo
$ fio -version
fio-2.1-8-gb2c77
$ fio --cpuclock-test
cs: reliable_tsc: no
time 17293 cycles[0]=2525
time 17293 cycles[1]=2526
time 17293 cycles[2]=2527
time 17293 cycles[3]=2526
time 17293 cycles[4]=2526
time 17293 cycles[5]=2527
time 17293 cycles[6]=2528
time 17293 cycles[7]=2527
time 17293 cycles[8]=2528
time 17293 cycles[9]=2526
time 17293 cycles[10]=2526
time 17293 cycles[11]=2527
time 17293 cycles[12]=2527
time 17293 cycles[13]=2527
time 17293 cycles[14]=2526
time 17293 cycles[15]=2526
time 17293 cycles[16]=2525
time 17293 cycles[17]=2525
time 17293 cycles[18]=2526
time 17293 cycles[19]=2527
time 17293 cycles[20]=2527
time 17293 cycles[21]=2527
time 17293 cycles[22]=2527
time 17293 cycles[23]=2525
time 17293 cycles[24]=2526
time 17293 cycles[25]=2527
time 17293 cycles[26]=2526
time 17293 cycles[27]=2525
time 17293 cycles[28]=2526
time 17293 cycles[29]=2527
time 17293 cycles[30]=2527
time 17293 cycles[31]=2527
time 17293 cycles[32]=2527
time 17293 cycles[33]=2525
time 17293 cycles[34]=2525
time 17293 cycles[35]=2527
time 17293 cycles[36]=2527
time 17293 cycles[37]=2526
time 17293 cycles[38]=2527
time 17293 cycles[39]=2526
time 17293 cycles[40]=2527
time 17293 cycles[41]=2528
time 17293 cycles[42]=2527
time 17293 cycles[43]=2526
time 17293 cycles[44]=2525
time 17293 cycles[45]=2525
time 17293 cycles[46]=2526
time 17293 cycles[47]=2526
time 17293 cycles[48]=2526
time 17293 cycles[49]=2527
time 17293 avg: 2527
time 17293 mean=2526.832000, S=0.151963
time 17293 inv_cycles_per_usec=6639
cs: Testing 2 CPUs
cs: cpu 1: 19177735 clocks seen
cs: cpu 0: 20651328 clocks seen
cs: Pass!
===========================================
$ cat four-threads-randio-016-clocksource.fio
[global]
size=256m
directory=/mnt/vda2/tmp
invalidate=1
runtime=60
time_based
ramp_time=5
clat_percentiles=0
direct=1
clocksource=clock_gettime
[bgwriter]
rw=randwrite
iodepth=32
ioengine=libaio
[queryA]
rw=randread
ioengine=mmap
thinktime=3
[queryB]
rw=randread
ioengine=mmap
thinktime=5
[bgupdater]
rw=randrw
ioengine=libaio
iodepth=16
size=64m
thinktime=5
===========================================
#output-fio-2.1-8-gb2c77-clocksource-run01.txt
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
bgwriter: (groupid=0, jobs=1): err= 0: pid=7833: Sat May 18 17:41:27 2013
write: io=41796KB, bw=712167B/s, iops=173, runt= 60097msec
slat (usec): min=10, max=636557, avg=202.75, stdev=7986.99
clat (msec): min=1, max=2193, avg=184.61, stdev=153.37
lat (msec): min=1, max=2193, avg=184.83, stdev=153.68
bw (KB /s): min= 0, max= 1304, per=100.00%, avg=713.81,
stdev=253.15
lat (msec) : 2=0.01%, 4=0.08%, 10=0.86%, 20=0.93%, 50=8.12%
lat (msec) : 100=21.95%, 250=40.41%, 500=25.37%, 750=2.02%, 1000=0.19%
lat (msec) : 2000=0.26%, >=2000=0.10%
cpu : usr=0.18%, sys=0.49%, ctx=11011, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=108.9%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=10418/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=7834: Sat May 18 17:41:27 2013
read : io=17554MB, bw=299582KB/s, iops=74895, runt= 60001msec
clat (usec): min=1, max=11002, avg= 3.85, stdev=17.84
lat (usec): min=2, max=11003, avg= 5.34, stdev=20.65
bw (KB /s): min= 0, max=321288, per=52.73%, avg=296984.06,
stdev=30994.78
lat (usec) : 2=0.01%, 4=46.18%, 10=53.27%, 20=0.32%, 50=0.12%
lat (usec) : 100=0.01%, 250=0.08%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=87.93%, sys=12.64%, ctx=31565, majf=0, minf=4560748
IO depths : 1=107.5%, 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=4493804/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=7835: Sat May 18 17:41:27 2013
read : io=15449MB, bw=263667KB/s, iops=65916, runt= 60001msec
clat (usec): min=1, max=8042, avg= 3.84, stdev=18.36
lat (usec): min=2, max=8043, avg= 5.18, stdev=20.30
bw (KB /s): min= 0, max=286672, per=46.41%, avg=261403.13,
stdev=28405.98
lat (usec) : 2=0.01%, 4=43.00%, 10=56.53%, 20=0.32%, 50=0.10%
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
cpu : usr=90.94%, sys=10.95%, ctx=26807, majf=0, minf=4092290
IO depths : 1=107.8%, 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=3955067/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=7836: Sat May 18 17:41:27 2013
read : io=1120.0KB, bw=19112B/s, iops=4, runt= 60006msec
slat (usec): min=9, max=50604, avg=436.92, stdev=3906.57
clat (usec): min=365, max=528456, avg=120418.40, stdev=134948.37
lat (usec): min=402, max=549557, avg=120724.24, stdev=135484.13
bw (KB /s): min= 0, max= 87, per=0.00%, avg=17.95, stdev=13.06
write: io=991232B, bw=16518B/s, iops=4, runt= 60006msec
slat (usec): min=25, max=442604, avg=3416.67, stdev=32428.43
clat (usec): min=712, max=1597.7K, avg=104399.00, stdev=166691.30
lat (usec): min=769, max=1597.8K, avg=108249.43, stdev=170645.26
bw (KB /s): min= 2, max= 43, per=2.20%, avg=15.67, stdev= 8.30
lat (usec) : 500=0.57%, 750=0.77%, 1000=0.96%
lat (msec) : 2=0.57%, 4=5.56%, 10=20.88%, 20=4.79%, 50=8.81%
lat (msec) : 100=20.69%, 250=19.35%, 500=16.09%, 750=0.38%, 2000=0.57%
cpu : usr=0.02%, sys=0.04%, ctx=600, majf=0, minf=21
IO depths : 1=109.4%, 2=0.4%, 4=0.8%, 8=1.5%, 16=0.2%, 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=280/w=242/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=33004MB, aggrb=563220KB/s, minb=18KB/s, maxb=299581KB/s,
mint=60001msec, maxt=60006msec
WRITE: io=42764KB, aggrb=711KB/s, minb=16KB/s, maxb=695KB/s,
mint=60006msec, maxt=60097msec
Disk stats (read/write):
dm-1: ios=306/13827, merge=0/0, ticks=38330/2387423, in_queue=2425763,
util=100.00%, aggrios=313/13844, aggrmerge=0/0, aggrticks=38390/2387406,
aggrin_queue=2425797, aggrutil=100.00%
dm-0: ios=313/13844, merge=0/0, ticks=38390/2387406, in_queue=2425797,
util=100.00%, aggrios=313/11823, aggrmerge=0/2021,
aggrticks=38352/2118973, aggrin_queue=2157320, aggrutil=99.99%
sda: ios=313/11823, merge=0/2021, ticks=38352/2118973, in_queue=2157320,
util=99.99%
===========================================
#output-fio-2.1-8-gb2c77-clocksource-run02.txt
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=21424: Sat May 18 17:45:58 2013
write: io=38652KB, bw=656531B/s, iops=159, runt= 60286msec
slat (usec): min=10, max=376955, avg=386.16, stdev=9359.89
clat (msec): min=1, max=1880, avg=199.44, stdev=167.99
lat (msec): min=1, max=1880, avg=199.85, stdev=168.52
bw (KB /s): min= 0, max= 1235, per=100.00%, avg=657.64,
stdev=264.27
lat (msec) : 2=0.01%, 4=0.30%, 10=1.44%, 20=1.90%, 50=10.38%
lat (msec) : 100=15.62%, 250=39.17%, 500=26.82%, 750=3.54%, 1000=0.65%
lat (msec) : 2000=0.48%
cpu : usr=0.22%, sys=0.57%, ctx=9776, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=108.9%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=9632/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=21425: Sat May 18 17:45:58 2013
read : io=15820MB, bw=269982KB/s, iops=67495, runt= 60001msec
clat (usec): min=1, max=20132, avg= 4.43, stdev=53.74
lat (usec): min=2, max=24895, avg= 6.03, stdev=60.63
bw (KB /s): min= 0, max=316976, per=52.43%, avg=267610.96,
stdev=45195.79
lat (usec) : 2=0.01%, 4=42.93%, 10=56.40%, 20=0.34%, 50=0.17%
lat (usec) : 100=0.04%, 250=0.06%, 500=0.02%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
cpu : usr=79.33%, sys=12.15%, ctx=43544, majf=0, minf=4143503
IO depths : 1=108.4%, 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=4049802/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=21426: Sat May 18 17:45:58 2013
read : io=14204MB, bw=242415KB/s, iops=60603, runt= 60001msec
clat (usec): min=1, max=31102, avg= 4.25, stdev=46.56
lat (usec): min=2, max=31102, avg= 5.67, stdev=52.90
bw (KB /s): min= 0, max=284624, per=47.10%, avg=240381.17,
stdev=38838.46
lat (usec) : 2=0.01%, 4=40.74%, 10=58.81%, 20=0.32%, 50=0.05%
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
cpu : usr=83.81%, sys=10.27%, ctx=20480, majf=0, minf=3774654
IO depths : 1=108.4%, 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=3636281/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=21427: Sat May 18 17:45:58
2013
read : io=823296B, bw=13667B/s, iops=3, runt= 60237msec
slat (usec): min=12, max=14578, avg=152.95, stdev=1253.54
clat (usec): min=440, max=695116, avg=132719.79, stdev=136919.31
lat (usec): min=479, max=695136, avg=132886.06, stdev=136970.47
bw (KB /s): min= 2, max= 63, per=0.00%, avg=16.68, stdev=11.82
write: io=729088B, bw=12103B/s, iops=2, runt= 60237msec
slat (usec): min=21, max=368815, avg=5889.06, stdev=36996.94
clat (msec): min=12, max=1888, avg=181.73, stdev=304.33
lat (msec): min=12, max=1900, avg=188.32, stdev=307.45
bw (KB /s): min= 0, max= 30, per=1.95%, avg=12.72, stdev= 7.04
lat (usec) : 500=0.26%
lat (msec) : 2=0.26%, 4=3.43%, 10=18.47%, 20=3.43%, 50=10.03%
lat (msec) : 100=20.05%, 250=22.96%, 500=18.47%, 750=0.53%, 1000=0.26%
lat (msec) : 2000=1.85%
cpu : usr=0.02%, sys=0.02%, ctx=467, majf=0, minf=21
IO depths : 1=111.9%, 2=0.5%, 4=1.1%, 8=2.1%, 16=0.3%, 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=201/w=178/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=30025MB, aggrb=510402KB/s, minb=13KB/s, maxb=269982KB/s,
mint=60001msec, maxt=60237msec
WRITE: io=39364KB, aggrb=652KB/s, minb=11KB/s, maxb=641KB/s,
mint=60237msec, maxt=60286msec
Disk stats (read/write):
dm-1: ios=265/12202, merge=0/0, ticks=37253/2417250, in_queue=2459189,
util=99.96%, aggrios=309/12276, aggrmerge=0/0, aggrticks=42704/2424620,
aggrin_queue=2467343, aggrutil=99.96%
dm-0: ios=309/12276, merge=0/0, ticks=42704/2424620, in_queue=2467343,
util=99.96%, aggrios=274/11161, aggrmerge=35/1128,
aggrticks=38012/2211094, aggrin_queue=2249116, aggrutil=99.96%
sda: ios=274/11161, merge=35/1128, ticks=38012/2211094,
in_queue=2249116, util=99.96%
===========================================
#output-fio-2.1-8-gb2c77-clocksource-run03.txt
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=28992: Sat May 18 17:48:33 2013
write: io=43084KB, bw=734443B/s, iops=178, runt= 60070msec
slat (usec): min=9, max=267785, avg=174.06, stdev=5320.19
clat (msec): min=3, max=630, avg=178.97, stdev=109.17
lat (msec): min=3, max=707, avg=179.14, stdev=109.61
bw (KB /s): min= 0, max= 1304, per=98.95%, avg=725.33,
stdev=228.04
lat (msec) : 4=0.01%, 10=0.16%, 20=1.02%, 50=10.21%, 100=16.56%
lat (msec) : 250=44.13%, 500=27.49%, 750=0.70%
cpu : usr=0.29%, sys=0.57%, ctx=11390, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=109.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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=10740/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=28993: Sat May 18 17:48:33 2013
read : io=17010MB, bw=290296KB/s, iops=72574, runt= 60001msec
clat (usec): min=1, max=18751, avg= 4.00, stdev=28.23
lat (usec): min=2, max=21993, avg= 5.51, stdev=33.32
bw (KB /s): min= 0, max=324568, per=52.32%, avg=287819.09,
stdev=33580.72
lat (usec) : 2=0.01%, 4=45.23%, 10=54.21%, 20=0.33%, 50=0.10%
lat (usec) : 100=0.04%, 250=0.06%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=85.30%, sys=12.45%, ctx=30102, majf=0, minf=4436073
IO depths : 1=107.7%, 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=4354517/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=28994: Sat May 18 17:48:33 2013
read : io=15244MB, bw=260154KB/s, iops=65038, runt= 60001msec
clat (usec): min=1, max=15439, avg= 3.92, stdev=26.11
lat (usec): min=2, max=15439, avg= 5.28, stdev=29.16
bw (KB /s): min= 0, max=285960, per=46.91%, avg=258013.36,
stdev=30605.46
lat (usec) : 2=0.01%, 4=42.79%, 10=56.72%, 20=0.32%, 50=0.12%
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
cpu : usr=89.37%, sys=11.14%, ctx=30316, majf=0, minf=4039065
IO depths : 1=107.9%, 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=3902373/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=28995: Sat May 18 17:48:33
2013
read : io=1092.0KB, bw=18622B/s, iops=4, runt= 60045msec
slat (usec): min=9, max=101133, avg=470.37, stdev=6073.32
clat (usec): min=362, max=555207, avg=128303.00, stdev=133601.26
lat (usec): min=391, max=555226, avg=128826.96, stdev=134014.07
bw (KB /s): min= 5, max= 68, per=0.00%, avg=18.53, stdev=12.06
write: io=987136B, bw=16439B/s, iops=4, runt= 60045msec
slat (usec): min=21, max=67195, avg=1354.70, stdev=7790.18
clat (msec): min=21, max=442, avg=101.90, stdev=74.20
lat (msec): min=21, max=497, avg=103.19, stdev=79.07
bw (KB /s): min= 0, max= 31, per=2.16%, avg=15.86, stdev= 6.93
lat (usec) : 500=0.39%, 1000=0.19%
lat (msec) : 2=0.19%, 4=3.70%, 10=18.68%, 20=4.28%, 50=9.14%
lat (msec) : 100=20.43%, 250=28.02%, 500=14.59%, 750=0.39%
cpu : usr=0.03%, sys=0.03%, ctx=598, majf=0, minf=21
IO depths : 1=109.1%, 2=0.4%, 4=0.8%, 8=1.6%, 16=0.2%, 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=273/w=241/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=32255MB, aggrb=550064KB/s, minb=18KB/s, maxb=290296KB/s,
mint=60001msec, maxt=60045msec
WRITE: io=44048KB, aggrb=733KB/s, minb=16KB/s, maxb=717KB/s,
mint=60045msec, maxt=60070msec
Disk stats (read/write):
dm-1: ios=305/15205, merge=0/0, ticks=37839/3980140, in_queue=4021506,
util=99.96%, aggrios=305/15237, aggrmerge=0/0, aggrticks=38072/3988561,
aggrin_queue=4026637, aggrutil=99.94%
dm-0: ios=305/15237, merge=0/0, ticks=38072/3988561, in_queue=4026637,
util=99.94%, aggrios=305/12165, aggrmerge=0/3072, aggrticks=38045/2152312,
aggrin_queue=2190352, aggrutil=99.94%
sda: ios=305/12165, merge=0/3072, ticks=38045/2152312, in_queue=2190352,
util=99.94%
======================================================
#output-fio-2.0.1.3-clocksource.txt
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=6668: Sat May 18 17:51:55 2013
write: io=22280KB, bw=378384 B/s, iops=91 , runt= 60295msec
slat (usec): min=9 , max=576672 , avg=563.21, stdev=13804.80
clat (msec): min=4 , max=1524 , avg=347.56, stdev=245.47
lat (msec): min=4 , max=1525 , avg=348.07, stdev=246.11
bw (KB/s) : min= 0, max= 888, per=75.11%, avg=374.79,
stdev=141.95
lat (msec) : 10=0.83%, 20=3.68%, 50=9.35%, 100=9.04%, 250=9.24%
lat (msec) : 500=46.34%, 750=16.14%, 1000=4.17%, 2000=1.75%
cpu : usr=0.14%, sys=0.34%, ctx=5754, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.3%, 32=108.9%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=5539/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=6669: Sat May 18 17:51:55 2013
read : io=1976.0KB, bw=33713 B/s, iops=8 , runt= 60018msec
clat (msec): min=6 , max=649 , avg=121.48, stdev=147.39
lat (msec): min=6 , max=649 , avg=121.48, stdev=147.39
bw (KB/s) : min= 0, max= 119, per=16.55%, avg=32.60, stdev=20.17
lat (msec) : 10=3.04%, 20=33.81%, 50=21.86%, 100=6.88%, 250=10.32%
lat (msec) : 500=22.06%, 750=2.02%
cpu : usr=0.01%, sys=0.12%, ctx=601, majf=546, minf=26
IO depths : 1=110.5%, 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=494/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=6670: Sat May 18 17:51:55 2013
read : io=2268.0KB, bw=38705 B/s, iops=9 , runt= 60002msec
clat (msec): min=6 , max=698 , avg=105.81, stdev=138.63
lat (msec): min=6 , max=698 , avg=105.81, stdev=138.63
bw (KB/s) : min= 0, max= 125, per=18.86%, avg=37.16, stdev=21.14
lat (msec) : 10=3.70%, 20=37.21%, 50=23.81%, 100=5.47%, 250=8.29%
lat (msec) : 500=20.28%, 750=1.23%
cpu : usr=0.02%, sys=0.11%, ctx=649, majf=627, minf=26
IO depths : 1=110.6%, 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=567/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=6671: Sat May 18 17:51:55 2013
read : io=7612.0KB, bw=129593 B/s, iops=31 , runt= 60147msec
slat (usec): min=6 , max=393298 , avg=480.26, stdev=10901.42
clat (usec): min=2 , max=738467 , avg=196112.75, stdev=151447.12
lat (msec): min=3 , max=738 , avg=196.43, stdev=151.24
bw (KB/s) : min= 0, max= 347, per=65.17%, avg=128.39, stdev=64.75
write: io=7836.0KB, bw=133407 B/s, iops=32 , runt= 60147msec
slat (usec): min=9 , max=280436 , avg=573.65, stdev=9113.92
clat (msec): min=5 , max=1531 , avg=303.01, stdev=218.43
lat (msec): min=5 , max=1531 , avg=303.62, stdev=219.15
bw (KB/s) : min= 7, max= 308, per=26.76%, avg=133.54, stdev=55.90
lat (usec) : 4=0.03%, 50=0.03%, 250=0.03%, 500=0.03%
lat (msec) : 4=0.03%, 10=1.09%, 20=6.73%, 50=10.71%, 100=10.92%
lat (msec) : 250=21.55%, 500=39.12%, 750=8.60%, 1000=1.12%, 2000=0.42%
cpu : usr=0.13%, sys=0.24%, ctx=4015, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=108.3%, 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=1896/w=1951/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=11856KB, aggrb=197KB/s, minb=32KB/s, maxb=126KB/s,
mint=60002msec, maxt=60147msec
WRITE: io=30116KB, aggrb=499KB/s, minb=130KB/s, maxb=369KB/s,
mint=60147msec, maxt=60295msec
Disk stats (read/write):
dm-1: ios=3232/8863, merge=0/0, ticks=520001/2905976,
in_queue=3432267, util=99.97%, aggrios=3238/8882, aggrmerge=0/0,
aggrticks=522983/2914392, aggrin_queue=3437376, aggrutil=99.95%
dm-0: ios=3238/8882, merge=0/0, ticks=522983/2914392,
in_queue=3437376, util=99.95%, aggrios=3237/8331, aggrmerge=1/551,
aggrticks=522374/2779308, aggrin_queue=3301679, aggrutil=99.95%
sda: ios=3237/8331, merge=1/551, ticks=522374/2779308, in_queue=3301679,
util=99.95%
===========================================
#output-fio-2.1-8-gb2c77-clocksource-run04.txt
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 processes
bgwriter: (groupid=0, jobs=1): err= 0: pid=14785: Sat May 18 17:54:34 2013
write: io=26688KB, bw=453201B/s, iops=110, runt= 60301msec
slat (usec): min=9, max=378442, avg=289.28, stdev=8413.42
clat (msec): min=4, max=1352, avg=290.98, stdev=210.53
lat (msec): min=4, max=1352, avg=291.29, stdev=210.88
bw (KB /s): min= 0, max= 988, per=99.50%, avg=448.73,
stdev=171.09
lat (msec) : 10=1.79%, 20=5.21%, 50=13.45%, 100=10.54%, 250=4.47%
lat (msec) : 500=52.76%, 750=10.15%, 1000=1.39%, 2000=0.71%
cpu : usr=0.19%, sys=0.38%, ctx=6951, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=109.2%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=6641/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=14786: Sat May 18 17:54:34 2013
read : io=4132.0KB, bw=70321B/s, iops=17, runt= 60169msec
clat (msec): min=3, max=824, avg=58.24, stdev=99.91
lat (msec): min=3, max=824, avg=58.24, stdev=99.91
bw (KB /s): min= 0, max= 119, per=46.20%, avg=67.91, stdev=18.24
lat (msec) : 4=0.10%, 10=5.91%, 20=57.12%, 50=20.52%, 100=0.97%
lat (msec) : 250=1.36%, 500=13.84%, 750=0.10%, 1000=0.10%
cpu : usr=0.05%, sys=0.04%, ctx=1120, majf=1118, minf=570
IO depths : 1=160.6%, 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=1033/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=14787: Sat May 18 17:54:34 2013
read : io=4076.0KB, bw=69382B/s, iops=16, runt= 60157msec
clat (usec): min=740, max=695534, avg=59021.33, stdev=99976.29
lat (usec): min=741, max=695536, avg=59022.59, stdev=99976.29
bw (KB /s): min= 0, max= 124, per=46.10%, avg=67.77, stdev=17.54
lat (usec) : 750=0.10%
lat (msec) : 4=0.10%, 10=5.10%, 20=58.98%, 50=19.14%, 100=0.79%
lat (msec) : 250=1.96%, 500=13.64%, 750=0.20%
cpu : usr=0.06%, sys=0.05%, ctx=1111, majf=1107, minf=653
IO depths : 1=169.9%, 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=1019/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=14788: Sat May 18 17:54:34
2013
read : io=663552B, bw=11029B/s, iops=2, runt= 60163msec
slat (usec): min=7, max=261587, avg=2302.71, stdev=21049.01
clat (usec): min=2, max=680737, avg=136896.22, stdev=132669.42
lat (msec): min=7, max=680, avg=139.35, stdev=133.27
bw (KB /s): min= 0, max= 39, per=8.74%, avg=12.84, stdev= 9.34
write: io=540672B, bw=8986B/s, iops=2, runt= 60163msec
slat (usec): min=9, max=100617, avg=1968.88, stdev=13441.24
clat (msec): min=44, max=973, avg=282.50, stdev=186.38
lat (msec): min=44, max=973, avg=284.72, stdev=188.77
bw (KB /s): min= 3, max= 22, per=1.92%, avg= 8.65, stdev= 4.07
lat (usec) : 4=0.34%
lat (msec) : 10=1.02%, 20=15.31%, 50=10.88%, 100=7.82%, 250=26.87%
lat (msec) : 500=32.99%, 750=3.74%, 1000=1.02%
cpu : usr=0.01%, sys=0.02%, ctx=341, majf=0, minf=21
IO depths : 1=106.5%, 2=0.7%, 4=1.4%, 8=2.7%, 16=0.3%, 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=162/w=132/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=8856KB, aggrb=147KB/s, minb=10KB/s, maxb=68KB/s,
mint=60157msec, maxt=60169msec
WRITE: io=27216KB, aggrb=451KB/s, minb=8KB/s, maxb=442KB/s,
mint=60163msec, maxt=60301msec
Disk stats (read/write):
dm-1: ios=2409/10744, merge=0/0, ticks=157436/4722979,
in_queue=4888552, util=99.97%, aggrios=2414/10759, aggrmerge=0/0,
aggrticks=157652/4733035, aggrin_queue=4890687, aggrutil=99.95%
dm-0: ios=2414/10759, merge=0/0, ticks=157652/4733035,
in_queue=4890687, util=99.95%, aggrios=2414/7627, aggrmerge=0/3132,
aggrticks=157316/2161791, aggrin_queue=2319104, aggrutil=99.95%
sda: ios=2414/7627, merge=0/3132, ticks=157316/2161791,
in_queue=2319104, util=99.95%
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 17:03 ` Edoardo Comar
@ 2013-05-18 23:15 ` Edoardo Comar
2013-05-22 8:28 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-18 23:15 UTC (permalink / raw)
To: Jens Axboe, fio
I just tried the code from git on my personal macbook.
I replaced libaio with posixaio in the config file and
the ultra-high aggrb read is there too (files being created).
is caused by the contribution to the aggregate stats
of the second of the two query threads [queryB]
edoardos-macbook-pro:devel edoardo$ sudo fio four-threads-randio-016.fio
fio: this platform does not support process shared mutexes, forcing use of
threads. Use the 'thread' option to get rid of this warning.
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=posixaio,
iodepth=32
fio: this platform does not support process shared mutexes, forcing use of
threads. Use the 'thread' option to get rid of this warning.
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
fio: this platform does not support process shared mutexes, forcing use of
threads. Use the 'thread' option to get rid of this warning.
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
fio: this platform does not support process shared mutexes, forcing use of
threads. Use the 'thread' option to get rid of this warning.
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=posixaio,
iodepth=16
fio-2.1-8-gb2c77
Starting 4 threads
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
Jobs: 1 (f=1): [___m] [26.9% done] [170.4MB/342KB/0KB /s] [43.6K/85/0
iops] [eta 02m:59s]
bgwriter: (groupid=0, jobs=1): err= 0: pid=4611: Sat May 18 23:38:37 2013
write: io=9632.0KB, bw=164145B/s, iops=39, runt= 60088msec
slat (usec): min=0, max=3804, avg= 4.82, stdev=74.40
clat (msec): min=6, max=1308, avg=376.14, stdev=137.62
lat (msec): min=6, max=1308, avg=376.15, stdev=137.61
bw (KB /s): min= 1, max= 456, per=94.60%, avg=158.93, stdev=47.60
lat (msec) : 10=0.08%, 50=0.17%, 100=1.38%, 250=9.82%, 500=77.03%
lat (msec) : 750=10.86%, 1000=0.50%, 2000=0.71%
cpu : usr=66.60%, sys=34.47%, ctx=70482, majf=2210,
minf=4379188
IO depths : 1=0.1%, 2=0.1%, 4=0.3%, 8=109.0%, 16=2.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=99.9%, 8=0.1%, 16=0.1%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=2394/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=4867: Sat May 18 23:38:37 2013
read : io=36340KB, bw=620037B/s, iops=151, runt= 60016msec
clat (usec): min=6, max=446986, avg=6596.70, stdev=15779.91
lat (usec): min=6, max=446987, avg=6597.95, stdev=15780.52
bw (KB /s): min= 0, max= 1773, per=0.22%, avg=601.57, stdev=232.79
lat (usec) : 10=64.65%, 20=11.88%, 50=0.57%, 100=0.26%, 250=0.30%
lat (usec) : 500=0.08%, 750=0.17%, 1000=0.64%
lat (msec) : 2=0.20%, 4=0.19%, 10=1.66%, 20=1.44%, 50=17.56%
lat (msec) : 100=0.32%, 250=0.04%, 500=0.06%
cpu : usr=66.68%, sys=34.51%, ctx=70432, majf=2210,
minf=4379191
IO depths : 1=109.9%, 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=9085/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=5123: Sat May 18 23:38:37 2013
read : io=16314MB, bw=278418KB/s, iops=69604, runt= 60001msec
clat (usec): min=0, max=23157, avg= 7.17, stdev=36.81
lat (usec): min=0, max=23158, avg= 7.77, stdev=37.02
bw (KB /s): min= 0, max=313216, per=99.38%, avg=276190.69,
stdev=34663.74
lat (usec) : 2=0.01%, 4=0.01%, 10=98.91%, 20=0.65%, 50=0.17%
lat (usec) : 100=0.13%, 250=0.09%, 500=0.02%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
cpu : usr=66.70%, sys=34.52%, ctx=70426, majf=2209,
minf=4379192
IO depths : 1=109.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=4176340/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=5379: Sat May 18 23:38:37 2013
read : io=663552B, bw=11015B/s, iops=2, runt= 60240msec
slat (usec): min=1, max=128, avg= 6.28, stdev=10.86
clat (usec): min=2, max=628813, avg=193318.38, stdev=145748.34
lat (usec): min=11, max=628817, avg=193324.99, stdev=145743.69
bw (KB /s): min= 2, max= 396, per=0.00%, avg=13.24, stdev=44.04
write: io=544768B, bw=9043B/s, iops=2, runt= 60240msec
slat (usec): min=1, max=301, avg=16.59, stdev=41.75
clat (usec): min=2, max=1131.3K, avg=207503.18, stdev=201150.42
lat (usec): min=15, max=1131.3K, avg=207521.24, stdev=201134.90
bw (KB /s): min= 0, max= 357, per=7.78%, avg=13.06, stdev=43.83
lat (usec) : 4=14.58%, 10=4.41%, 20=2.71%, 50=2.71%, 100=0.68%
lat (usec) : 500=0.34%
lat (msec) : 4=1.36%, 10=4.75%, 20=0.68%, 50=0.34%, 100=2.03%
lat (msec) : 250=14.92%, 500=48.14%, 750=1.36%, 1000=0.34%, 2000=0.68%
cpu : usr=66.44%, sys=34.39%, ctx=70611, majf=2210,
minf=4379189
IO depths : 1=107.8%, 2=0.7%, 4=1.4%, 8=0.3%, 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.1%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=162/w=133/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=16350MB, aggrb=277927KB/s, minb=10KB/s, maxb=278418KB/s,
mint=60001msec, maxt=60240msec
WRITE: io=10164KB, aggrb=168KB/s, minb=8KB/s, maxb=160KB/s,
mint=60088msec, maxt=60240msec
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-18 23:15 ` Edoardo Comar
@ 2013-05-22 8:28 ` Edoardo Comar
2013-05-22 8:57 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-22 8:28 UTC (permalink / raw)
To: Jens Axboe, fio
>
> I just tried the code from git on my personal macbook.
> I replaced libaio with posixaio in the config file and
> the ultra-high aggrb read is there too (files being created).
>
> is caused by the contribution to the aggregate stats
> of the second of the two query threads [queryB]
>
>
> Run status group 0 (all jobs):
> READ: io=16350MB, aggrb=277927KB/s, minb=10KB/s, maxb=278418KB/s,
> mint=60001msec, maxt=60240msec
> WRITE: io=10164KB, aggrb=168KB/s, minb=8KB/s, maxb=160KB/s,
> mint=60088msec, maxt=60240msec
Hi, are there any insight on the READ aggrb issue?
I'm fairly confident it's a bug now that I see it happening even on
different platforms (mac and linux)
thanks
Edo
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 8:28 ` Edoardo Comar
@ 2013-05-22 8:57 ` Jens Axboe
2013-05-22 10:03 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-22 8:57 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Wed, May 22 2013, Edoardo Comar wrote:
> >
> > I just tried the code from git on my personal macbook.
> > I replaced libaio with posixaio in the config file and
> > the ultra-high aggrb read is there too (files being created).
> >
> > is caused by the contribution to the aggregate stats
> > of the second of the two query threads [queryB]
> >
> >
> > Run status group 0 (all jobs):
> > READ: io=16350MB, aggrb=277927KB/s, minb=10KB/s, maxb=278418KB/s,
> > mint=60001msec, maxt=60240msec
> > WRITE: io=10164KB, aggrb=168KB/s, minb=8KB/s, maxb=160KB/s,
> > mint=60088msec, maxt=60240msec
>
> Hi, are there any insight on the READ aggrb issue?
> I'm fairly confident it's a bug now that I see it happening even on
> different platforms (mac and linux)
It would help a lot if you could do a git bisect and reliably find out
which commit caused the problem. The procedure is something like this,
assuming you are in the fio git repository:
$ git bisect start
$ git bisect good fio-2.0.13
$ git bisect bad master
Then make clean and make fio, run the job file:
$ make clean; make
$ ./fio <jobfile>
Run the job file as many times as is required to reliably tell whether
this is a good or a bad build. Lets assume the first one is good, you
would then do:
$ git bisect good
and repeat the make clean && make && run of job file. If the result was
bad, you'd do git bisect bad.
You continue this process until it tells you which one is the offending
commit. Then you mail that here :-)
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 8:57 ` Jens Axboe
@ 2013-05-22 10:03 ` Edoardo Comar
2013-05-22 10:15 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-22 10:03 UTC (permalink / raw)
To: Jens Axboe; +Cc: fio
>
> It would help a lot if you could do a git bisect and reliably find out
> which commit caused the problem. The procedure is something like this,
> assuming you are in the fio git repository:
>
> You continue this process until it tells you which one is the offending
> commit. Then you mail that here :-)
>
> --
> Jens Axboe
>
Thanks for the detailed explanataion
please find the log below,
Edo
[ecomar@edow500 fio]$ git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[78c1111eacdb594e0488d5adc508091fc2a3af88] Fix variable type warning
[ecomar@edow500 fio]$ git bisect log
git bisect start
# good: [ffa93ca9d8d37ef795904773a22bf4ea77f58373] Fio 2.0.13
git bisect good ffa93ca9d8d37ef795904773a22bf4ea77f58373
# bad: [4728b3c82f07612d64b79a67adc31dd9ca3c79fc] fusion atomic: retrieve
all capabilities and support larger writes
git bisect bad 4728b3c82f07612d64b79a67adc31dd9ca3c79fc
# good: [73cfb8a7da365c37253662477edb54ecc19575df] Merge branch 'gfio' of
ssh://brick.kernel.dk/data/git/fio into gfio
git bisect good 73cfb8a7da365c37253662477edb54ecc19575df
# bad: [44583e022320424d145dbf01d51480e4c9a71126] Fixup commit error in
56c796
git bisect bad 44583e022320424d145dbf01d51480e4c9a71126
# bad: [fd112d34a2cfdc2d9efcd394e38b6d87b357c23d] Fix percentile_list
option
git bisect bad fd112d34a2cfdc2d9efcd394e38b6d87b357c23d
# bad: [cfd94f79c362da249d22a59b6ede367ce3d2ba1d] configure: fixup Windows
git bisect bad cfd94f79c362da249d22a59b6ede367ce3d2ba1d
# bad: [17f0fd39d8b1f8edb420721c38302bd46254db03] axmap: clear
map->first_free when we reset it
git bisect bad 17f0fd39d8b1f8edb420721c38302bd46254db03
# bad: [c81f9347e5849a6b97a02f215f1c474e27c79f1a] Add CONFIG_64BIT_LLP64,
CONFIG_POSIX_FALLOCATE and CONFIG_LINUX_FALLOCATE to Makefile.
git bisect bad c81f9347e5849a6b97a02f215f1c474e27c79f1a
# bad: [d537c08b0eacdeb05835ee8c5f269b872239713a] Add a check avoid
segfault
git bisect bad d537c08b0eacdeb05835ee8c5f269b872239713a
# bad: [67bf982340d95ca98098ea050b54b4c7adb116c0] Add configure script
git bisect bad 67bf982340d95ca98098ea050b54b4c7adb116c0
[ecomar@edow500 fio]$
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 10:03 ` Edoardo Comar
@ 2013-05-22 10:15 ` Jens Axboe
2013-05-22 10:18 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-22 10:15 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Wed, May 22 2013, Edoardo Comar wrote:
> >
> > It would help a lot if you could do a git bisect and reliably find out
> > which commit caused the problem. The procedure is something like this,
> > assuming you are in the fio git repository:
> >
> > You continue this process until it tells you which one is the offending
> > commit. Then you mail that here :-)
> >
> > --
> > Jens Axboe
> >
>
> Thanks for the detailed explanataion
> please find the log below,
> Edo
>
> [ecomar@edow500 fio]$ git bisect bad
> Bisecting: 0 revisions left to test after this (roughly 0 steps)
> [78c1111eacdb594e0488d5adc508091fc2a3af88] Fix variable type warning
>
> [ecomar@edow500 fio]$ git bisect log
> git bisect start
> # good: [ffa93ca9d8d37ef795904773a22bf4ea77f58373] Fio 2.0.13
> git bisect good ffa93ca9d8d37ef795904773a22bf4ea77f58373
> # bad: [4728b3c82f07612d64b79a67adc31dd9ca3c79fc] fusion atomic: retrieve
> all capabilities and support larger writes
> git bisect bad 4728b3c82f07612d64b79a67adc31dd9ca3c79fc
> # good: [73cfb8a7da365c37253662477edb54ecc19575df] Merge branch 'gfio' of
> ssh://brick.kernel.dk/data/git/fio into gfio
> git bisect good 73cfb8a7da365c37253662477edb54ecc19575df
> # bad: [44583e022320424d145dbf01d51480e4c9a71126] Fixup commit error in
> 56c796
> git bisect bad 44583e022320424d145dbf01d51480e4c9a71126
> # bad: [fd112d34a2cfdc2d9efcd394e38b6d87b357c23d] Fix percentile_list
> option
> git bisect bad fd112d34a2cfdc2d9efcd394e38b6d87b357c23d
> # bad: [cfd94f79c362da249d22a59b6ede367ce3d2ba1d] configure: fixup Windows
> git bisect bad cfd94f79c362da249d22a59b6ede367ce3d2ba1d
> # bad: [17f0fd39d8b1f8edb420721c38302bd46254db03] axmap: clear
> map->first_free when we reset it
> git bisect bad 17f0fd39d8b1f8edb420721c38302bd46254db03
> # bad: [c81f9347e5849a6b97a02f215f1c474e27c79f1a] Add CONFIG_64BIT_LLP64,
> CONFIG_POSIX_FALLOCATE and CONFIG_LINUX_FALLOCATE to Makefile.
> git bisect bad c81f9347e5849a6b97a02f215f1c474e27c79f1a
> # bad: [d537c08b0eacdeb05835ee8c5f269b872239713a] Add a check avoid
> segfault
> git bisect bad d537c08b0eacdeb05835ee8c5f269b872239713a
> # bad: [67bf982340d95ca98098ea050b54b4c7adb116c0] Add configure script
> git bisect bad 67bf982340d95ca98098ea050b54b4c7adb116c0
> [ecomar@edow500 fio]$
So 67bf982340d95ca98098ea050b54b4c7adb116c0 is the first bad commit,
funky. Ah I think I see what it is, hang on.
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 10:15 ` Jens Axboe
@ 2013-05-22 10:18 ` Jens Axboe
2013-05-22 12:19 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-22 10:18 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Wed, May 22 2013, Jens Axboe wrote:
> On Wed, May 22 2013, Edoardo Comar wrote:
> > >
> > > It would help a lot if you could do a git bisect and reliably find out
> > > which commit caused the problem. The procedure is something like this,
> > > assuming you are in the fio git repository:
> > >
> > > You continue this process until it tells you which one is the offending
> > > commit. Then you mail that here :-)
> > >
> > > --
> > > Jens Axboe
> > >
> >
> > Thanks for the detailed explanataion
> > please find the log below,
> > Edo
> >
> > [ecomar@edow500 fio]$ git bisect bad
> > Bisecting: 0 revisions left to test after this (roughly 0 steps)
> > [78c1111eacdb594e0488d5adc508091fc2a3af88] Fix variable type warning
> >
> > [ecomar@edow500 fio]$ git bisect log
> > git bisect start
> > # good: [ffa93ca9d8d37ef795904773a22bf4ea77f58373] Fio 2.0.13
> > git bisect good ffa93ca9d8d37ef795904773a22bf4ea77f58373
> > # bad: [4728b3c82f07612d64b79a67adc31dd9ca3c79fc] fusion atomic: retrieve
> > all capabilities and support larger writes
> > git bisect bad 4728b3c82f07612d64b79a67adc31dd9ca3c79fc
> > # good: [73cfb8a7da365c37253662477edb54ecc19575df] Merge branch 'gfio' of
> > ssh://brick.kernel.dk/data/git/fio into gfio
> > git bisect good 73cfb8a7da365c37253662477edb54ecc19575df
> > # bad: [44583e022320424d145dbf01d51480e4c9a71126] Fixup commit error in
> > 56c796
> > git bisect bad 44583e022320424d145dbf01d51480e4c9a71126
> > # bad: [fd112d34a2cfdc2d9efcd394e38b6d87b357c23d] Fix percentile_list
> > option
> > git bisect bad fd112d34a2cfdc2d9efcd394e38b6d87b357c23d
> > # bad: [cfd94f79c362da249d22a59b6ede367ce3d2ba1d] configure: fixup Windows
> > git bisect bad cfd94f79c362da249d22a59b6ede367ce3d2ba1d
> > # bad: [17f0fd39d8b1f8edb420721c38302bd46254db03] axmap: clear
> > map->first_free when we reset it
> > git bisect bad 17f0fd39d8b1f8edb420721c38302bd46254db03
> > # bad: [c81f9347e5849a6b97a02f215f1c474e27c79f1a] Add CONFIG_64BIT_LLP64,
> > CONFIG_POSIX_FALLOCATE and CONFIG_LINUX_FALLOCATE to Makefile.
> > git bisect bad c81f9347e5849a6b97a02f215f1c474e27c79f1a
> > # bad: [d537c08b0eacdeb05835ee8c5f269b872239713a] Add a check avoid
> > segfault
> > git bisect bad d537c08b0eacdeb05835ee8c5f269b872239713a
> > # bad: [67bf982340d95ca98098ea050b54b4c7adb116c0] Add configure script
> > git bisect bad 67bf982340d95ca98098ea050b54b4c7adb116c0
> > [ecomar@edow500 fio]$
>
> So 67bf982340d95ca98098ea050b54b4c7adb116c0 is the first bad commit,
> funky. Ah I think I see what it is, hang on.
http://git.kernel.dk/?p=fio.git;a=commit;h=4b20c6814d4742e27a68f8a740a955283869fbcd
If you git pull, you'll get that. Please see if that makes it behave
like 2.0.13 for you.
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 10:18 ` Jens Axboe
@ 2013-05-22 12:19 ` Edoardo Comar
2013-05-22 12:25 ` Jens Axboe
0 siblings, 1 reply; 17+ messages in thread
From: Edoardo Comar @ 2013-05-22 12:19 UTC (permalink / raw)
To: Jens Axboe; +Cc: fio
> > So 67bf982340d95ca98098ea050b54b4c7adb116c0 is the first bad commit,
> > funky. Ah I think I see what it is, hang on.
>
> http://git.kernel.dk/?
> p=fio.git;a=commit;h=4b20c6814d4742e27a68f8a740a955283869fbcd
>
> If you git pull, you'll get that. Please see if that makes it behave
> like 2.0.13 for you.
>
Thanks,
this has fixed the read aggrb reported value to be unreasonably high
however the value is now significantly lower than 2.0.13 it's about 1/2
while the write value is very comparable.
Please find the outputs below.
MASTER:
Run status group 0 (all jobs):
READ: io=7976KB, aggrb=132KB/s, minb=13KB/s, maxb=59KB/s,
mint=60023msec, maxt=60131msec
WRITE: io=39552KB, aggrb=658KB/s, minb=12KB/s, maxb=646KB/s,
mint=60023msec, maxt=60079msec
2.0.13
Run status group 0 (all jobs):
READ: io=13716KB, aggrb=227KB/s, minb=32KB/s, maxb=162KB/s,
mint=60118msec, maxt=60368msec
WRITE: io=41100KB, aggrb=680KB/s, minb=168KB/s, maxb=513KB/s,
mint=60230msec, maxt=60368msec
=========================================================
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.1-10-g4b20
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
Jobs: 4 (f=4):
bgwriter: (groupid=0, jobs=1): err= 0: pid=31283: Wed May 22 12:57:10 2013
write: io=38816KB, bw=661588B/s, iops=161, runt= 60079msec
slat (usec): min=11, max=90943, avg=36.96, stdev=906.14
clat (msec): min=3, max=1325, avg=200.20, stdev=164.31
lat (msec): min=3, max=1325, avg=200.24, stdev=164.33
bw (KB /s): min= 0, max= 1088, per=99.83%, avg=656.91,
stdev=229.78
lat (msec) : 4=0.01%, 10=1.58%, 20=6.64%, 50=16.00%, 100=13.95%
lat (msec) : 250=27.55%, 500=29.66%, 750=3.71%, 1000=1.17%, 2000=0.05%
cpu : usr=0.22%, sys=0.58%, ctx=9875, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=108.6%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=9673/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=31284: Wed May 22 12:57:10 2013
read : io=3604.0KB, bw=61374B/s, iops=14, runt= 60131msec
clat (msec): min=3, max=700, avg=66.73, stdev=91.42
lat (msec): min=3, max=700, avg=66.73, stdev=91.42
bw (KB /s): min= 0, max= 125, per=45.45%, avg=60.00, stdev=21.47
lat (msec) : 4=0.11%, 10=2.66%, 20=47.17%, 50=19.42%, 100=8.10%
lat (msec) : 250=17.20%, 500=5.22%, 750=0.11%
cpu : usr=0.04%, sys=0.04%, ctx=971, majf=970, minf=29
IO depths : 1=107.7%, 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=901/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=31285: Wed May 22 12:57:10 2013
read : io=3548.0KB, bw=60452B/s, iops=14, runt= 60099msec
clat (usec): min=725, max=583477, avg=67740.67, stdev=94737.81
lat (usec): min=726, max=583479, avg=67741.96, stdev=94737.80
bw (KB /s): min= 0, max= 112, per=44.47%, avg=58.70, stdev=22.41
lat (usec) : 750=0.11%
lat (msec) : 10=3.38%, 20=49.38%, 50=18.49%, 100=6.43%, 250=16.57%
lat (msec) : 500=5.52%, 750=0.11%
cpu : usr=0.03%, sys=0.04%, ctx=962, majf=961, minf=29
IO depths : 1=108.3%, 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=887/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=31286: Wed May 22 12:57:10
2013
read : io=843776B, bw=14057B/s, iops=3, runt= 60023msec
slat (usec): min=10, max=227735, avg=1445.97, stdev=15443.42
clat (usec): min=5, max=579413, avg=120337.02, stdev=108882.11
lat (msec): min=7, max=579, avg=121.96, stdev=109.78
bw (KB /s): min= 4, max= 85, per=11.82%, avg=15.60, stdev=12.91
write: io=753664B, bw=12556B/s, iops=3, runt= 60023msec
slat (usec): min=17, max=132927, avg=3184.62, stdev=18633.89
clat (msec): min=17, max=566, avg=186.08, stdev=122.85
lat (msec): min=17, max=582, avg=189.64, stdev=129.83
bw (KB /s): min= 0, max= 23, per=1.82%, avg=11.97, stdev= 4.60
lat (usec) : 10=0.26%
lat (msec) : 10=1.28%, 20=9.74%, 50=11.54%, 100=18.72%, 250=39.49%
lat (msec) : 500=17.44%, 750=1.54%
cpu : usr=0.03%, sys=0.01%, ctx=466, majf=0, minf=21
IO depths : 1=108.2%, 2=0.5%, 4=1.0%, 8=2.1%, 16=0.3%, 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=206/w=184/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=7976KB, aggrb=132KB/s, minb=13KB/s, maxb=59KB/s,
mint=60023msec, maxt=60131msec
WRITE: io=39552KB, aggrb=658KB/s, minb=12KB/s, maxb=646KB/s,
mint=60023msec, maxt=60079msec
Disk stats (read/write):
dm-1: ios=2165/15038, merge=0/0, ticks=159046/3058053,
in_queue=3222168, util=99.97%, aggrios=2165/15066, aggrmerge=0/0,
aggrticks=159722/3065336, aggrin_queue=3225058, aggrutil=99.95%
dm-0: ios=2165/15066, merge=0/0, ticks=159722/3065336,
in_queue=3225058, util=99.95%, aggrios=2165/11221, aggrmerge=0/3841,
aggrticks=159422/2284175, aggrin_queue=2443590, aggrutil=99.95%
sda: ios=2165/11221, merge=0/3841, ticks=159422/2284175,
in_queue=2443590, util=99.95%
=========================================================
[ecomar@edow500 fio]$ rm -rf /mnt/vda2/tmp/*; /usr/bin/fio
../fio-check-bug/four-threads-randio-016.fio
bgwriter: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=32
queryA: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
queryB: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=mmap, iodepth=1
bgupdater: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio,
iodepth=16
fio-2.0.13
Starting 4 processes
bgwriter: Laying out IO file(s) (1 file(s) / 256MB)
queryA: Laying out IO file(s) (1 file(s) / 256MB)
queryB: Laying out IO file(s) (1 file(s) / 256MB)
bgupdater: Laying out IO file(s) (1 file(s) / 64MB)
Jobs: 4 (f=4):
bgwriter: (groupid=0, jobs=1): err= 0: pid=10553: Wed May 22 13:10:21 2013
write: io=30900KB, bw=525346 B/s, iops=127 , runt= 60230msec
slat (usec): min=10 , max=520 , avg=26.59, stdev=10.78
clat (msec): min=5 , max=1559 , avg=250.44, stdev=195.85
lat (msec): min=5 , max=1559 , avg=250.47, stdev=195.85
bw (KB/s) : min= 0, max= 890, per=76.42%, avg=519.68,
stdev=168.78
lat (msec) : 10=0.70%, 20=5.06%, 50=12.65%, 100=9.51%, 250=24.34%
lat (msec) : 500=39.76%, 750=5.63%, 1000=2.16%, 2000=0.60%
cpu : usr=0.16%, sys=0.49%, ctx=8153, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=109.2%,
>=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.1%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=7694/d=0, short=r=0/w=0/d=0
queryA: (groupid=0, jobs=1): err= 0: pid=10554: Wed May 22 13:10:21 2013
read : io=1940.0KB, bw=32964 B/s, iops=8 , runt= 60263msec
clat (msec): min=5 , max=634 , avg=124.24, stdev=125.99
lat (msec): min=5 , max=634 , avg=124.24, stdev=125.99
bw (KB/s) : min= 0, max= 87, per=14.16%, avg=32.14, stdev=17.10
lat (msec) : 10=1.24%, 20=25.77%, 50=18.35%, 100=11.34%, 250=25.98%
lat (msec) : 500=15.88%, 750=1.44%
cpu : usr=0.01%, sys=0.03%, ctx=516, majf=515, minf=26
IO depths : 1=106.2%, 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=485/w=0/d=0, short=r=0/w=0/d=0
queryB: (groupid=0, jobs=1): err= 0: pid=10555: Wed May 22 13:10:21 2013
read : io=1960.0KB, bw=33385 B/s, iops=8 , runt= 60118msec
clat (msec): min=5 , max=741 , avg=122.67, stdev=129.91
lat (msec): min=5 , max=741 , avg=122.68, stdev=129.91
bw (KB/s) : min= 0, max= 110, per=14.24%, avg=32.33, stdev=17.89
lat (msec) : 10=2.65%, 20=27.14%, 50=18.98%, 100=10.61%, 250=23.47%
lat (msec) : 500=16.53%, 750=0.61%
cpu : usr=0.01%, sys=0.03%, ctx=528, majf=527, minf=26
IO depths : 1=107.6%, 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=490/w=0/d=0, short=r=0/w=0/d=0
bgupdater: (groupid=0, jobs=1): err= 0: pid=10556: Wed May 22 13:10:21
2013
read : io=9816.0KB, bw=166505 B/s, iops=40 , runt= 60368msec
slat (usec): min=5 , max=217275 , avg=166.39, stdev=4660.87
clat (usec): min=214 , max=684589 , avg=167396.86, stdev=117164.35
lat (msec): min=2 , max=684 , avg=167.58, stdev=117.11
bw (KB/s) : min= 0, max= 344, per=72.87%, avg=165.41, stdev=64.85
write: io=10200KB, bw=173018 B/s, iops=42 , runt= 60368msec
slat (usec): min=9 , max=369054 , avg=629.51, stdev=11351.66
clat (msec): min=5 , max=1273 , avg=217.41, stdev=168.08
lat (msec): min=5 , max=1273 , avg=218.05, stdev=168.80
bw (KB/s) : min= 39, max= 515, per=25.10%, avg=170.70, stdev=71.17
lat (usec) : 250=0.02%
lat (msec) : 4=0.02%, 10=1.16%, 20=5.75%, 50=11.89%, 100=12.83%
lat (msec) : 250=36.90%, 500=28.42%, 750=2.57%, 1000=0.66%, 2000=0.08%
cpu : usr=0.18%, sys=0.26%, ctx=5309, majf=0, minf=21
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.2%, 16=110.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=2449/w=2540/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
READ: io=13716KB, aggrb=227KB/s, minb=32KB/s, maxb=162KB/s,
mint=60118msec, maxt=60368msec
WRITE: io=41100KB, aggrb=680KB/s, minb=168KB/s, maxb=513KB/s,
mint=60230msec, maxt=60368msec
Disk stats (read/write):
dm-1: ios=3772/13937, merge=0/0, ticks=567832/3199902,
in_queue=3780615, util=99.96%, aggrios=3773/13956, aggrmerge=0/0,
aggrticks=571088/3212158, aggrin_queue=3783247, aggrutil=99.94%
dm-0: ios=3773/13956, merge=0/0, ticks=571088/3212158,
in_queue=3783247, util=99.94%, aggrios=3766/11395, aggrmerge=7/2561,
aggrticks=569634/2696054, aggrin_queue=3265686, aggrutil=99.94%
sda: ios=3766/11395, merge=7/2561, ticks=569634/2696054,
in_queue=3265686, util=99.94%
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] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 12:19 ` Edoardo Comar
@ 2013-05-22 12:25 ` Jens Axboe
2013-05-22 13:15 ` Edoardo Comar
0 siblings, 1 reply; 17+ messages in thread
From: Jens Axboe @ 2013-05-22 12:25 UTC (permalink / raw)
To: Edoardo Comar; +Cc: fio
On Wed, May 22 2013, Edoardo Comar wrote:
> > > So 67bf982340d95ca98098ea050b54b4c7adb116c0 is the first bad commit,
> > > funky. Ah I think I see what it is, hang on.
> >
> > http://git.kernel.dk/?
> > p=fio.git;a=commit;h=4b20c6814d4742e27a68f8a740a955283869fbcd
> >
> > If you git pull, you'll get that. Please see if that makes it behave
> > like 2.0.13 for you.
> >
>
> Thanks,
> this has fixed the read aggrb reported value to be unreasonably high
> however the value is now significantly lower than 2.0.13 it's about 1/2
> while the write value is very comparable.
> Please find the outputs below.
This is due to the change in thinktime, fixing the unreasonable
latencies. Effectively it reduces your queue depth to what
thinktime_blocks is set to, which is 1 by default. Even if set to the
queue depth, you will still be completely draining the software queue
for every N thinktime_blocks. I'm guessing your device has write caching
enabled, hence the change is basically only apparent on reads. The
writes queue up nicely on the hw side still.
--
Jens Axboe
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: output - aggregate read bandwitdh
2013-05-22 12:25 ` Jens Axboe
@ 2013-05-22 13:15 ` Edoardo Comar
0 siblings, 0 replies; 17+ messages in thread
From: Edoardo Comar @ 2013-05-22 13:15 UTC (permalink / raw)
To: Jens Axboe; +Cc: fio
> > this has fixed the read aggrb reported value to be unreasonably high
> > however the value is now significantly lower than 2.0.13 it's about
1/2
> > while the write value is very comparable.
> > Please find the outputs below.
>
> This is due to the change in thinktime, fixing the unreasonable
> latencies. Effectively it reduces your queue depth to what
> thinktime_blocks is set to, which is 1 by default. Even if set to the
> queue depth, you will still be completely draining the software queue
> for every N thinktime_blocks. I'm guessing your device has write caching
> enabled, hence the change is basically only apparent on reads. The
> writes queue up nicely on the hw side still.
>
> --
> Jens Axboe
>
Ok - if I explicitly set the iodepth=1 in the job config file
then the results of the master fio-2.1-10-g4b20 and the old 2.0.13 are
comparable.
Thanks again, great job, Jens
cheers
Edo
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] 17+ messages in thread
end of thread, other threads:[~2013-05-22 13:15 UTC | newest]
Thread overview: 17+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-05-18 1:28 output - aggregate read bandwitdh Edoardo Comar
2013-05-18 6:53 ` Jens Axboe
2013-05-18 7:01 ` Jens Axboe
2013-05-18 10:52 ` Edoardo Comar
2013-05-18 11:02 ` Edoardo Comar
[not found] ` <OFEF259463.FACECBD6-ON80257B6F.003C54FB-80257B6F.003CA237@LocalDomain>
2013-05-18 11:18 ` Edoardo Comar
2013-05-18 12:22 ` Jens Axboe
2013-05-18 17:03 ` Edoardo Comar
2013-05-18 23:15 ` Edoardo Comar
2013-05-22 8:28 ` Edoardo Comar
2013-05-22 8:57 ` Jens Axboe
2013-05-22 10:03 ` Edoardo Comar
2013-05-22 10:15 ` Jens Axboe
2013-05-22 10:18 ` Jens Axboe
2013-05-22 12:19 ` Edoardo Comar
2013-05-22 12:25 ` Jens Axboe
2013-05-22 13:15 ` Edoardo Comar
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.