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

[Zhi Yong Wu]

Log for bps=((10 * 1024 * 1024)).

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=2657
  write: io=51,200KB, bw=58,527B/s, iops=114, runt=895793msec
    slat (usec): min=26, max=376K, avg=81.69, stdev=2104.09
    clat (usec): min=859, max=757K, avg=8648.07, stdev=8278.64
     lat (usec): min=921, max=1,133K, avg=8730.49, stdev=9239.57
    bw (KB/s) : min=    0, max=   60, per=101.03%, avg=57.59, stdev= 7.41
  cpu          : usr=0.05%, sys=0.75%, ctx=102611, majf=0, minf=51
  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.02%, 10=98.99%, 20=0.24%, 50=0.66%
     lat (msec): 100=0.03%, 250=0.01%, 500=0.05%, 1000=0.01%

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

Disk stats (read/write):
  dm-0: ios=28/103311, merge=0/0, ticks=1318/950537, in_queue=951852,
util=99.63%, aggrios=28/102932, aggrmerge=0/379,
aggrticks=1316/929743, aggrin_queue=930987, aggrutil=99.60%
    vda: ios=28/102932, merge=0/379, ticks=1316/929743,
in_queue=930987, util=99.60%
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/892K /s] [0/108 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2782
  write: io=51,200KB, bw=926KB/s, iops=115, runt= 55269msec
    slat (usec): min=20, max=32,160, avg=66.43, stdev=935.62
    clat (msec): min=1, max=157, avg= 8.53, stdev= 2.55
     lat (msec): min=1, max=158, avg= 8.60, stdev= 2.93
    bw (KB/s) : min=  539, max=  968, per=100.12%, avg=927.09, stdev=63.89
  cpu          : usr=0.10%, sys=0.47%, ctx=6415, 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.05%, 10=99.19%, 20=0.06%, 50=0.62%
     lat (msec): 250=0.02%

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

Disk stats (read/write):
  dm-0: ios=3/6546, merge=0/0, ticks=117/65262, in_queue=65387,
util=99.58%, aggrios=3/6472, aggrmerge=0/79, aggrticks=117/62063,
aggrin_queue=62178, aggrutil=99.54%
    vda: ios=3/6472, merge=0/79, ticks=117/62063, in_queue=62178, util=99.54%
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,332K /s] [0/111 iops] [eta 00m:00s]
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,332K /s] [0/111 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2793
  write: io=51,200KB, bw=7,074KB/s, iops=110, runt=  7238msec
    slat (usec): min=23, max=37,715, avg=82.08, stdev=1332.25
    clat (msec): min=2, max=34, avg= 8.96, stdev= 1.54
     lat (msec): min=2, max=58, avg= 9.04, stdev= 2.31
    bw (KB/s) : min= 6361, max= 7281, per=100.13%, avg=7082.07, stdev=274.31
  cpu          : usr=0.08%, sys=0.53%, 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.12%, 20=7.25%, 50=0.38%

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

Disk stats (read/write):
  dm-0: ios=0/811, merge=0/0, ticks=0/8003, in_queue=8003,
util=98.35%, aggrios=0/804, aggrmerge=0/17, aggrticks=0/7319,
aggrin_queue=7319, aggrutil=98.19%
    vda: ios=0/804, merge=0/17, ticks=0/7319, in_queue=7319, 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] [83.3% done] [0K/10M /s] [0/81 iops] [eta 00m:01s]
test: (groupid=0, jobs=1): err= 0: pid=2800
  write: io=51,200KB, bw=10,113KB/s, iops=79, runt=  5063msec
    slat (usec): min=36, max=35,279, avg=130.55, stdev=1761.93
    clat (msec): min=3, max=134, avg=12.52, stdev=16.93
     lat (msec): min=3, max=134, avg=12.65, stdev=17.14
    bw (KB/s) : min= 7888, max=13128, per=100.41%, avg=10153.00, stdev=1607.48
  cpu          : usr=0.00%, sys=0.51%, 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=81.25%, 20=14.75%, 50=0.75%, 250=2.75%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=10,112KB/s, minb=10,355KB/s,
maxb=10,355KB/s, mint=5063msec, maxt=5063msec

Disk stats (read/write):
  dm-0: ios=0/403, merge=0/0, ticks=0/6216, in_queue=6225,
util=97.83%, aggrios=0/404, aggrmerge=0/17, aggrticks=0/5228,
aggrin_queue=5228, aggrutil=97.62%
    vda: ios=0/404, merge=0/17, ticks=0/5228, in_queue=5228, util=97.62%
test: (g=0): rw=write, bs=256K-256K/256K-256K, ioengine=libaio, iodepth=1
Starting 1 process
Jobs: 1 (f=1): [W] [100.0% done] [0K/9,165K /s] [0/34 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=2807
  write: io=51,200KB, bw=8,883KB/s, iops=34, runt=  5764msec
    slat (usec): min=37, max=36,481, avg=240.22, stdev=2575.78
    clat (msec): min=4, max=164, avg=28.57, stdev=39.97
     lat (msec): min=4, max=164, avg=28.81, stdev=40.03
    bw (KB/s) : min= 7613, max= 9678, per=98.98%, avg=8791.27, stdev=569.82
  cpu          : usr=0.10%, sys=0.17%, ctx=201, 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=14.50%, 20=68.00%, 50=1.00%, 250=16.50%

Run status group 0 (all jobs):
  WRITE: io=51,200KB, aggrb=8,882KB/s, minb=9,095KB/s, maxb=9,095KB/s,
mint=5764msec, maxt=5764msec

Disk stats (read/write):
  dm-0: ios=0/216, merge=0/0, ticks=0/6446, in_queue=6484,
util=98.10%, aggrios=0/204, aggrmerge=0/16, aggrticks=0/5861,
aggrin_queue=5861, aggrutil=97.92%
    vda: ios=0/204, merge=0/16, ticks=0/5861, in_queue=5861, util=97.92%


On Tue, Sep 13, 2011 at 6:14 PM, Stefan Hajnoczi <address@hidden> wrote:
> On Tue, Sep 13, 2011 at 10:25 AM, Zhi Yong Wu <address@hidden> wrote:
>> 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=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
>
> This shows that the physical disk is capable of far exceeding 1 MB/s
> when I/O is not limited.  So the earlier result where the guest only
> gets 482 KiB/s under 1000000 bps limit shows that I/O limits are being
> too aggressive.  For some reason the algorithm is causing the guest to
> get lower throughput than expected.
>
> It would be interesting to try with bps=$((10 * 1024 * 1024)).  I
> wonder if the algorithm has a constant overhead of a couple hundred
> KB/s or if it changes with the much larger bps value.
>
> Stefan
>



-- 
Regards,

Zhi Yong Wu