[Qemu-devel] Why qemu write/rw speed is so low?

[Zhi Yong Wu]

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