635527 – KVM:qemu-img re-base poor performance(on local storage) when snapshot to a new disk

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 635527 - KVM:qemu-img re-base poor performance(on local storage) when snapshot to a new disk

Summary: KVM:qemu-img re-base poor performance(on local storage) when snapshot to a ne...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	qemu-kvm
Sub Component:
Version:	6.0
Hardware:	All
OS:	Linux
Priority:	high
Severity:	medium
Target Milestone:	beta
Target Release:	6.1
Assignee:	Kevin Wolf
QA Contact:	Virtualization Bugs
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	676565 (view as bug list)
Depends On:
Blocks:	Rhel6KvmTier1
TreeView+	depends on / blocked

Reported:	2010-09-20 05:00 UTC by juzhang
Modified:	2013-01-09 23:09 UTC (History)
CC List:	11 users (show)
Fixed In Version:	qemu-kvm-0.12.1.2-2.136.el6
Doc Type:	Bug Fix
Doc Text:	Previously, qemu-kvm did not include metadata caching, which resulted in poor performance for the the qemu-img rebase process. This is now fixed and the QCOW2 code now includes metadata caching, which results in improved performance for the qemu-img rebase process.
Clone Of:
Environment:
Last Closed:	2011-05-19 11:27:05 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHSA-2011:0534	0	normal	SHIPPED_LIVE	Important: qemu-kvm security, bug fix, and enhancement update	2011-05-19 11:20:36 UTC

Description juzhang 2010-09-20 05:00:09 UTC

Description of problem:
base -> snA -> snB -> snC, create a new disk  with the same size of base, then rebase snC to base_new.however,It's spent 172 mins on rebasing snC to a new disk.

Version-Release number of selected component (if applicable):
#rpm -q qemu-kvm
qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64
#uname -r
2.6.32-71.el6.x86_64

How reproducible:

Steps to Reproduce:
1.Create base image 
#qemu-img create -opreallocation=metadata -ocluster_size=2M -f "qcow2" rhel6.0rc3_64.qcow2 15G

2.Install guest on rhel6.0rc3_64.qcow2

3.After installed guest on base image.check img
#qemu-img info rhel6.0rc3_64.qcow2
image: rhel6.0rc3_64.qcow2
file format: qcow2
virtual size: 15G (16106127360 bytes)
disk size: 12G
cluster_size: 2097152

4.issue the following commands.(base -> snA -> snB -> snC)
#qemu-img create -f qcow2 -F qcow2 -b rhel6.0rc3_64.qcow2 A.qcow2
Formatting 'A.qcow2', fmt=qcow2 size=16106127360 backing_file='rhel6.0rc3_64.qcow2' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b A.qcow2 B.qcow2
Formatting 'B.qcow2', fmt=qcow2 size=16106127360 backing_file='A.qcow2' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b B.qcow2 C.qcow2
Formatting 'C.qcow2', fmt=qcow2 size=16106127360 backing_file='B.qcow2' backing_fmt='qcow2' encryption=off cluster_size=0 

5. boot snapshot C.qcow,write about 1G file in guest,then shutdown guest.
#/usr/libexec/qemu-kvm -M rhel6.0.0 -enable-kvm -m 2G -smp 2 -uuid `uuidgen` -monitor stdio -rtc base=localtime -drive file=/root/zhangjunyitest/C.qcow2,format=qcow2,werror=stop,rerror=stop,id=drive-ide,cache=none,boot=on -device virtio-blk-pci,drive=drive-ide,id=test1 -boot c -netdev tap,id=hostnet0 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=22:11:22:45:66:97 -qmp tcp:0:4444,server,nowait -drive file=/root/boot.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw -device ide-drive,drive=drive-ide0-1-0  -device ide-drive,drive=drive-ide0-1-0 -vnc :11

In guest:
write about 1G file
dd if=/dev/zero of=/root/zhang bs=1M count=1024;cksum zhang > zhang.txt

6.Create a new disk with the same size of base image.
#qemu-img create -f qcow2 testrebasetime.qcow2 15G
Formatting 'testrebasetime.qcow2', fmt=qcow2 size=16106127360 encryption=off cluster_size=0

7.Rebase snapshot C to base_new.
#time qemu-img rebase -b testrebasetime.qcow2 -f qcow2 -F qcow2 C.qcow2
real 172m48.997s
user 0m36.703s
sys 1m19.921s

Actual results:
I tried rebase snapshot to new image three times,average costs is around 170 mins.

Expected results:
Rebase Costs on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64 should not increased.

Additional info:
1. I also tried rebase operation on qemu-kvm-0.12.1.2-2.53.el6.x86_64 rebase snapshotc to new image.Just costs 9 mins.
#time qemu-img rebase -b testbasetimeqemu53.qcow2 -f qcow2 -F qcow2 Cqemu53.qcow2

real	9m5.052s
user	0m28.208s
sys	0m54.080s

2.Do rebase on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64 compare to  qemu-kvm-0.12.1.2-2.53.el6.x86_64. there are a lot of fdatasync() calls.I am not sure this is key reasons.

(1) A snip of strace log in the progress of rebase snapshot C to base_new on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64.

pwrite(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512, 2147592704) = 512
fdatasync(3)                            = 0
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
pwrite(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65024, 3587637760) = 65024
fdatasync(3)                            = 0
pwrite(3, "\200\0\0\0\325\237\0\0\200\0\0\0\325\240\0\0\200\0\0\0\325\241\0\0\200\0\0\0\325\242\0\0"..., 512, 6496256) = 512
fdatasync(3)                            = 0
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
pwrite(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512, 2147592704) = 512
fdatasync(3)                            = 0
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
pwrite(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65024, 3587703296) = 65024
fdatasync(3)                            = 0
pwrite(3, "\200\0\0\0\325\237\0\0\200\0\0\0\325\240\0\0\200\0\0\0\325\241\0\0\200\0\0\0\325\242\0\0"..., 512, 6496256) = 512
fdatasync(3)                            = 0
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
pwrite(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512, 2147592704) = 512
fdatasync(3)                            = 0
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
pwrite(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65024, 3587768832) = 65024
fdatasync(3^C <unfinished ...>

(2) A snip of strace log in the progress of rebase snapshot C to base_new on qemu-kvm-0.12.1.2-2.53.el6.x86_64.didn't find fdatasync() calls

futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 12489135104, SEEK_SET)         = 12489135104
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 60416) = 60416
lseek(3, 12458069504, SEEK_SET)         = 12458069504
write(3, "\200\0\0\2\350P\0\0\200\0\0\2\350Q\0\0\200\0\0\2\350R\0\0\200\0\0\2\350S\0\0"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 12489202688, SEEK_SET)         = 12489202688
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 58368) = 58368
lseek(3, 12458069504, SEEK_SET)         = 12458069504
write(3, "\200\0\0\2\350P\0\0\200\0\0\2\350Q\0\0\200\0\0\2\350R\0\0\200\0\0\2\350S\0\0"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 12489273344, SEEK_SET)         = 12489273344
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 53248) = 53248
lseek(3, 12458069504, SEEK_SET)         = 12458069504
write(3, "\200\0\0\2\350P\0\0\200\0\0\2\350Q\0\0\200\0\0\2\350R\0\0\200\0\0\2\350S\0\0"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
lseek(3, 12489449472, SEEK_SET)         = 12489449472
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
lseek(3, 12458069504, SEEK_SET)         = 12458069504
write(3, "\200\0\0\2\350P\0\0\200\0\0\2\350Q\0\0\200\0\0\2\350R\0\0\200\0\0\2\350S\0\0"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 12489459712, SEEK_SET)         = 12489459712
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 63488) = 63488
lseek(3, 12458069504, SEEK_SET)         = 12458069504
write(3, "\200\0\0\2\350P\0\0\200\0\0\2\350Q\0\0\200\0\0\2\350R\0\0\200\0\0\2\350S\0\0"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
lseek(3, 10737537024, SEEK_SET)         = 10737537024
write(3, "\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1\0\1"..., 512) = 512
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x63ac24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63ac20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\34.\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
lseek(3, 12489523712, SEEK_SET)         = 12489523712
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65024) = 65024
lseek(3, 12458069504, SEEK_SET)         = 12458069504

3. I also tried rebase snapshotC to snapshotA on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64.didn't find didn't find fdatasync() calls.


#time qemu-img rebase -b A.qcow2 -f qcow2 -F qcow2 C.qcow2

real	3m1.431s
user	0m22.627s
sys	0m15.424s

A snip of strace
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
select(5, [4], [], NULL, NULL)          = 1 (in [4])
read(4, "\f\0\0\0\0\0\0\0\0\0\0\0\233\21\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
futex(0x63eec4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x63eec0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1

4.In the progess of rebase on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64
#top 
top - 04:29:39 up 3 days, 20:18,  5 users,  load average: 1.37, 0.77, 0.32
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.3%sy,  0.0%ni, 85.6%id, 13.9%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:   3662032k total,  2378392k used,  1283640k free,    41428k buffers
Swap:  4296696k total,     2384k used,  4294312k free,  2020984k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                         
 5723 root      20   0  249m  47m  608 D  1.0  1.3   0:02.81 qemu-img 

#free
             total       used       free     shared    buffers     cached
Mem:       3662032    2507476    1154556          0      44272    2145884
-/+ buffers/cache:     317320    3344712
Swap:      4296696       2384    4294312

5. host cpu
#cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 23
model name	: Intel(R) Core(TM)2 Quad CPU    Q9550  @ 2.83GHz
stepping	: 10
cpu MHz		: 2826.086
cache size	: 6144 KB
physical id	: 0
siblings	: 4
core id		: 0
cpu cores	: 4
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 13
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good aperfmperf pni dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm sse4_1 xsave lahf_lm tpr_shadow vnmi flexpriority
bogomips	: 5652.17
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:

#cat /proc/cpuinfo | grep cores
cpu cores	: 4

Comment 6 Kevin Wolf 2010-10-22 11:08:18 UTC

(In reply to comment #0)
> 2.Do rebase on qemu-kvm-0.12.1.2-2.113.el6_0.1.x86_64 compare to 
> qemu-kvm-0.12.1.2-2.53.el6.x86_64. there are a lot of fdatasync() calls.I am
> not sure this is key reasons.

Yes, it is the reason. The fdatasync is required to guarantee image integrity in case of a crash/power failure, so we can't just remove it again. There is a prototype for an optimization approach to get much of the performance back, but it's an intrusive change and not ready yet.

Comment 14 Shirley Zhou 2011-02-16 07:52:03 UTC

Reproduce this bug with qemu-kvm-0.12.1.2-2.135.el6.x86_64 on local storage and iscsi storage as following:

For local storage:
1. RHEL6.img is previous installed rhel6 guest image
# qemu-img info RHEL6.img 
image: RHEL6.img
file format: qcow2
virtual size: 20G (20971520000 bytes)
disk size: 6.6G
cluster_size: 65536

2. create snapshot chain
RHEL6.img -> snA -> snB -> snC
# qemu-img create -f qcow2 -F qcow2 -b RHEL6.img snA
Formatting 'snA', fmt=qcow2 size=20971520000 backing_file='RHEL6.img' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b snA snB
Formatting 'snB', fmt=qcow2 size=20971520000 backing_file='snA' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b snB snC
Formatting 'snC', fmt=qcow2 size=20971520000 backing_file='snB' backing_fmt='qcow2' encryption=off cluster_size=0 

3. create new base image with same size as base
# qemu-img create -f qcow2 newbase.img 20G
Formatting 'newbase.img', fmt=qcow2 size=21474836480 encryption=off cluster_size=0 

4. record time of rebase snapshot c to new base.
# time strace -c qemu-img rebase -b  newbase.img  -f qcow2 -F qcow2 snC
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 61.18    8.712965         104     83632           select
 35.52    5.058238         149     33997           fdatasync
  2.36    0.335972           1    227702      1639 futex
  0.91    0.130272           1    100271           pwrite
  0.01    0.001760           0     83637           read
  0.01    0.001385          12       117           pread
  0.01    0.000869          46        19           munmap
  0.00    0.000011           1        22           close
  0.00    0.000000           0        22           open
  0.00    0.000000           0         8           stat
  0.00    0.000000           0         6           fstat
  0.00    0.000000           0         8           lseek
  0.00    0.000000           0        37           mmap
  0.00    0.000000           0        10           mprotect
  0.00    0.000000           0        14           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0         8         8 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           signalfd
------ ----------- ----------- --------- --------- ----------------
100.00   14.241472                529527      1648 total

real	36m21.471s
user	0m30.643s
sys	0m35.155s

Last about 36 mins.

For iscsi storage:

1.previous installed rhel6 guest
# qemu-img info /dev/vgtest/lvtest 
image: /dev/vgtest/lvtest
file format: qcow2
virtual size: 50G (53687091200 bytes)
disk size: 0
cluster_size: 65536

2. create snapshot chain.
RHEL6.img -> snA -> snB -> snC
# qemu-img create -f qcow2 -F qcow2 -b /dev/vgtest/lvtest /dev/vgtest/snA
Formatting '/dev/vgtest/snA', fmt=qcow2 size=53687091200 backing_file='/dev/vgtest/lvtest' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b /dev/vgtest/snA /dev/vgtest/snB
Formatting '/dev/vgtest/snB', fmt=qcow2 size=53687091200 backing_file='/dev/vgtest/snA' backing_fmt='qcow2' encryption=off cluster_size=0 
# qemu-img create -f qcow2 -F qcow2 -b /dev/vgtest/snB /dev/vgtest/snC
Formatting '/dev/vgtest/snC', fmt=qcow2 size=53687091200 backing_file='/dev/vgtest/snB' backing_fmt='qcow2' encryption=off cluster_size=0 

3. create new base image with same size as base image

# qemu-img create -f qcow2 /dev/vgtest/newbase 50G
Formatting '/dev/vgtest/newbase', fmt=qcow2 size=53687091200 encryption=off cluster_size=0 

4. record time to rebase snapshot to base new.

# time strace -c qemu-img rebase -b  /dev/vgtest/newbase  -f qcow2 -F qcow2 /dev/vgtest/snC
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 60.89    5.644797         160     35378           select
 24.05    2.229636         162     13728           fdatasync
 12.65    1.172540       53297        22           close
  2.10    0.194862           2     91233       178 futex
  0.24    0.022066           1     39913           pwrite
  0.03    0.003153          27       116           pread
  0.02    0.001873           0     35383           read
  0.01    0.000969          51        19           munmap
  0.00    0.000032           1        37           mmap
  0.00    0.000000           0        22           open
  0.00    0.000000           0         8           stat
  0.00    0.000000           0         6           fstat
  0.00    0.000000           0         8           lseek
  0.00    0.000000           0        10           mprotect
  0.00    0.000000           0        14           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0         8         8 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           signalfd
------ ----------- ----------- --------- --------- ----------------
100.00    9.269928                215922       187 total

real	11m51.648s
user	1m33.070s
sys	0m18.393s

Last about 11 mins.

Verify this bug with qemu-kvm-0.12.1.2-2.145.el6.x86_64 as reproduce steps, time spend as following:

Local storage:

# time strace -c qemu-img rebase -b  newbase.img  -f qcow2 -F qcow2 snC
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.49   17.133394      237964        72           fdatasync
 32.66    8.545440         111     76793           select
  1.41    0.367682           2    225227       516 futex
  0.42    0.109451           3     32383           pwrite
  0.02    0.004100          35       117           pread
  0.01    0.001906           0     76798           read
  0.00    0.000342          31        11           munmap
  0.00    0.000017           1        22           open
  0.00    0.000009           0        73           brk
  0.00    0.000000           0        22           close
  0.00    0.000000           0         8           stat
  0.00    0.000000           0         6           fstat
  0.00    0.000000           0         8           lseek
  0.00    0.000000           0        29           mmap
  0.00    0.000000           0        10           mprotect
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0         8         8 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           signalfd
------ ----------- ----------- --------- --------- ----------------
100.00   26.162341                411604       525 total

real	2m45.269s
user	0m29.700s
sys	0m43.185s

Last about 3 mins.

For iscsi storage:
# time strace -c qemu-img rebase -b  /dev/vgtest/newbase  -f qcow2 -F qcow2 /dev/vgtest/snC
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 76.30    6.349827         160     39803           select
 11.34    0.943855       18151        52           fdatasync
 10.39    0.864869       39312        22           close
  1.58    0.131680           1     91823       279 futex
  0.33    0.027392           2     12534           pwrite
  0.03    0.002116          18       116           pread
  0.02    0.001531           0     39808           read
  0.01    0.001058          96        11           munmap
  0.00    0.000325           5        72           brk
  0.00    0.000000           0        22           open
  0.00    0.000000           0         8           stat
  0.00    0.000000           0         6           fstat
  0.00    0.000000           0         8           lseek
  0.00    0.000000           0        29           mmap
  0.00    0.000000           0        10           mprotect
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0         8         8 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           signalfd
------ ----------- ----------- --------- --------- ----------------
100.00    8.322653                184349       288 total

real	3m19.102s
user	1m32.898s
sys	0m16.125s

Last about 3 mins.

So compare above test result, we have performance improvement as
36 mins --> 3 mins (local storage)
11 mins --> 3 mins ( iscsi storage)

So this bug has been resolved.

Comment 15 Kevin Wolf 2011-02-17 08:47:02 UTC

*** Bug 676565 has been marked as a duplicate of this bug. ***

Comment 17 Miya Chen 2011-03-09 05:13:17 UTC

move to verified based on comment#14

Comment 18 Eduardo Habkost 2011-05-05 19:28:00 UTC

    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
Cause: no metadata caching in the qemu-kvm qcow2 code.
Consequence: poor performance of 'qemu-img rebase'
Fix: a metadata cache was introduced into the qcow2 code.
Result: improved performance of 'qemu-img rebase'.

Comment 19 Misha H. Ali 2011-05-12 23:58:18 UTC

    Technical note updated. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    Diffed Contents:
@@ -1,4 +1 @@
-Cause: no metadata caching in the qemu-kvm qcow2 code.
+Previously, qemu-kvm did not include metadata caching, which resulted in poor performance for the the qemu-img rebase process. This is now fixed and the QCOW2 code now includes metadata caching, which results in improved performance for the qemu-img rebase process.-Consequence: poor performance of 'qemu-img rebase'
-Fix: a metadata cache was introduced into the qcow2 code.
-Result: improved performance of 'qemu-img rebase'.

Comment 20 errata-xmlrpc 2011-05-19 11:27:05 UTC

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2011-0534.html

Comment 21 errata-xmlrpc 2011-05-19 12:49:12 UTC

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2011-0534.html

Note You need to log in before you can comment on or make changes to this bug.