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

[Zhi Yong Wu]

On Tue, Sep 13, 2011 at 3:14 PM, Stefan Hajnoczi
<address@hidden> wrote:
> On Tue, Sep 13, 2011 at 10:52:44AM +0800, Zhi Yong Wu wrote:
>> This is real log when fio issued with bs=128K and bps=1000000(block
>> I/O throttling):
>
> I would use 1024 * 1024 instead of 1000000 as the throughput limit.
> 10^5 is not a multiple of 512 bytes and is not a nice value in KB/s
> (976.5625).
OK. next time, i will adopt this.
>
>>
>>   8,2    0        1     0.000000000 24332  A  WS 79958528 + 256 <-
>> (253,2) 71830016
>
> 256 blocks = 256 * 512 bytes = 128 KB per request.  We know the maximum
> request size from Linux is 128 KB so this makes sense.
>
>> Throughput (R/W): 0KiB/s / 482KiB/s
>
> What throughput do you get without I/O throttling?  Either I/O
> throttling is limiting too aggressively here or the physical disk is the
> bottleneck (I double that since the write throughput value is very low).
> We need to compare against the throughput when throttling is not
> enabled.
Without block I/O throttling.

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/58K /s] [0/114 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2659
  write: io=51,200KB, bw=59,936B/s, iops=117, runt=874741msec
    slat (usec): min=25, max=44,515, avg=69.77, stdev=774.19
    clat (usec): min=778, max=216K, avg=8460.67, stdev=2417.70
     lat (usec): min=845, max=216K, avg=8531.11, stdev=2778.62
    bw (KB/s) : min=   11, max=   60, per=100.89%, avg=58.52, stdev= 3.14
  cpu          : usr=0.04%, sys=0.76%, ctx=102601, majf=0, minf=49
  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 (usec): 1000=0.01%
     lat (msec): 2=0.01%, 4=0.01%, 10=99.17%, 20=0.24%, 50=0.53%
     lat (msec): 100=0.04%, 250=0.01%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=58KB/s, minb=59KB/s, maxb=59KB/s,
mint=874741msec, maxt=874741msec

Disk stats (read/write):
  dm-0: ios=37/103237, merge=0/0, ticks=1935/901887, in_queue=903811,
util=99.67%, aggrios=37/102904, aggrmerge=0/351,
aggrticks=1935/889769, aggrin_queue=891623, aggrutil=99.64%
    vda: ios=37/102904, merge=0/351, ticks=1935/889769,
in_queue=891623, util=99.64%
test: (g=0): rw=write, bs=8K-8K/8K-8K, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [100.0% done] [0K/973K /s] [0/118 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2716
  write: io=51,200KB, bw=926KB/s, iops=115, runt= 55291msec
    slat (usec): min=20, max=36,133, avg=68.68, stdev=920.02
    clat (msec): min=1, max=58, avg= 8.52, stdev= 1.99
     lat (msec): min=1, max=66, avg= 8.58, stdev= 2.48
    bw (KB/s) : min=  587, max=  972, per=100.23%, avg=928.14, stdev=54.43
  cpu          : usr=0.04%, sys=0.59%, ctx=6416, majf=0, minf=26
  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/6400, short=0/0

     lat (msec): 2=0.06%, 4=0.06%, 10=99.00%, 20=0.25%, 50=0.61%
     lat (msec): 100=0.02%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=926KB/s, minb=948KB/s, maxb=948KB/s,
mint=55291msec, maxt=55291msec

Disk stats (read/write):
  dm-0: ios=3/6507, merge=0/0, ticks=33/68470, in_queue=68508,
util=99.51%, aggrios=3/6462, aggrmerge=0/60, aggrticks=33/64291,
aggrin_queue=64322, aggrutil=99.48%
    vda: ios=3/6462, merge=0/60, ticks=33/64291, in_queue=64322, util=99.48%
test: (g=0): rw=write, bs=64K-64K/64K-64K, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [100.0% done] [0K/7,259K /s] [0/110 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2727
  write: io=51,200KB, bw=7,050KB/s, iops=110, runt=  7262msec
    slat (usec): min=30, max=46,393, avg=90.62, stdev=1639.10
    clat (msec): min=2, max=39, avg= 8.98, stdev= 1.82
     lat (msec): min=2, max=85, avg= 9.07, stdev= 3.08
    bw (KB/s) : min= 6003, max= 7252, per=100.13%, avg=7058.86, stdev=362.31
  cpu          : usr=0.00%, sys=0.61%, ctx=801, majf=0, minf=23
  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/800, short=0/0

     lat (msec): 4=0.25%, 10=92.38%, 20=7.00%, 50=0.38%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=7,050KB/s, minb=7,219KB/s, maxb=7,219KB/s,
mint=7262msec, maxt=7262msec

Disk stats (read/write):
  dm-0: ios=0/808, merge=0/0, ticks=0/8216, in_queue=8225,
util=98.31%, aggrios=0/804, aggrmerge=0/18, aggrticks=0/7363,
aggrin_queue=7363, aggrutil=98.19%
    vda: ios=0/804, merge=0/18, ticks=0/7363, in_queue=7363, util=98.19%
test: (g=0): rw=write, bs=128K-128K/128K-128K, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [100.0% done] [0K/13M /s] [0/103 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2734
  write: io=51,200KB, bw=12,933KB/s, iops=101, runt=  3959msec
    slat (usec): min=35, max=37,845, avg=132.90, stdev=1890.38
    clat (msec): min=3, max=39, avg= 9.76, stdev= 2.56
     lat (msec): min=3, max=77, avg= 9.89, stdev= 3.98
    bw (KB/s) : min=13029, max=13660, per=103.33%, avg=13362.14, stdev=227.96
  cpu          : usr=0.43%, sys=0.15%, ctx=401, majf=0, minf=23
  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/400, short=0/0

     lat (msec): 4=0.50%, 10=84.25%, 20=14.50%, 50=0.75%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=12,932KB/s, minb=13,242KB/s,
maxb=13,242KB/s, mint=3959msec, maxt=3959msec

Disk stats (read/write):
  dm-0: ios=0/415, merge=0/0, ticks=0/4834, in_queue=4838,
util=97.39%, aggrios=0/404, aggrmerge=0/18, aggrticks=0/4068,
aggrin_queue=4068, aggrutil=97.08%
    vda: ios=0/404, merge=0/18, ticks=0/4068, in_queue=4068, util=97.08%
test: (g=0): rw=write, bs=256K-256K/256K-256K, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [-.-% done] [0K/23M /s] [0/90 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2741
  write: io=51,200KB, bw=23,073KB/s, iops=90, runt=  2219msec
    slat (usec): min=45, max=246, avg=49.48, stdev=15.27
    clat (msec): min=4, max=58, avg=11.04, stdev= 3.73
     lat (msec): min=4, max=58, avg=11.09, stdev= 3.75
    bw (KB/s) : min=21841, max=23920, per=100.02%, avg=23077.75, stdev=1005.31
  cpu          : usr=0.41%, sys=0.23%, ctx=200, majf=0, minf=23
  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/200, short=0/0

     lat (msec): 10=16.50%, 20=83.00%, 100=0.50%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=23,073KB/s, minb=23,627KB/s,
maxb=23,627KB/s, mint=2219msec, maxt=2219msec

Disk stats (read/write):
  dm-0: ios=0/198, merge=0/0, ticks=0/2841, in_queue=2849,
util=95.10%, aggrios=0/206, aggrmerge=0/0, aggrticks=0/2944,
aggrin_queue=2944, aggrutil=94.61%
    vda: ios=0/206, merge=0/0, ticks=0/2944, in_queue=2944, util=94.61%


>
> Stefan
>



-- 
Regards,

Zhi Yong Wu