815791 – deal with qemu block-job-set-speed race fix

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 815791 - deal with qemu block-job-set-speed race fix

Summary: deal with qemu block-job-set-speed race fix

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	6.3
Hardware:	All
OS:	Linux
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	6.2
Assignee:	Eric Blake
QA Contact:	Virtualization Bugs
Docs Contact:
URL:
Whiteboard:
Depends On:	582475 799055 811683 812085 813953
Blocks:	580954 638508 638509 748534 756082 769496 786141 802284 806280 806432
TreeView+	depends on / blocked

Reported:	2012-04-24 14:13 UTC by Eric Blake
Modified:	2013-01-10 00:54 UTC (History)
CC List:	33 users (show)
Fixed In Version:	libvirt-0.9.10-16.el6
Doc Type:	Bug Fix
Doc Text:
Clone Of:	811683
Environment:
Last Closed:	2012-06-20 06:57:36 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHSA-2012:0748	0	normal	SHIPPED_LIVE	Low: libvirt security, bug fix, and enhancement update	2012-06-19 19:31:38 UTC

Comment 1 Eric Blake 2012-04-24 14:26:33 UTC

The latest upstream qemu proposal is here; the impact to libvirt is using the parameter name 'speed' instead of 'value' for virDomainBlockJobSetSpeed(), and using the optional 'speed' parameter of 'block-stream' and 'drive-mirror' to avoid the race.
https://lists.gnu.org/archive/html/qemu-devel/2012-04/msg03510.html

Comment 4 Eric Blake 2012-04-25 23:06:26 UTC

The upstream half of the fix (for block-stream):
https://www.redhat.com/archives/libvir-list/2012-April/msg01372.html
I will have to prepare the drive-mirror half later, since the drive-mirror patches are currently RHEL-only.

Comment 5 Eric Blake 2012-04-27 23:10:09 UTC

In POST, but we should be cautious about applying this until we know for sure that qemu will be fixed per bug 813953

http://post-office.corp.redhat.com/archives/rhvirt-patches/2012-April/msg00867.html

Comment 11 Wayne Sun 2012-05-04 10:19:01 UTC

env prepare:
1. prpare a domain with qed img disk
# virsh dumpxml dom
...
    <disk type='file' device='disk'>
      <driver name='qemu' type='qed' cache='none'/>
      <source file='/var/lib/libvirt/images/qed.img'/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04'
function='0x0'/>
    </disk>
...

2. create img backing file
# qemu-img create -f qed -b /var/lib/libvirt/images/qed.img
/var/lib/libvirt/images/qed1.img
Formatting '/var/lib/libvirt/images/qed1.img', fmt=qed size=8388608000
backing_file='/var/lib/libvirt/images/qed.img' cluster_size=0 table_size=0 

3. edit domain disk as using the backing file
# virsh edit dom
...
    <disk type='file' device='disk'>
      <driver name='qemu' type='qed' cache='none'/>
      <source file='/var/lib/libvirt/images/qed1.img'/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04'
function='0x0'/>
    </disk>
...

4. start domain
# virsh start dom



On RHEL6.2
libvirt-0.9.4-23.el6.x86_64
qemu-kvm-0.12.1.2-2.209.el6.x86_64


Steps:
1. set blockjob speed with no active device

# virsh blockjob dom vda --bandwidth 1
error: Requested operation is not valid: No active operation on device: drive-virtio-disk0

2. do blockpull with setting bandwidth
# virsh blockpull dom vda --bandwidth 1

check libvirtd.log:
16:57:36.905: 21141: debug : qemuMonitorBlockJob:2562 : mon=0x7f1a3c002ea0, device=0x7f1a4c0ed130, bandwidth=1, info=(nil), mode=3
16:57:36.905: 21141: debug : virJSONValueToString:1068 : object=0x7f1a4c193340
16:57:36.905: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c193340 type=0 gen=0x7f1a4c0ee2a0
16:57:36.905: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c1a1080 type=2 gen=0x7f1a4c0ee2a0
16:57:36.905: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c1a0580 type=0 gen=0x7f1a4c0ee2a0
16:57:36.905: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c1929f0 type=2 gen=0x7f1a4c0ee2a0
16:57:36.905: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c192b20 type=2 gen=0x7f1a4c0ee2a0
16:57:36.905: 21141: debug : virJSONValueToString:1102 : result={"execute":"block_stream","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-8"}
...

16:57:36.906: 21141: debug : virJSONValueToString:1102 : result={"execute":"block_job_set_speed","arguments":{"device":"drive-virtio-disk0","value":1048576},"id":"libvirt-9"}
16:57:36.906: 21141: debug : virEventPollUpdateHandle:145 : Update handle w=13 e=15
...

block_stream followed by block_job_set_speed

3. check blockjob info
# virsh blockjob dom vda --info
Block Pull: [  0 %]    Bandwidth limit: 1 MB/s


check libvirtd.log:
16:57:51.809: 21141: debug : qemuMonitorBlockJob:2562 : mon=0x7f1a3c002ea0, device=0x7f1a4c136570, bandwidth=0, info=0x7f1a598c5b90, mode=1
16:57:51.809: 21141: debug : virJSONValueToString:1068 : object=0x7f1a4c1a1080
16:57:51.809: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c1a1080 type=0 gen=0x7f1a4c0ee2a0
16:57:51.809: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c193340 type=2 gen=0x7f1a4c0ee2a0
16:57:51.809: 21141: debug : virJSONValueToStringOne:1000 : object=0x7f1a4c193c10 type=2 gen=0x7f1a4c0ee2a0
16:57:51.809: 21141: debug : virJSONValueToString:1102 : result={"execute":"query-block-jobs","id":"libvirt-10"}
16:57:51.809: 21141: debug : virEventPollUpdateHandle:145 : Update handle w=13 e=15

Can't set blockjob speed after pull start.

On RHEL6.3
pkgs:
libvirt-0.9.10-16.el6.x86_64
qemu-kvm-rhev-0.12.1.2-2.290.el6.x86_64
kernel-2.6.32-262.el6.x86_64


1. set speed on no active device
# virsh blockjob dom vda --bandwidth 1
error: Requested operation is not valid: No active operation on device: drive-virtio-disk0

2. do blockpull with setting bandwidth
# virsh blockpull dom vda --bandwidth 1
Block Pull started


check libvirtd.log:
2012-05-04 09:13:37.651+0000: 21814: debug : virDomainBlockPull:18082 : dom=0x7f792c008f30, (VM: name=dom, uuid=5bddd275-6f55-8530-b39f-79140960bac9), disk=vda, bandwidth=1, flags=0
2012-05-04 09:13:37.651+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-04 09:13:37.651+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-04 09:13:37.651+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=12 e=1 d=0
2012-05-04 09:13:37.651+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=13 e=1 d=0
2012-05-04 09:13:37.651+0000: 21814: debug : qemuDomainObjBeginJobInternal:753 : Starting job: modify (async=none)
...

2012-05-04 09:13:37.713+0000: 21814: debug : qemuMonitorBlockJob:2796 : mon=0x7f79280033f0, device=drive-virtio-disk0, base=(null), bandwidth=1M, info=(nil), mode=3, modern=1
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToString:1071 : object=0x7f792c0097b0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c0097b0 type=0 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c0098b0 type=2 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c009ea0 type=0 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c009ec0 type=2 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c00a060 type=3 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c00a0a0 type=2 gen=0x7f792c000ff0
2012-05-04 09:13:37.713+0000: 21814: debug : virJSONValueToString:1105 : result={"execute":"block-stream","arguments":{"device":"drive-virtio-disk0","speed":1048576},"id":"libvirt-8"}
2012-05-04 09:13:37.713+0000: 21814: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=15
2012-05-04 09:13:37.713+0000: 21814: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:13:37.713+0000: 21814: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f79280033f0 msg={"execute":"block-stream","arguments":{"device":"drive-virtio-disk0","speed":1048576},"id":"libvirt-8"}^M
 fd=-1
2012-05-04 09:13:37.714+0000: 21811: debug : virEventPollRunOnce:630 : Poll got 1 event(s)


As log show, the behaviour is different with 6.2. virDomainBlockPull support with bandwidth, speed was set right at pull event(no block-job-set-speed followed).


3. check blockjob info
# virsh blockjob dom vda
Block Pull: [ 11 %]    Bandwidth limit: 1 MB/s

check libvirtd.log:
2012-05-04 09:13:58.785+0000: 21812: debug : qemuMonitorBlockJob:2796 : mon=0x7f79280033f0, device=drive-virtio-disk0, base=(null), bandwidth=0M, info=0x7f793c715b20, mode=1, modern=1
2012-05-04 09:13:58.785+0000: 21812: debug : virJSONValueToString:1071 : object=0x7f793000d920
2012-05-04 09:13:58.785+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f793000d920 type=0 gen=0x7f79300f94b0
2012-05-04 09:13:58.785+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f793019a7b0 type=2 gen=0x7f79300f94b0
2012-05-04 09:13:58.785+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f793019a310 type=2 gen=0x7f79300f94b0
2012-05-04 09:13:58.785+0000: 21812: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-10"}
2012-05-04 09:13:58.785+0000: 21812: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=15
2012-05-04 09:13:58.785+0000: 21812: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:13:58.785+0000: 21812: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f79280033f0 msg={"execute":"query-block-jobs","id":"libvirt-10"}^M
 fd=-1

4. set speed on active device
# virsh blockjob dom vda --bandwidth 2


check libvirtd.log:
 2012-05-04 09:15:11.538+0000: 21813: debug : qemuMonitorBlockJob:2796 : mon=0x7f79280033f0, device=drive-virtio-disk0, base=(null), bandwidth=2M, info=(nil), mode=2, modern=1
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToString:1071 : object=0x7f79280013f0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f79280013f0 type=0 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f79280017c0 type=2 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f792800c7b0 type=0 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f792800c7d0 type=2 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f79280015b0 type=3 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928002350 type=2 gen=0x7f7928010ac0
2012-05-04 09:15:11.538+0000: 21813: debug : virJSONValueToString:1105 : result={"execute":"block-job-set-speed","arguments":{"device":"drive-virtio-disk0","speed":2097152},"id":"libvirt-11"}
2012-05-04 09:15:11.538+0000: 21813: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=15
2012-05-04 09:15:11.538+0000: 21813: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:15:11.538+0000: 21813: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f79280033f0 msg={"execute":"block-job-set-speed","arguments":{"device":"drive-virtio-disk0","speed":2097152},"id":"libvirt-11"}^M
 fd=-1
2012-05-04 09:15:11.538+0000: 21811: debug : virEventPollRunOnce:630 : Poll got 1 event(s)

5. recheck blockjob info
# virsh blockjob dom vda
Block Pull: [ 14 %]    Bandwidth limit: 2 MB/s

6. redo set speed and check
# virsh blockjob dom vda --bandwidth 3

# virsh blockjob dom vda
Block Pull: [ 15 %]    Bandwidth limit: 3 MB/s

7.abort and check
# virsh blockjob dom vda --abort --async

# virsh blockjob dom vda

check libvirtd.log:
2012-05-04 09:16:05.054+0000: 21812: debug : qemuMonitorBlockJob:2796 : mon=0x7f79280033f0, device=drive-virtio-disk0, base=(null), bandwidth=0M, info=(nil), mode=0, modern=1
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToString:1071 : object=0x7f79301a6f30
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f79301a6f30 type=0 gen=0x7f79300b9590
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f79301a4040 type=2 gen=0x7f79300b9590
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f79301a9a90 type=0 gen=0x7f79300b9590
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f793019a310 type=2 gen=0x7f79300b9590
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToStringOne:1003 : object=0x7f7930196d80 type=2 gen=0x7f79300b9590
2012-05-04 09:16:05.054+0000: 21812: debug : virJSONValueToString:1105 : result={"execute":"block-job-cancel","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-15"}
2012-05-04 09:16:05.054+0000: 21812: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=15
2012-05-04 09:16:05.054+0000: 21812: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:16:05.054+0000: 21812: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f79280033f0 msg={"execute":"block-job-cancel","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-15"}^M
 fd=-1
2012-05-04 09:16:05.054+0000: 21811: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
...

2012-05-04 09:16:09.213+0000: 21813: debug : qemuMonitorBlockJob:2796 : mon=0x7f79280033f0, device=drive-virtio-disk0, base=(null), bandwidth=0M, info=0x7f793bd14b20, mode=1, modern=1
2012-05-04 09:16:09.213+0000: 21813: debug : virJSONValueToString:1071 : object=0x7f7928003660
2012-05-04 09:16:09.213+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928003660 type=0 gen=0x7f7928012cb0
2012-05-04 09:16:09.213+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928002f80 type=2 gen=0x7f7928012cb0
2012-05-04 09:16:09.213+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928001150 type=2 gen=0x7f7928012cb0
2012-05-04 09:16:09.213+0000: 21813: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-16"}
2012-05-04 09:16:09.213+0000: 21813: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=15
2012-05-04 09:16:09.213+0000: 21813: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:16:09.213+0000: 21813: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f79280033f0 msg={"execute":"query-block-jobs","id":"libvirt-16"}^M
 fd=-1
2012-05-04 09:16:09.213+0000: 21811: debug : virEventPollRunOnce:630 : Poll got 1 event(s)

8. Check with blockcopy
8.1 destroy, undefine domain
# virsh destroy dom
Domain dom destroyed

# virsh undefine dom
Domain dom has been undefined

8.2 create transient domain (using the dump xml of guest dom)
# virsh create /root/dom.xml 
Domain dom created from /root/dom.xml

# virsh list
 Id    Name                           State
----------------------------------------------------
 2     dom                            running

8.3 start blockcopy with bandwidth set
# virsh blockcopy dom vda /var/lib/libvirt/images/copy_target --bandwidth 1
Block Copy started

check libvirtd.log:
...
2012-05-04 09:52:52.789+0000: 21812: debug : virDomainBlockRebase:18204 : dom=0x7f7930142270, (VM: name=dom, uuid=c61e3edf-7c8b-24b7-e293-18def9e6a9ab), disk=vda, base=/var/lib/libvirt/images/copy_target bandwidth=1, flags=8
2012-05-04 09:52:52.789+0000: 21812: debug : qemuDomainObjBeginJobInternal:753 : Starting job: modify (async=none)
2012-05-04 09:52:52.884+0000: 21812: debug : virStorageFileIsSharedFSType:1031 : Check if path /var/lib/libvirt/images/copy_target with FS magic 61267 is shared
2012-05-04 09:52:52.884+0000: 21812: debug : qemuMonitorRef:201 : QEMU_MONITOR_REF: mon=0x7f792400a830 refs=3
2012-05-04 09:52:52.884+0000: 21812: debug : qemuMonitorDriveMirror:2653 : mon=0x7f792400a830, device=drive-virtio-disk0, file=/var/lib/libvirt/images/copy_target, format=qed, bandwidth=1M, flags=0
2012-05-04 09:52:52.884+0000: 21812: debug : virJSONValueToString:1071 : object=0x7f793018b600
...

2012-05-04 09:52:52.884+0000: 21812: debug : virJSONValueToString:1105 : result={"execute":"__com.redhat_drive-mirror","arguments":{"device":"drive-virtio-disk0","target":"/var/lib/libvirt/images/copy_target","full":true,"speed":1048576,"mode":"absolute-paths","format":"qed"},"id":"libvirt-7"}
2012-05-04 09:52:52.884+0000: 21812: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 09:52:52.884+0000: 21812: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:52:52.884+0000: 21812: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"__com.redhat_drive-mirror","arguments":{"device":"drive-virtio-disk0","target":"/var/lib/libvirt/images/copy_target","full":true,"speed":1048576,"mode":"absolute-paths","format":"qed"},"id":"libvirt-7"}^M
 fd=-1

No no block-job-set-speed followed.

8.4 check blockjob info
# virsh blockjob dom vda
Block Copy: [ 66 %]    Bandwidth limit: 1 MB/s

check libvirtd.log:
2012-05-04 09:53:02.884+0000: 21813: debug : qemuMonitorBlockJob:2796 : mon=0x7f792400a830, device=drive-virtio-disk0, base=(null), bandwidth=0M, info=0x7f793bd14b20, mode=1, modern=1
2012-05-04 09:53:02.884+0000: 21813: debug : virJSONValueToString:1071 : object=0x7f7928000960
2012-05-04 09:53:02.884+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928000960 type=0 gen=0x7f7928031d30
2012-05-04 09:53:02.884+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928003850 type=2 gen=0x7f7928031d30
2012-05-04 09:53:02.884+0000: 21813: debug : virJSONValueToStringOne:1003 : object=0x7f7928000c50 type=2 gen=0x7f7928031d30
2012-05-04 09:53:02.884+0000: 21813: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-8"}
2012-05-04 09:53:02.885+0000: 21813: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 09:53:02.885+0000: 21813: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 09:53:02.885+0000: 21813: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"query-block-jobs","id":"libvirt-8"}^M
 fd=-1


So, this fix is working expected.

Eric, is this enough for verify this bug? Anything miss?

Comment 12 Eric Blake 2012-05-04 14:08:24 UTC

Everything you did looks pretty thorough, and shows that libvirt is using the new command when it is available.  Other things I can think of testing, if you want:

after step 8.4, test that you can use 'virsh blockjob $dom --bandwidth $speed' to adjust the bandwidth of a copy job.

Have you tried mixing the RHEL 6.2 qemu with the RHEL 6.3 libvirt? (qemu-kvm-0.12.1.2-2.209.el6.x86_64, libvirt-0.9.10-16.el6.x86_64)?  In that case, libvirt should be able to target the older command spelling of block_job_set_speed, and attempts to start a block pull with bandwidth will fail because the qemu is too old to support it atomically.

Comment 13 Wayne Sun 2012-05-04 16:23:15 UTC

(In reply to comment #12)
> Everything you did looks pretty thorough, and shows that libvirt is using the
> new command when it is available.  Other things I can think of testing, if you
> want:
> 
> after step 8.4, test that you can use 'virsh blockjob $dom --bandwidth $speed'
> to adjust the bandwidth of a copy job.
> 
> Have you tried mixing the RHEL 6.2 qemu with the RHEL 6.3 libvirt?
> (qemu-kvm-0.12.1.2-2.209.el6.x86_64, libvirt-0.9.10-16.el6.x86_64)?  In that
> case, libvirt should be able to target the older command spelling of
> block_job_set_speed, and attempts to start a block pull with bandwidth will
> fail because the qemu is too old to support it atomically.

For step 8, I redo with following steps:
8.3 In one console, start blockcopy with speed set. Also with --wait for the job end, and --pivot provided for end the job. 
# virsh blockcopy dom vda /var/lib/libvirt/images/copy_target_3 --bandwidth 2 --wait --pivot

Successfully pivoted

After copy start, check in another console for job info:
# virsh blockjob dom vda
Block Copy: [ 65 %]    Bandwidth limit: 2 MB/s

check libvirtd.log:
2012-05-04 15:22:27.479+0000: 21815: debug : virDomainBlockRebase:18204 : dom=0x7f7920007890, (VM: name=dom, uuid=c61e3edf-7c8b-24b7-e293-18def9e6a9ab), disk=vda, base=/var/lib/libvirt/images/copy_target_3 bandwidth=2, flags=8
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollCleanupHandles:554 : Cleanup 9
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=12 e=1 d=0
2012-05-04 15:22:27.479+0000: 21815: debug : qemuDomainObjBeginJobInternal:753 : Starting job: modify (async=none)
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=13 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=14 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=16 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=17 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=26, f=23 e=25 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=55, f=18 e=1 d=0
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 4 timers
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollCalculateTimeout:331 : Got a timeout scheduled for 1336144952479
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollCalculateTimeout:351 : Timeout at 1336144952479 due in 5000 ms
2012-05-04 15:22:27.479+0000: 21811: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=9 imeout=5000
2012-05-04 15:22:27.515+0000: 21815: debug : virStorageFileIsSharedFSType:1031 : Check if path /var/lib/libvirt/images/copy_target_3 with FS magic 61267 is shared
2012-05-04 15:22:27.516+0000: 21815: debug : qemuMonitorRef:201 : QEMU_MONITOR_REF: mon=0x7f792400a830 refs=3
2012-05-04 15:22:27.516+0000: 21815: debug : qemuMonitorDriveMirror:2653 : mon=0x7f792400a830, device=drive-virtio-disk0, file=/var/lib/libvirt/images/copy_target_3, format=qed, bandwidth=2M, flags=0
...

2012-05-04 15:22:27.516+0000: 21815: debug : virJSONValueToString:1105 : result={"execute":"__com.redhat_drive-mirror","arguments":{"device":"drive-virtio-disk0","target":"/var/lib/libvirt/images/copy_target_3","full":true,"speed":2097152,"mode":"absolute-paths","format":"qed"},"id":"libvirt-232"}
2012-05-04 15:22:27.516+0000: 21815: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 15:22:27.516+0000: 21815: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 15:22:27.516+0000: 21815: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"__com.redhat_drive-mirror","arguments":{"device":"drive-virtio-disk0","target":"/var/lib/libvirt/images/copy_target_3","full":true,"speed":2097152,"mode":"absolute-paths","format":"qed"},"id":"libvirt-232"}^M
 fd=-1
...

Multiple get block job info followed since is at wait:

2012-05-04 15:22:27.675+0000: 21814: debug : virDomainGetBlockJobInfo:17944 : dom=0x7f792c00b5e0, (VM: name=dom, uuid=c61e3edf-7c8b-24b7-e293-18def9e6a9ab), disk=vda, info=0x7f793b313b20, flags=0
...

2012-05-04 15:22:27.699+0000: 21814: debug : qemuMonitorBlockJob:2796 : mon=0x7f792400a830, device=drive-virtio-disk0, base=(null), bandwidth=0M, info=0x7f793b313b20, mode=1, modern=1
2012-05-04 15:22:27.699+0000: 21814: debug : virJSONValueToString:1071 : object=0x7f792c00aec0
2012-05-04 15:22:27.699+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c00aec0 type=0 gen=0x7f792c000c60
2012-05-04 15:22:27.699+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c0008c0 type=2 gen=0x7f792c000c60
2012-05-04 15:22:27.699+0000: 21814: debug : virJSONValueToStringOne:1003 : object=0x7f792c000960 type=2 gen=0x7f792c000c60
2012-05-04 15:22:27.699+0000: 21814: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-233"}
2012-05-04 15:22:27.699+0000: 21814: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 15:22:27.699+0000: 21814: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 15:22:27.699+0000: 21814: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"query-block-jobs","id":"libvirt-233"}^M
 fd=-1
...



8.4 update blockcopy speed

# virsh blockjob dom vda --bandwidth 100

# virsh blockjob dom vda
Block Copy: [ 67 %]    Bandwidth limit: 100 MB/s

Continue with libvirtd.log:
...
2012-05-04 15:22:50.894+0000: 21812: debug : virJSONValueToString:1105 : result={"execute":"block-job-set-speed","arguments":{"device":"drive-virtio-disk0","speed":104857600},"id":"libvirt-273"}
2012-05-04 15:22:50.894+0000: 21812: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 15:22:50.894+0000: 21812: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 15:22:50.894+0000: 21812: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"block-job-set-speed","arguments":{"device":"drive-virtio-disk0","speed":104857600},"id":"libvirt-273"}^M
 fd=-1
...

multiple query-block-jobs followed up

...

2012-05-04 15:24:08.675+0000: 21816: debug : virJSONValueToString:1105 : result={"execute":"__com.redhat_drive-reopen","arguments":{"device":"drive-virtio-disk0","new-image-file":"/var/lib/libvirt/images/copy_target_3","format":"qed"},"id":"libvirt-383"}
2012-05-04 15:24:08.675+0000: 21816: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=15
2012-05-04 15:24:08.675+0000: 21816: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 15:24:08.675+0000: 21816: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7f792400a830 msg={"execute":"__com.redhat_drive-reopen","arguments":{"device":"drive-virtio-disk0","new-image-file":"/var/lib/libvirt/images/copy_target_3","format":"qed"},"id":"libvirt-383"}^M
 fd=-1
2012-05-04 15:24:08.675+0000: 21811: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
...

2012-05-04 15:24:08.675+0000: 21811: debug : qemuMonitorRef:201 : QEMU_MONITOR_REF: mon=0x7f792400a830 refs=4
2012-05-04 15:24:08.676+0000: 21811: debug : qemuMonitorIOWrite:432 : QEMU_MONITOR_IO_WRITE: mon=0x7f792400a830 buf={"execute":"__com.redhat_drive-reopen","arguments":{"device":"drive-virtio-disk0","new-image-file":"/var/lib/libvirt/images/copy_target_3","format":"qed"},"id":"libvirt-383"}^M
 len=176 ret=176 errno=11
2012-05-04 15:24:08.676+0000: 21811: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=26 events=13
...

2012-05-04 15:24:08.677+0000: 21811: debug : qemuMonitorRef:201 : QEMU_MONITOR_REF: mon=0x7f792400a830 refs=4
2012-05-04 15:24:08.677+0000: 21811: debug : qemuMonitorIOProcess:327 : QEMU_MONITOR_IO_PROCESS: mon=0x7f792400a830 buf={"timestamp": {"seconds": 1336145048, "microseconds": 677272}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 8388608000, "offset": 8388608000, "speed": 104857600, "type": "mirror"}}^M
 len=217
2012-05-04 15:24:08.677+0000: 21811: debug : virJSONValueFromString:948 : string={"timestamp": {"seconds": 1336145048, "microseconds": 677272}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 8388608000, "offset": 8388608000, "speed": 104857600, "type": "mirror"}}

Job done.

9. mix with 6.2 qemu and 6.3 libvirt
libvirt-0.9.10-16.el6.x86_64
qemu-kvm-0.12.1.2-2.209.el6.x86_64

9.1 test blockcopy
# virsh blockcopy dom vda /var/lib/libvirt/images/copy_target_3 --bandwidth 2 --wait --pivot
error: unsupported configuration: block copy is not supported with this QEMU binary

As expected, not supported.

9.2 test blockpull with set speed
# virsh blockpull dom vda 1
error: unsupported configuration: setting bandwidth at start of block pull not supported with this QEMU binary

Also expected.

9.3 begin blockpull first

# virsh blockpull dom vda
Block Pull started

# virsh blockjob dom vda
Block Pull: [ 16 %]

check in libvirtd.log:

2012-05-04 16:05:12.986+0000: 24511: debug : virJSONValueToString:1105 : result={"execute":"block_stream","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-7"}
2012-05-04 16:05:12.986+0000: 24511: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=15
2012-05-04 16:05:12.986+0000: 24511: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 16:05:12.986+0000: 24511: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7fd960009660 msg={"execute":"block_stream","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-7"}^M
 fd=-1
...

2012-05-04 16:05:22.318+0000: 24513: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-8"}
2012-05-04 16:05:22.318+0000: 24513: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=15
2012-05-04 16:05:22.318+0000: 24513: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 16:05:22.318+0000: 24513: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7fd960009660 msg={"execute":"query-block-jobs","id":"libvirt-8"}^M
 fd=-1


9.4 set speed

# virsh blockjob dom vda --bandwidth 2

continue with log:
2012-05-04 16:05:34.030+0000: 24509: debug : qemuMonitorIOWrite:432 : QEMU_MONITOR_IO_WRITE: mon=0x7fd960009660 buf={"execute":"block_job_set_speed","arguments":{"device":"drive-virtio-disk0","value":2097152},"id":"libvirt-9"}^M
 len=112 ret=112 errno=11
2012-05-04 16:05:34.030+0000: 24509: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=13

block_job_set_speed spotted, not block-job-set-speed, as expected.
9.5 abort

# virsh blockjob dom vda --abort --async

# virsh blockjob dom vda 

2012-05-04 16:05:50.369+0000: 24512: debug : virJSONValueToString:1105 : result={"execute":"block_job_cancel","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-10"}
2012-05-04 16:05:50.369+0000: 24512: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=15
2012-05-04 16:05:50.369+0000: 24512: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 16:05:50.369+0000: 24512: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7fd960009660 msg={"execute":"block_job_cancel","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-10"}^M
 fd=-1
...

block_job_cancel spotted, as expected.

2012-05-04 16:06:00.027+0000: 24514: debug : virJSONValueToString:1105 : result={"execute":"query-block-jobs","id":"libvirt-11"}
2012-05-04 16:06:00.027+0000: 24514: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=15
2012-05-04 16:06:00.027+0000: 24514: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-04 16:06:00.027+0000: 24514: debug : qemuMonitorSend:823 : QEMU_MONITOR_SEND_MSG: mon=0x7fd960009660 msg={"execute":"query-block-jobs","id":"libvirt-11"}^M
 fd=-1

Comment 15 errata-xmlrpc 2012-06-20 06:57:36 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2012-0748.html

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

abaron
acathrow
ajia
areis
bazulay
berrange
bili
bsarathy
bugproxy
dallan
djuran
dyasny
dyuan
eblake
fosborne
gcosta
gsun
iheim
juzhang
kirbyzhou
michen
mkenneth
mzhan
pbonzini
rwu
shu
syeghiay
tburke
veillard
virt-maint
weizhan
whuang
yupzhang