HI,
Today, i did some basical I/O testing, and suddenly found that qemu write and
rw speed is so low now, my qemu binary is built on commit
344eecf6995f4a0ad1d887cec922f6806f91a3f8.
Do qemu have regression?
The testing data is shown as below:
1.) write
test: (g=0): rw=write, bs=512-512/512-512, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [100.0% done] [0K/2K /s] [0/4 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2694
write: io=51,200KB, bw=58,751B/s, iops=114, runt=892381msec
slat (usec): min=19, max=376K, avg=68.30, stdev=1411.60
clat (msec): min=1, max=375, avg= 8.63, stdev= 4.71
lat (msec): min=1, max=433, avg= 8.70, stdev= 5.08
bw (KB/s) : min= 1, max= 60, per=100.80%, avg=57.46, stdev= 6.36
cpu : usr=0.04%, sys=0.65%, ctx=102616, majf=0, minf=52
IO depths : 1=100.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 r/w: total=0/102400, short=0/0
lat (msec): 2=0.01%, 4=0.02%, 10=98.82%, 20=0.20%, 50=0.76%
lat (msec): 100=0.17%, 250=0.01%, 500=0.01%
Run status group 0 (all jobs):
WRITE: io=51,200KB, aggrb=57KB/s, minb=58KB/s, maxb=58KB/s, mint=892381msec,
maxt=892381msec
Disk stats (read/write):
dm-0: ios=18/103166, merge=0/0, ticks=1143/910779, in_queue=911921,
util=99.74%, aggrios=18/102881, aggrmerge=0/294, aggrticks=1143/900778,
aggrin_queue=901855, aggrutil=99.72%
vda: ios=18/102881, merge=0/294, ticks=1143/900778, in_queue=901855,
util=99.72%
2.) read and write
test: (g=0): rw=rw, bs=512-512/512-512, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [M] [100.0% done] [60K/61K /s] [117/119 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2731
read : io=25,559KB, bw=58,883B/s, iops=115, runt=444473msec
read : io=25,559KB, bw=58,883B/s, iops=115, runt=444473msec
slat (usec): min=13, max=24,781, avg=32.04, stdev=349.25
clat (usec): min=1, max=123K, avg=121.98, stdev=807.49
lat (usec): min=75, max=123K, avg=154.66, stdev=879.19
bw (KB/s) : min= 1, max= 105, per=100.86%, avg=57.49, stdev=12.40
write: io=25,642KB, bw=59,074B/s, iops=115, runt=444473msec
slat (usec): min=18, max=60,087, avg=59.29, stdev=830.81
clat (msec): min=1, max=392, avg= 8.44, stdev= 5.60
lat (msec): min=1, max=392, avg= 8.50, stdev= 5.77
bw (KB/s) : min= 1, max= 60, per=101.40%, avg=57.80, stdev= 5.87
cpu : usr=0.10%, sys=0.99%, ctx=102007, majf=0, minf=38
IO depths : 1=100.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 r/w: total=51117/51283, short=0/0
lat (usec): 2=0.18%, 4=0.49%, 10=0.01%, 20=0.01%, 100=14.25%
lat (usec): 250=34.74%, 500=0.11%, 750=0.05%, 1000=0.03%
lat (msec): 2=0.03%, 4=0.02%, 10=49.64%, 20=0.12%, 50=0.25%
lat (msec): 100=0.05%, 250=0.01%, 500=0.01%
Run status group 0 (all jobs):
READ: io=25,558KB, aggrb=57KB/s, minb=58KB/s, maxb=58KB/s, mint=444473msec,
maxt=444473msec
WRITE: io=25,641KB, aggrb=57KB/s, minb=59KB/s, maxb=59KB/s, mint=444473msec,
maxt=444473msec
Disk stats (read/write):
dm-0: ios=51105/51689, merge=0/0, ticks=6302/454018, in_queue=460323,
util=99.44%, aggrios=51130/51542, aggrmerge=0/174, aggrticks=6264/447128,
aggrin_queue=453328, aggrutil=99.40%
vda: ios=51130/51542, merge=0/174, ticks=6264/447128, in_queue=453328,
util=99.40%
3.) read
test: (g=0): rw=read, bs=512-512/512-512, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [R] [100.0% done] [4,004K/0K /s] [8K/0 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2800
read : io=51,200KB, bw=3,925KB/s, iops=7,850, runt= 13044msec
slat (usec): min=13, max=1,191, avg=22.25, stdev=28.32
clat (usec): min=1, max=37,035, avg=102.70, stdev=177.61
lat (usec): min=78, max=37,123, avg=125.47, stdev=178.64
bw (KB/s) : min= 3368, max= 5151, per=100.02%, avg=3925.73, stdev=362.41
cpu : usr=2.61%, sys=22.80%, ctx=102591, majf=0, minf=24
IO depths : 1=100.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 r/w: total=102400/0, short=0/0
lat (usec): 2=2.20%, 4=0.80%, 10=0.01%, 20=0.01%, 50=0.01%
lat (usec): 100=73.93%, 250=22.45%, 500=0.14%, 750=0.03%, 1000=0.05%
lat (msec): 2=0.32%, 4=0.04%, 10=0.01%, 50=0.01%
Run status group 0 (all jobs):
READ: io=51,200KB, aggrb=3,925KB/s, minb=4,019KB/s, maxb=4,019KB/s,
mint=13044msec, maxt=13044msec
Disk stats (read/write):
dm-0: ios=101230/24, merge=0/0, ticks=10002/2082, in_queue=12083,
util=77.25%, aggrios=102400/4, aggrmerge=0/20, aggrticks=10103/244,
aggrin_queue=10341, aggrutil=77.03%
vda: ios=102400/4, merge=0/20, ticks=10103/244, in_queue=10341, util=77.03%
Regards,
Zhi Yong Wu
