From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([140.186.70.92]:51251) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1R3ItM-0000TG-UG for qemu-devel@nongnu.org; Mon, 12 Sep 2011 22:38:34 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1R3ItK-0001MT-RB for qemu-devel@nongnu.org; Mon, 12 Sep 2011 22:38:32 -0400 Received: from mail-wy0-f173.google.com ([74.125.82.173]:43328) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1R3ItK-0001ML-CT for qemu-devel@nongnu.org; Mon, 12 Sep 2011 22:38:30 -0400 Received: by wyf22 with SMTP id 22so82664wyf.4 for ; Mon, 12 Sep 2011 19:38:28 -0700 (PDT) MIME-Version: 1.0 In-Reply-To: <20110909103801.GA26148@stefanha-thinkpad.localdomain> References: <20110909094436.GB23929@f15.cn.ibm.com> <20110909103801.GA26148@stefanha-thinkpad.localdomain> Date: Tue, 13 Sep 2011 10:38:28 +0800 Message-ID: From: Zhi Yong Wu Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Subject: Re: [Qemu-devel] Why qemu write/rw speed is so low? List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Stefan Hajnoczi Cc: kwolf@redhat.com, Zhi Yong Wu , aliguro@us.ibm.com, qemu-devel@nongnu.org, ryanh@us.ibm.com On Fri, Sep 9, 2011 at 6:38 PM, Stefan Hajnoczi wrote: > On Fri, Sep 09, 2011 at 05:44:36PM +0800, Zhi Yong Wu wrote: >> Today, i did some basical I/O testing, and suddenly found that qemu writ= e and rw speed is so low now, my qemu binary is built on commit 344eecf6995= f4a0ad1d887cec922f6806f91a3f8. >> >> Do qemu have regression? >> >> The testing data is shown as below: >> >> 1.) write >> >> test: (g=3D0): rw=3Dwrite, bs=3D512-512/512-512, ioengine=3Dlibaio, iode= pth=3D1 > > Please post your QEMU command-line. =A0If your -drive is using > cache=3Dwritethrough then small writes are slow because they require the > physical disk to write and then synchronize its write cache. =A0Typically > cache=3Dnone is a good setting to use for local disks. > > The block size of 512 bytes is too small. =A0Ext4 uses a 4 KB block size, > so I think a 512 byte write from the guest could cause a 4 KB > read-modify-write operation on the host filesystem. > > You can check this by running btrace(8) on the host during the > benchmark. =A0The blktrace output and the summary statistics will show > what I/O pattern the host is issuing. 8,2 0 1 0.000000000 337 A WS 425081504 + 8 <- (253,1) 42611360 8,0 0 2 0.000000896 337 A WS 426107552 + 8 <- (8,2) 425081504 8,2 0 3 0.000001772 337 Q WS 426107552 + 8 [jbd2/dm-1-8= ] 8,2 0 4 0.000006617 337 G WS 426107552 + 8 [jbd2/dm-1-8= ] 8,2 0 5 0.000007862 337 P N [jbd2/dm-1-8] 8,2 0 6 0.000010481 337 I WS 426107552 + 8 [jbd2/dm-1-8= ] ..... CPU0 (8,2): Reads Queued: 11, 416KiB Writes Queued: 20, = 72KiB Read Dispatches: 12, 440KiB Write Dispatches: 8, = 72KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 14, 448KiB Writes Completed: 12, = 72KiB Read Merges: 0, 0KiB Write Merges: 10, = 40KiB Read depth: 2 Write depth: 2 IO unplugs: 11 Timer unplugs: 0 CPU1 (8,2): Reads Queued: 8, 32KiB Writes Queued: 0, = 0KiB Read Dispatches: 2, 8KiB Write Dispatches: 0, = 0KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 0, 0KiB Writes Completed: 0, = 0KiB Read Merges: 5, 20KiB Write Merges: 0, = 0KiB Read depth: 2 Write depth: 2 IO unplugs: 0 Timer unplugs: 0 Total (8,2): Reads Queued: 19, 448KiB Writes Queued: 20, = 72KiB Read Dispatches: 14, 448KiB Write Dispatches: 8, = 72KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 14, 448KiB Writes Completed: 12, = 72KiB Read Merges: 5, 20KiB Write Merges: 10, = 40KiB IO unplugs: 11 Timer unplugs: 0 Throughput (R/W): 69KiB/s / 11KiB/s Events (8,2): 411 entries Skips: 50 forward (5,937 - 93.5%) >>From its log, host will write 8 blocks each time. what is each block's size= ? > > I suggest changing your fio block size to 8 KB if you want to try a > small block size. =A0If you want a large block size, try 64 KB or 128 KB. When -drive if=3Dvirtio,cache=3Dnone,file=3Dxxx,bps=3D1000000 is set (note that bps is in bytes). test: (g=3D0): rw=3Dwrite, bs=3D512-512/512-512, ioengine=3Dlibaio, iodepth= =3D1 Starting 1 process ^Cbs: 1 (f=3D1): [W] [1.9% done] [0K/61K /s] [0/120 iops] [eta 01h:00m:57s] fio: terminating on signal 2 test: (groupid=3D0, jobs=3D1): err=3D 0: pid=3D27515 write: io=3D3,960KB, bw=3D56,775B/s, iops=3D110, runt=3D 71422msec slat (usec): min=3D19, max=3D31,032, avg=3D65.03, stdev=3D844.57 clat (msec): min=3D1, max=3D353, avg=3D 8.93, stdev=3D11.91 lat (msec): min=3D1, max=3D353, avg=3D 8.99, stdev=3D12.00 bw (KB/s) : min=3D 2, max=3D 60, per=3D102.06%, avg=3D56.14, stdev= =3D10.89 cpu : usr=3D0.04%, sys=3D0.61%, ctx=3D7936, majf=3D0, minf=3D26 IO depths : 1=3D100.0%, 2=3D0.0%, 4=3D0.0%, 8=3D0.0%, 16=3D0.0%, 32=3D= 0.0%, >=3D64=3D0.0% submit : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% complete : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% issued r/w: total=3D0/7920, short=3D0/0 lat (msec): 2=3D0.03%, 4=3D0.09%, 10=3D98.48%, 20=3D0.54%, 50=3D0.67% lat (msec): 100=3D0.03%, 250=3D0.05%, 500=3D0.11% Run status group 0 (all jobs): WRITE: io=3D3,960KB, aggrb=3D55KB/s, minb=3D56KB/s, maxb=3D56KB/s, mint=3D71422msec, maxt=3D71422msec Disk stats (read/write): dm-0: ios=3D6/8007, merge=3D0/0, ticks=3D179/78114, in_queue=3D78272, util=3D99.58%, aggrios=3D4/7975, aggrmerge=3D0/44, aggrticks=3D179/75153, aggrin_queue=3D75304, aggrutil=3D99.53% vda: ios=3D4/7975, merge=3D0/44, ticks=3D179/75153, in_queue=3D75304, u= til=3D99.53% test: (g=3D0): rw=3Dwrite, bs=3D8K-8K/8K-8K, ioengine=3Dlibaio, iodepth=3D1 Starting 1 process Jobs: 1 (f=3D1): [W] [100.0% done] [0K/752K /s] [0/91 iops] [eta 00m:00s] test: (groupid=3D0, jobs=3D1): err=3D 0: pid=3D27526 write: io=3D51,200KB, bw=3D668KB/s, iops=3D83, runt=3D 76622msec slat (usec): min=3D20, max=3D570K, avg=3D386.16, stdev=3D11400.53 clat (msec): min=3D1, max=3D1,699, avg=3D11.57, stdev=3D29.85 lat (msec): min=3D1, max=3D1,699, avg=3D11.96, stdev=3D33.24 bw (KB/s) : min=3D 20, max=3D 968, per=3D104.93%, avg=3D700.95, stde= v=3D245.18 cpu : usr=3D0.08%, sys=3D0.41%, ctx=3D6418, majf=3D0, minf=3D25 IO depths : 1=3D100.0%, 2=3D0.0%, 4=3D0.0%, 8=3D0.0%, 16=3D0.0%, 32=3D= 0.0%, >=3D64=3D0.0% submit : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% complete : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% issued r/w: total=3D0/6400, short=3D0/0 lat (msec): 2=3D0.05%, 4=3D0.09%, 10=3D94.08%, 20=3D0.78%, 50=3D3.39% lat (msec): 100=3D0.33%, 250=3D1.12%, 500=3D0.11%, 750=3D0.03%, 2000= =3D0.02% Run status group 0 (all jobs): WRITE: io=3D51,200KB, aggrb=3D668KB/s, minb=3D684KB/s, maxb=3D684KB/s, mint=3D76622msec, maxt=3D76622msec Disk stats (read/write): dm-0: ios=3D913/6731, merge=3D0/0, ticks=3D161809/696060, in_queue=3D8580= 86, util=3D100.00%, aggrios=3D1070/6679, aggrmerge=3D316/410, aggrticks=3D163975/1587245, aggrin_queue=3D1751267, aggrutil=3D100.00% vda: ios=3D1070/6679, merge=3D316/410, ticks=3D163975/1587245, in_queue=3D1751267, util=3D100.00% test: (g=3D0): rw=3Dwrite, bs=3D64K-64K/64K-64K, ioengine=3Dlibaio, iodepth= =3D1 Starting 1 process Jobs: 1 (f=3D1): [W] [100.0% done] [0K/458K /s] [0/6 iops] [eta 00m:00s] test: (groupid=3D0, jobs=3D1): err=3D 0: pid=3D27614 write: io=3D51,200KB, bw=3D428KB/s, iops=3D6, runt=3D119618msec slat (usec): min=3D28, max=3D5,507K, avg=3D7618.90, stdev=3D194782.69 clat (msec): min=3D14, max=3D9,418, avg=3D140.49, stdev=3D328.96 lat (msec): min=3D14, max=3D9,418, avg=3D148.11, stdev=3D382.21 bw (KB/s) : min=3D 11, max=3D 664, per=3D114.06%, avg=3D488.19, stde= v=3D53.97 cpu : usr=3D0.03%, sys=3D0.04%, ctx=3D825, majf=3D0, minf=3D27 IO depths : 1=3D100.0%, 2=3D0.0%, 4=3D0.0%, 8=3D0.0%, 16=3D0.0%, 32=3D= 0.0%, >=3D64=3D0.0% submit : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% complete : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% issued r/w: total=3D0/800, short=3D0/0 lat (msec): 20=3D0.38%, 50=3D2.50%, 250=3D97.00%, >=3D2000=3D0.12% Run status group 0 (all jobs): WRITE: io=3D51,200KB, aggrb=3D428KB/s, minb=3D438KB/s, maxb=3D438KB/s, mint=3D119618msec, maxt=3D119618msec Disk stats (read/write): dm-0: ios=3D0/938, merge=3D0/0, ticks=3D0/517622, in_queue=3D517712, util=3D100.00%, aggrios=3D0/883, aggrmerge=3D0/55, aggrticks=3D0/351498, aggrin_queue=3D351497, aggrutil=3D100.00% vda: ios=3D0/883, merge=3D0/55, ticks=3D0/351498, in_queue=3D351497, ut= il=3D100.00% test: (g=3D0): rw=3Dwrite, bs=3D128K-128K/128K-128K, ioengine=3Dlibaio, iod= epth=3D1 Starting 1 process Jobs: 1 (f=3D1): [W] [100.0% done] [0K/374K /s] [0/2 iops] [eta 00m:00s] test: (groupid=3D0, jobs=3D1): err=3D 0: pid=3D27623 write: io=3D51,200KB, bw=3D422KB/s, iops=3D3, runt=3D121420msec slat (usec): min=3D29, max=3D5,484K, avg=3D17456.88, stdev=3D274747.99 clat (msec): min=3D174, max=3D9,559, avg=3D283.02, stdev=3D465.37 lat (msec): min=3D176, max=3D9,559, avg=3D300.47, stdev=3D538.58 bw (KB/s) : min=3D 22, max=3D 552, per=3D114.21%, avg=3D480.81, stde= v=3D49.10 cpu : usr=3D0.00%, sys=3D0.03%, ctx=3D425, majf=3D0, minf=3D27 IO depths : 1=3D100.0%, 2=3D0.0%, 4=3D0.0%, 8=3D0.0%, 16=3D0.0%, 32=3D= 0.0%, >=3D64=3D0.0% submit : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% complete : 0=3D0.0%, 4=3D100.0%, 8=3D0.0%, 16=3D0.0%, 32=3D0.0%, 64= =3D0.0%, >=3D64=3D0.0% issued r/w: total=3D0/400, short=3D0/0 lat (msec): 250=3D9.50%, 500=3D90.25%, >=3D2000=3D0.25% Run status group 0 (all jobs): WRITE: io=3D51,200KB, aggrb=3D421KB/s, minb=3D431KB/s, maxb=3D431KB/s, mint=3D121420msec, maxt=3D121420msec Disk stats (read/write): dm-0: ios=3D0/541, merge=3D0/0, ticks=3D0/573761, in_queue=3D574004, util=3D100.00%, aggrios=3D0/484, aggrmerge=3D0/57, aggrticks=3D0/396662, aggrin_queue=3D396662, aggrutil=3D100.00% vda: ios=3D0/484, merge=3D0/57, ticks=3D0/396662, in_queue=3D396662, ut= il=3D100.00% > > Stefan > > --=20 Regards, Zhi Yong Wu