* 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
[parent not found: <OFEF259463.FACECBD6-ON80257B6F.003C54FB-80257B6F.003CA237@LocalDomain>]
* 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.