[libvirt] Bug in DOMINFO command when balloon driver is used on a vm with more then 8 GB of MaxMemory ?

Hi , I have been banging my head on this for the last 8 hours ... and i really need to know if is really a bug or i am doing something wrong. Description of the problem: When the virsh setmem command is used to inflate the balloon on a VM to which 8GB of MaxMemory or more are allocated then the information reported with virsh dominfo , virsh dumpxml after the balloon change has been performed are wrong. The actual balloon is inflated correctly though and that is verifiable both in the vm itself and through the "virsh dommemstat" commands. I *think* that is because the dommestat command will perform a proper query to find out the amount of ram currently used (and i can see that in the logs when issuing a dommestat command) 2013-03-22 21:22:41.820+0000: 23181: debug : virJSONValueToString:1133 : result={"execute":"query-balloon","id":"libvirt-9"} 2013-03-22 21:22:41.820+0000: 23181: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"query-balloon","id":"libvirt-9"}' for write with FD -1 2013-03-22 21:22:41.820+0000: 23181: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d643eb5a0 msg={"execute":"query-balloon","id":"libvirt-9"} 2013-03-22 21:22:41.820+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d643eb5a0 buf={"execute":"query-balloon","id":"libvirt-9"} but no entries are shown in the log for qemu-monitor when virsh dominfo is run, how does dominfo gather those informations? I am going to raise a ticket on RED HAT bugzilla for this but was hoping to get some feedback here first to avoid raising a ticket for something that maybe i just misunderstood. Platform is Centos 6.4 (problem was present in 6.3 as well starting with libvirt-0.9.10-21.el6.3.7 ) The patch that actually is causing the problem is patch number 398 in the src rpm for libvirt-0.9.10-21.el6.3.7 : libvirt-Wire-up-handling-for-QMP-s-BALLOON_EVENT.patch ( https://bugzilla.redhat.com/show_bug.cgi?id=884713) And i verified it by removing the patch and recompiling the rpm , that indeed worked perfectly after that. The problem exists in every version up to the latest (that is what i am running now) but now the patch is part of the libvirt source code in itself and not a patch in the rpm anymore. Software used: # yum list installed | egrep -i "qemu|libvirt" gpxe-roms-qemu.noarch 0.9.7-6.9.el6 @base libvirt.x86_64 0.10.2-18.el6_4.2 @updates libvirt-client.x86_64 0.10.2-18.el6_4.2 @updates libvirt-python.x86_64 0.10.2-18.el6_4.2 @updates qemu-img.x86_64 2:0.12.1.2-2.355.0.1.el6.centos.2 @updates qemu-kvm.x86_64 2:0.12.1.2-2.355.0.1.el6.centos.2 @updates qemu-kvm-tools.x86_64 2:0.12.1.2-2.355.0.1.el6.centos.2 @updates Full example ( long and include debug logs ) : 1) Start VM with 12GB of MAX and CURRENT (12582912) (tail -f libvirtd.log | grep -i balloon) 2013-03-22 21:06:34.438+0000: 23180: debug : qemuMonitorSetBalloon:1690 : mon=0x7f3d6c1789e0 newmem=12582912 2013-03-22 21:06:34.438+0000: 23180: debug : virJSONValueToString:1133 : result={"execute":"balloon","arguments":{"value":12884901888},"id":"libvirt-6"} 2013-03-22 21:06:34.438+0000: 23180: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"balloon","arguments":{"value":12884901888},"id":"libvirt-6"}' for write with FD -1 2013-03-22 21:06:34.438+0000: 23180: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d6c1789e0 msg={"execute":"balloon","arguments":{"value":12884901888},"id":"libvirt-6"} 2013-03-22 21:06:34.439+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d6c1789e0 buf={"execute":"balloon","arguments":{"value":12884901888},"id":"libvirt-6"} # dominfo 2 Id: 2 Name: centos_jt UUID: bc25a6c4-ba34-a593-47c7-6372999946d6 OS Type: hvm State: running CPU(s): 1 CPU time: 26.6s Max memory: 12582912 KiB Used memory: 12582912 KiB Persistent: yes Autostart: disable Managed save: no Security model: none Security DOI: 0 2) set mem to 8GB # setmem 2 --live --config --size 8388608 2013-03-22 21:13:45.522+0000: 23183: debug : qemuMonitorSetBalloon:1690 : mon=0x7f3d6c1789e0 newmem=8388608 2013-03-22 21:13:45.522+0000: 23183: debug : virJSONValueToString:1133 : result={"execute":"balloon","arguments":{"value":8589934592},"id":"libvirt-9"} 2013-03-22 21:13:45.522+0000: 23183: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"balloon","arguments":{"value":8589934592},"id":"libvirt-9"}' for write with FD -1 2013-03-22 21:13:45.522+0000: 23183: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d6c1789e0 msg={"execute":"balloon","arguments":{"value":8589934592},"id":"libvirt-9"} 2013-03-22 21:13:45.523+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d6c1789e0 buf={"execute":"balloon","arguments":{"value":8589934592},"id":"libvirt-9"} 2013-03-22 21:13:45.528+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d6c1789e0 buf={"timestamp": {"seconds": 1363986825, "microseconds": 528314}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:13:45.528+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363986825, "microseconds": 528314}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}}] 2013-03-22 21:13:45.528+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363986825, "microseconds": 528314}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:13:45.528+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d6c1789e0 event={"timestamp": {"seconds": 1363986825, "microseconds": 528314}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:13:45.528+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1685ce0 2013-03-22 21:13:45.528+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d6c1789e0 2013-03-22 21:13:45.528+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 12582912 to 12581888 kb 2013-03-22 21:13:46.528+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d6c1789e0 buf={"timestamp": {"seconds": 1363986826, "microseconds": 352941}, "event": "BALLOON_CHANGE", "data": {"actual": 12884901888}} 2013-03-22 21:13:46.528+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363986826, "microseconds": 352941}, "event": "BALLOON_CHANGE", "data": {"actual": 12884901888}}] 2013-03-22 21:13:46.528+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363986826, "microseconds": 352941}, "event": "BALLOON_CHANGE", "data": {"actual": 12884901888}} 2013-03-22 21:13:46.528+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d6c1789e0 event={"timestamp": {"seconds": 1363986826, "microseconds": 352941}, "event": "BALLOON_CHANGE", "data": {"actual": 12884901888}} 2013-03-22 21:13:46.528+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1686770 2013-03-22 21:13:46.528+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d6c1789e0 2013-03-22 21:13:46.528+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 12581888 to 12582912 kb virsh # dominfo 2 Id: 2 Name: centos_jt UUID: bc25a6c4-ba34-a593-47c7-6372999946d6 OS Type: hvm State: running CPU(s): 1 CPU time: 41.6s Max memory: 12582912 KiB Used memory: 12582912 KiB Persistent: yes Autostart: disable Managed save: no Security model: none Security DOI: 0 virsh # dommemstat 2 actual 8388608 rss 599916 The Balloon was actually inflated , and in the VM i can see 8GB of Ram available with free 3) setmem to to 3000000 2013-03-22 21:18:19.182+0000: 23181: debug : qemuMonitorSetBalloon:1690 : mon=0x7f3d6c1789e0 newmem=3000000 2013-03-22 21:18:19.182+0000: 23181: debug : virJSONValueToString:1133 : result={"execute":"balloon","arguments":{"value":3072000000},"id":"libvirt-63"} 2013-03-22 21:18:19.182+0000: 23181: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"balloon","arguments":{"value":3072000000},"id":"libvirt-63"}' for write with FD -1 2013-03-22 21:18:19.182+0000: 23181: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d6c1789e0 msg={"execute":"balloon","arguments":{"value":3072000000},"id":"libvirt-63"} 2013-03-22 21:18:19.183+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d6c1789e0 buf={"execute":"balloon","arguments":{"value":3072000000},"id":"libvirt-63"} 2013-03-22 21:18:19.184+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d6c1789e0 buf={"timestamp": {"seconds": 1363987099, "microseconds": 184245}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:18:19.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363987099, "microseconds": 184245}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}}] 2013-03-22 21:18:19.184+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363987099, "microseconds": 184245}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:18:19.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d6c1789e0 event={"timestamp": {"seconds": 1363987099, "microseconds": 184245}, "event": "BALLOON_CHANGE", "data": {"actual": 12883853312}} 2013-03-22 21:18:19.184+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1688320 2013-03-22 21:18:19.184+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d6c1789e0 2013-03-22 21:18:19.191+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 12582912 to 12581888 kb 2013-03-22 21:18:20.184+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d6c1789e0 buf={"timestamp": {"seconds": 1363987100, "microseconds": 184128}, "event": "BALLOON_CHANGE", "data": {"actual": 11874074624}} 2013-03-22 21:18:20.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363987100, "microseconds": 184128}, "event": "BALLOON_CHANGE", "data": {"actual": 11874074624}}] 2013-03-22 21:18:20.184+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363987100, "microseconds": 184128}, "event": "BALLOON_CHANGE", "data": {"actual": 11874074624}} 2013-03-22 21:18:20.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d6c1789e0 event={"timestamp": {"seconds": 1363987100, "microseconds": 184128}, "event": "BALLOON_CHANGE", "data": {"actual": 11874074624}} 2013-03-22 21:18:20.184+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1685ce0 2013-03-22 21:18:20.184+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d6c1789e0 2013-03-22 21:18:20.184+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 12581888 to 11595776 kb 2013-03-22 21:18:21.184+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d6c1789e0 buf={"timestamp": {"seconds": 1363987100, "microseconds": 224930}, "event": "BALLOON_CHANGE", "data": {"actual": 11661934592}} 2013-03-22 21:18:21.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363987100, "microseconds": 224930}, "event": "BALLOON_CHANGE", "data": {"actual": 11661934592}}] 2013-03-22 21:18:21.184+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363987100, "microseconds": 224930}, "event": "BALLOON_CHANGE", "data": {"actual": 11661934592}} 2013-03-22 21:18:21.184+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d6c1789e0 event={"timestamp": {"seconds": 1363987100, "microseconds": 224930}, "event": "BALLOON_CHANGE", "data": {"actual": 11661934592}} 2013-03-22 21:18:21.184+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1686770 2013-03-22 21:18:21.184+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d6c1789e0 2013-03-22 21:18:21.184+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 11595776 to 11388608 virsh # dominfo 2 Id: 2 Name: centos_jt UUID: bc25a6c4-ba34-a593-47c7-6372999946d6 OS Type: hvm State: running CPU(s): 1 CPU time: 53.0s Max memory: 12582912 KiB Used memory: 11388608 KiB Persistent: yes Autostart: disable Managed save: no Security model: none Security DOI: 0 virsh # dommemstat 2 actual 3000000 rss 599036 4) Restart vm with 4GB of Current and Max (4194304) 2013-03-22 21:20:58.894+0000: 23182: debug : qemuMonitorSetBalloon:1690 : mon=0x7f3d643eb5a0 newmem=4194304 2013-03-22 21:20:58.894+0000: 23182: debug : virJSONValueToString:1133 : result={"execute":"balloon","arguments":{"value":4294967296},"id":"libvirt-6"} 2013-03-22 21:20:58.894+0000: 23182: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"balloon","arguments":{"value":4294967296},"id":"libvirt-6"}' for write with FD -1 2013-03-22 21:20:58.894+0000: 23182: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d643eb5a0 msg={"execute":"balloon","arguments":{"value":4294967296},"id":"libvirt-6"} 2013-03-22 21:20:58.894+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d643eb5a0 buf={"execute":"balloon","arguments":{"value":4294967296},"id":"libvirt-6"} virsh # dominfo 3 Id: 3 Name: centos_jt UUID: bc25a6c4-ba34-a593-47c7-6372999946d6 OS Type: hvm State: running CPU(s): 1 CPU time: 15.4s Max memory: 4194304 KiB Used memory: 4194304 KiB Persistent: yes Autostart: disable Managed save: no Security model: none Security DOI: 0 virsh # dommemstat 3 actual 4194304 rss 431384 5) reduce ram to 1GB virsh # setmem 3 --live --config --size 1048576 2013-03-22 21:26:08.783+0000: 23183: debug : qemuMonitorSetBalloon:1690 : mon=0x7f3d643eb5a0 newmem=1048576 2013-03-22 21:26:08.783+0000: 23183: debug : virJSONValueToString:1133 : result={"execute":"balloon","arguments":{"value":1073741824},"id":"libvirt-11"} 2013-03-22 21:26:08.783+0000: 23183: debug : qemuMonitorJSONCommandWithFd:265 : Send command '{"execute":"balloon","arguments":{"value":1073741824},"id":"libvirt-11"}' for write with FD -1 2013-03-22 21:26:08.783+0000: 23183: debug : qemuMonitorSend:903 : QEMU_MONITOR_SEND_MSG: mon=0x7f3d643eb5a0 msg={"execute":"balloon","arguments":{"value":1073741824},"id":"libvirt-11"} 2013-03-22 21:26:08.784+0000: 23179: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f3d643eb5a0 buf={"execute":"balloon","arguments":{"value":1073741824},"id":"libvirt-11"} 2013-03-22 21:26:08.789+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d643eb5a0 buf={"timestamp": {"seconds": 1363987568, "microseconds": 789570}, "event": "BALLOON_CHANGE", "data": {"actual": 4293918720}} 2013-03-22 21:26:08.789+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363987568, "microseconds": 789570}, "event": "BALLOON_CHANGE", "data": {"actual": 4293918720}}] 2013-03-22 21:26:08.789+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363987568, "microseconds": 789570}, "event": "BALLOON_CHANGE", "data": {"actual": 4293918720}} 2013-03-22 21:26:08.789+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d643eb5a0 event={"timestamp": {"seconds": 1363987568, "microseconds": 789570}, "event": "BALLOON_CHANGE", "data": {"actual": 4293918720}} 2013-03-22 21:26:08.789+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x1686360 2013-03-22 21:26:08.789+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d643eb5a0 2013-03-22 21:26:08.789+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 4194304 to 4193280 kb 2013-03-22 21:26:09.789+0000: 23179: debug : qemuMonitorIOProcess:353 : QEMU_MONITOR_IO_PROCESS: mon=0x7f3d643eb5a0 buf={"timestamp": {"seconds": 1363987569, "microseconds": 408889}, "event": "BALLOON_CHANGE", "data": {"actual": 1073741824}} 2013-03-22 21:26:09.789+0000: 23179: debug : qemuMonitorJSONIOProcessLine:152 : Line [{"timestamp": {"seconds": 1363987569, "microseconds": 408889}, "event": "BALLOON_CHANGE", "data": {"actual": 1073741824}}] 2013-03-22 21:26:09.789+0000: 23179: debug : virJSONValueFromString:975 : string={"timestamp": {"seconds": 1363987569, "microseconds": 408889}, "event": "BALLOON_CHANGE", "data": {"actual": 1073741824}} 2013-03-22 21:26:09.789+0000: 23179: debug : qemuMonitorJSONIOProcessLine:167 : QEMU_MONITOR_RECV_EVENT: mon=0x7f3d643eb5a0 event={"timestamp": {"seconds": 1363987569, "microseconds": 408889}, "event": "BALLOON_CHANGE", "data": {"actual": 1073741824}} 2013-03-22 21:26:09.789+0000: 23179: debug : qemuMonitorJSONIOProcessEvent:138 : handle BALLOON_CHANGE handler=0x4b4de0 data=0x16826e0 2013-03-22 21:26:09.789+0000: 23179: debug : qemuMonitorEmitBalloonChange:1151 : mon=0x7f3d643eb5a0 2013-03-22 21:26:09.789+0000: 23179: debug : qemuProcessHandleBalloonChange:1248 : Updating balloon from 4193280 to 1048576 kb virsh # dominfo 3 Id: 3 Name: centos_jt UUID: bc25a6c4-ba34-a593-47c7-6372999946d6 OS Type: hvm State: running CPU(s): 1 CPU time: 28.6s Max memory: 4194304 KiB Used memory: 1048576 KiB Persistent: yes Autostart: disable Managed save: no Security model: none Security DOI: 0 virsh # dommemstat 3 actual 1048576 rss 411740

On 03/22/2013 04:11 PM, fc lists wrote:
Hi ,
I have been banging my head on this for the last 8 hours ... and i really need to know if is really a bug or i am doing something wrong.
Cleaning out my inbox, and I don't think I ever saw a reply to this one.
Description of the problem:
When the virsh setmem command is used to inflate the balloon on a VM to which 8GB of MaxMemory or more are allocated then the information reported with virsh dominfo , virsh dumpxml after the balloon change has been performed are wrong.
It turned out to be a bug in qemu and not libvirt; it has since been fixed for the upcoming qemu 1.5, and will probably be backported to other stable builds (pester your distro to include the fix, if they haven't already).
I am going to raise a ticket on RED HAT bugzilla for this but was hoping to get some feedback here first to avoid raising a ticket for something that maybe i just misunderstood.
Platform is Centos 6.4 (problem was present in 6.3 as well starting with libvirt-0.9.10-21.el6.3.7 )
Then it looks like this bug is relevant to your setup: https://bugzilla.redhat.com/show_bug.cgi?id=927336 -- Eric Blake eblake redhat com +1-919-301-3266 Libvirt virtualization library http://libvirt.org
participants (2)
-
Eric Blake
-
fc lists