Bug 815791

Summary:	deal with qemu block-job-set-speed race fix
Product:	Red Hat Enterprise Linux 6	Reporter:	Eric Blake <eblake>
Component:	libvirt	Assignee:	Eric Blake <eblake>
Status:	CLOSED ERRATA	QA Contact:	Virtualization Bugs <virt-bugs>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	6.3	CC:	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
Target Milestone:	rc
Target Release:	6.2
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	libvirt-0.9.10-16.el6	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:	811683	Environment:
Last Closed:	2012-06-20 06:57:36 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	582475, 799055, 811683, 812085, 813953
Bug Blocks:	580954, 638508, 638509, 748534, 756082, 769496, 786141, 802284, 806280, 806432

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