Bug 617286

> attached is virsh logs - please contact me in case you want to observe issue in

You didn't attach any logs to this BZ

Created attachment 434212 [details]
virsh log

It is pretty hard to tell what's the biggest problem here. The log isn't entirely conclusive, but it does suggest that the virDomainGetInfo() API is being slow, apparently as a result of 'query-balloon' being slow.

I fear this may be a result of the extended balloon statistics change. Originally the 'query-balloon' monitor command would return the balloon value immediately. Now it first asks the guest OS to update the extended balloon statistics, waits for that to happen and then returns the data. It does this even when we don't want the extended balloon statistics. My theory is that on a highly loaded system is it taking a while for the guest OS to be re-scheduled & reply with the balloon stats.

If this hypothesis is correct, we will need to do something with the 'query-balloon' command. Either setup a separate command for querying extended stats, or add a parameter to 'query-balloon' to  indicate whether extended stats should be returned or not.

(In reply to comment #3)
> It is pretty hard to tell what's the biggest problem here. The log isn't
> entirely conclusive, but it does suggest that the virDomainGetInfo() API is
> being slow, apparently as a result of 'query-balloon' being slow.
> 
> I fear this may be a result of the extended balloon statistics change.
> Originally the 'query-balloon' monitor command would return the balloon value
> immediately. Now it first asks the guest OS to update the extended balloon
> statistics, waits for that to happen and then returns the data. It does this
> even when we don't want the extended balloon statistics. My theory is that on a
> highly loaded system is it taking a while for the guest OS to be re-scheduled &
> reply with the balloon stats.
> 
> If this hypothesis is correct, we will need to do something with the
> 'query-balloon' command. Either setup a separate command for querying extended
> stats, or add a parameter to 'query-balloon' to  indicate whether extended
> stats should be returned or not.    

Remember that the above VMs do not have balloon at all.

> Remember that the above VMs do not have balloon at all.

All guests run via libvirt have the balloon driver enabled.

What guest OS is running in these guests ? Are any of them RHEL6 guests ?

(In reply to comment #5)
> > Remember that the above VMs do not have balloon at all.
> 
> All guests run via libvirt have the balloon driver enabled.

Really? We (RHEV-M) do not support it, so I don't think we should waste a PCI slot on balloon.

> 
> What guest OS is running in these guests ? Are any of them RHEL6 guests ?

(In reply to comment #5)
> > Remember that the above VMs do not have balloon at all.
> 
> All guests run via libvirt have the balloon driver enabled.
> 
> What guest OS is running in these guests ? Are any of them RHEL6 guests ?    

Daniel - can we disable this option via xml and not use the balloon driver ?

> can we disable this option via xml and not use the balloon driver ?    

No that isn't supported by libvirt. If my hypothesis of comment #3 is correct, then we need to address this at the QEMU level.

What's the reason for forcing the balloon device?
From what I read here http://www.redhat.com/archives/libvir-list/2010-January/msg00035.html  it sounds like it's to maintain backward compatibility and that's the reason for adding it by default.

But what's the reason for not having the ability to disable it?

I tend to agree, I just posted a rather simple patch allowing to
disable the balloon driver by using the 
  <memballoon type="none"/>
construct, patch is very simple applies to RHEL-6 code directly and
seems to work without changing the normal behaviour:

https://www.redhat.com/archives/libvir-list/2010-August/msg00118.html

Since I don't think we will be able to make a change to qemu, this may be
a simpler interim solution.
To note though, this seems related to Windows guests, when running
with 250+ Linux RHEL-6 guests we didn't see the huge slowdown issues
raised here (it was a bit slow of course with that number of guests
but not as slow as reported). So this is really due to the guest
reactivity on balloon requests it seems...

Daniel

> To note though, this seems related to Windows guests, when running
> with 250+ Linux RHEL-6 guests we didn't see the huge slowdown issues
> raised here (it was a bit slow of course with that number of guests
> but not as slow as reported). So this is really due to the guest
> reactivity on balloon requests it seems...

Very odd. This is actually the exact opposite of what I'd expect to see. The Windows balloon driver does not support the extended memory statistics, so the balloon monitor command should be taking the fast path. The slow path would only be taken with Linux guests supporting the new stats (basically only RHEL6 so far, perhaps RHEL 5.6).

Either way I don't think that disabling the balloon driver is really a suitable fix for this bug. The balloon provides core functionality & we need libvirt to perform well with it enabled, so if there is a balloon problem we likely need to address it at QEMU.

Sure QEmu need to be fixed, but that's outside libvirt scope (mostly
we would need to use the simpler function when available.
Still forcing the baloon in libvirt KVM guest as this is an option
of the hypervisor is a policy, and we should not impose policies
at the libvirt level.
I'm rewriting the patch as you blocked the simplest way upstream, but
I want this fixed.

Daniel

https://bugzilla.redhat.com/show_bug.cgi?id=623096

has been cloned as the qemu-kvm bug for this issue, very likely to be the
real bug (this need more testing on a big box)

In the meantime I made a build libvirt-0.8.1-23.el6 allowing to disable
the ballon device with type='none' it's not perfect but at this point that's
the only viable option to disable the balloon on RHEL-6, far from perfect
but the one with the less risks.

Daniel

Just a little comment for future frustrated verifiers: the element should have "model", not "type" attribute.

<memballoon model="none"/>

Okay, I have been able to go into one of those boxes:

[root@intel-XE7450-512-1 ~]# w
 20:47:10 up  9:03,  7 users,  load average: 107.63, 105.43, 105.66
...
[root@intel-XE7450-512-1 ~]# ps auxwww | grep qemu-kvm | wc -l
101

all of those domains are running Windows 2008R2 in core mode and 
under libvirt control

I could reproduce the problem with the help of Guannan Ren

[root@intel-XE7450-512-1 ~]# time virsh list > /tmp/list
real    8m32.513s
user    0m0.153s
sys     0m1.039s

I gdb' attached to the libvirtd daemon and traced into qemudDomainGetInfo
the first call to qemudGetProcessInfo returns immediately, but the
qemuMonitorGetBalloonInfo() call takes a bit of lag.
Then I experimented a bit and noticed the following:

[root@intel-XE7450-512-1 ~]# time virsh dominfo wintest1 > /dev/null

real	0m1.988s
user	0m0.008s
sys	0m0.178s

but ....

[root@intel-XE7450-512-1 ~]# time virsh dominfo wintest99 > /dev/null

real	0m7.129s
user	0m0.012s
sys	0m0.396s
[root@intel-XE7450-512-1 ~]#

  So some VM takes way longuer to answer than others

I gdb attached again on libvirtd and traced again in qemudDomainGetInfo
when called asking for this specific domain info and no surprize gdb
waited for nearly 10 second returning from that step

5213	            err = qemuMonitorGetBalloonInfo(priv->mon, &balloon);
(gdb) 

tracing deeper we actually issue the command though JSON interface in
qemuMonitorJSONGetBalloonInfo()

912	    virJSONValuePtr cmd = qemuMonitorJSONMakeCommand("query-balloon",
(gdb) 
916	    *currmem = 0;
(gdb) 
918	    if (!cmd)
(gdb) 
921	    ret = qemuMonitorJSONCommand(mon, cmd, &reply);

and that step is taking nearly 10s for this domain
I hadn't a good way to retry this with a domain without balooning
in the immediate but I'm gonna try if possible,

Daniel

So I restarted one guest without the memballoon device,
I'm not sure it's conclusive I restarted wintest99:


[root@intel-XE7450-512-1 ~]# time virsh dominfo wintest98 > /dev/null

real	0m17.605s
user	0m0.008s
sys	0m0.269s
[root@intel-XE7450-512-1 ~]# time virsh dominfo wintest99 > /dev/null

real	0m2.672s
user	0m0.013s
sys	0m0.300s
[root@intel-XE7450-512-1 ~]

this is still slow, okay the machine is extremely loaded, but still
[root@intel-XE7450-512-1 ~]# ps auxwww | grep wintest98
qemu     18854  2.9  0.0 854144 541396 ?       Sl   17:58   7:05 /usr/libexec/qemu-kvm -S -M rhel6.0.0 -enable-kvm -m 512 -smp 1,sockets=1,cores=1,threads=1 -name wintest98 -uuid 5b86d226-9bb0-0f39-2319-c6c9b11dfffc -nodefconfig -nodefaults -chardev socket,id=monitor,path=/var/lib/libvirt/qemu/wintest98.monitor,server,nowait -mon chardev=monitor,mode=control -rtc base=utc -boot c -drive file=/mnt/wintest98,if=none,id=drive-ide0-0-0,boot=on,format=raw,cache=none -device ide-drive,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0 -netdev tap,fd=18,id=hostnet0 -device rtl8139,netdev=hostnet0,id=net0,mac=52:54:00:2b:2e:98,bus=pci.0,addr=0x3 -chardev pty,id=serial0 -device isa-serial,chardev=serial0 -usb -vnc 127.0.0.1:98 -k en-us -vga cirrus -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x4
root     53590 10.0  0.0 103148   844 pts/105  R+   21:57   0:00 grep wintest98
[root@intel-XE7450-512-1 ~]#  ps auxwww | grep wintest99
qemu     52590  1.9  0.0 777552 15864 ?        Sl   21:50   0:08 /usr/libexec/qemu-kvm -S -M rhel6.0.0 -enable-kvm -m 512 -smp 1,sockets=1,cores=1,threads=1 -name wintest99 -uuid 27fbcd64-98f2-7732-7a04-1f7d5c39ccc2 -nodefconfig -nodefaults -chardev socket,id=monitor,path=/var/lib/libvirt/qemu/wintest99.monitor,server,nowait -mon chardev=monitor,mode=control -rtc base=utc -boot c -drive file=/mnt/wintest99,if=none,id=drive-ide0-0-0,boot=on,format=raw,cache=none -device ide-drive,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0 -netdev tap,fd=18,id=hostnet0 -device rtl8139,netdev=hostnet0,id=net0,mac=52:54:00:23:36:32,bus=pci.0,addr=0x3 -chardev pty,id=serial0 -device isa-serial,chardev=serial0 -usb -vnc 127.0.0.1:99 -k en-us -vga cirrus
root     53632  8.0  0.0 103148   844 pts/105  R+   21:57   0:00 grep wintest99
[root@intel-XE7450-512-1 ~]# 

the difference is the virtio balloon part of the command ...

Daniel

Hmm, I think there's a missing piece here. The <memballoon type='none'/> patch just allows the balloon device to be removed from the QEMU binary. It doesn't stop libvirt issuing the 'query-balloon' monitor command.

So instead of issuing a monitor command & getting back the balloon value, we now issue a monitor command & get back an error. In the context of Windows guests, this won't have changed the response time / performance at all. It will only have improved with Linux guests, because it will have eliminated the call into the guest OS.

Another interesting scalability point, I restarted the
libvirtd on that loaded box, and virsh command just get
stuck, apparently waiting for the server to answer on
the socket ...
Well it appears that the box is busy reconnecting to the hundred
qemu guests after 5mn it's still around guest 80 out of 100

a lot of time seems to be spent in qemudParsePCIDeviceStrs()
and some qemuMonitorJSON commands or qemudExtractVersionInfo().

Maybe some of this could be cached at least for the reconnect on
startup,

Daniel

precision about previous comment ... when I said time spent,
actually libvirtd is waiting for data to be read from qemu-kvm
typically

#0  0x0000003795c0e50d in read () from /lib64/libpthread.so.0
#1  0x0000000000436dee in read (fd=30, buf=0xc87850, count=8192)
    at /usr/include/bits/unistd.h:45
#2  saferead (fd=30, buf=0xc87850, count=8192) at util/util.c:93
#3  0x0000000000436ec6 in saferead_lim (fd=30, maxlen=65536, 
    buf=0x7fff1afd7288) at util/util.c:1045
#4  virFileReadLimFD (fd=30, maxlen=65536, buf=0x7fff1afd7288)
    at util/util.c:1075
#5  0x000000000045da6e in qemudExtractVersionInfo (
    qemu=0xdbb7d0 "/usr/libexec/qemu-kvm", retversion=0x0, 
    retflags=0x7fff1afd7318) at qemu/qemu_conf.c:1482
#6  0x000000000043f363 in qemuReconnectDomain (payload=0xdb3fb0, 
    name=<value optimized out>, opaque=0xc91120) at qemu/qemu_driver.c:1664

and

#0  0x0000003795c0e50d in read () from /lib64/libpthread.so.0
#1  0x0000000000436dee in read (fd=28, buf=0xc8b860, count=4097)
    at /usr/include/bits/unistd.h:45
#2  saferead (fd=28, buf=0xc8b860, count=4097) at util/util.c:93
#3  0x0000000000436ec6 in saferead_lim (fd=28, maxlen=4096, buf=0x7fff1afd7280)
    at util/util.c:1045
#4  virFileReadLimFD (fd=28, maxlen=4096, buf=0x7fff1afd7280)
    at util/util.c:1075
#5  0x000000000045dd2e in qemudParsePCIDeviceStrs (qemu=<value optimized out>, 
    retversion=0x0, retflags=0x7fff1afd7318) at qemu/qemu_conf.c:1432
#6  qemudExtractVersionInfo (qemu=<value optimized out>, retversion=0x0, 
    retflags=0x7fff1afd7318) at qemu/qemu_conf.c:1505
#7  0x000000000043f363 in qemuReconnectDomain (payload=0xc936a0, 
    name=<value optimized out>, opaque=0xc91120) at qemu/qemu_driver.c:1664

Daniel

Humpf, 30mn later libvirtd is still in the process of reconnecting to the
guests there is something weird going on

#1  0x0000000000436dee in read (fd=30, buf=0xc87850, count=8192)
    at /usr/include/bits/unistd.h:45
#2  saferead (fd=30, buf=0xc87850, count=8192) at util/util.c:93
#3  0x0000000000436ec6 in saferead_lim (fd=30, maxlen=65536, 
    buf=0x7fff1afd7288) at util/util.c:1045
#4  virFileReadLimFD (fd=30, maxlen=65536, buf=0x7fff1afd7288)
    at util/util.c:1075
#5  0x000000000045da6e in qemudExtractVersionInfo (
    qemu=0xdbb7d0 "/usr/libexec/qemu-kvm", retversion=0x0, 
    retflags=0x7fff1afd7318) at qemu/qemu_conf.c:1482
#6  0x000000000043f363 in qemuReconnectDomain (payload=0xdb3fb0, 
    name=<value optimized out>, opaque=0xc91120) at qemu/qemu_driver.c:1664

I found a rogue libvirtd running, killed it and restarted the service, weird...

Daniel

This all just sounds to me like the machine is heavily (over) committed with VMs, and this is slowing down all operations on the host, whether talking to QEMU, or spawning processes during libvirtd startup.

Agreed, that we can probably cache the QEMU data across libvirtd restarts - this protects us against QEMU RPM being upgraded. It is not entirely simple though, because we need a data format that is stable long term in case libvirtd itself is upgraded.

I found something, the box is actually a NUMA, with 96 cores with 4 cells
and at 100 Windows guest the qemu were incredibly slow, I guess it's due
to qrmu-kvm not being pinned to a given cell and being bounced from
node to node as they were all competing for CPU. With Linux guests
the load is lower so that did scale better but the same kind of issue
arose after twice the number of guest.

That doesn't explain completely the slowness though, 7s to get back qemu-kvm
feedback on balloon (especially if that should have been an error) is a bit
extreme.

Daniel

When restarting the machine with 80 windows guests and ballooning
desactivated, plus applying the small extra patch

https://www.redhat.com/archives/libvir-list/2010-August/msg00207.html

this looks far better:

[root@intel-XE7450-512-1 tmp]# time virsh list > /tmp/list

real	0m16.896s
user	0m0.080s
sys	0m0.608s
[root@intel-XE7450-512-1 tmp]# w
 19:50:20 up  9:42,  7 users,  load average: 92.27, 84.82, 66.58

So I would push to add this extra small patch in as this really solve the
issue, or at least its perception.

Having worked on that box quite a bit more and checked from gdb I think
we have issues on loaded workload, basically libvirtd sends a command to
QEmu though the monitor/QMP and we don't get rescheduled upon the reply
it seems like we hit a timeout, and then parse the buffer back. The balloon
command is just one example of it, it happens with other command or when
we execute a binary waiting for its reply, like for the info command when
launching new guests. I have seen very often zombies of qemu-kvm when
lauching guests in a row, as if the process exited with the reply but libvirtd
fifn't catch the output and waitpid() it.

Daniel

After further investigation the slowness of 'virsh list' in comment #24 is caused by the 'cpu' cgroups controller. Disabling the 'cpu' controller makes virsh list complete in < 1 second, instead of 16 seconds.

We have filed a report for this kernel bug:

  https://bugzilla.redhat.com/show_bug.cgi?id=623712

Seems Dan Berrange found out the culprit,  the 'cpu'  cgroups controller has a
very serious scalability problem, he's raising the kernel bug,
but basically stopping cgroup and restarting libvirtd and the guests
leads to normal performances again:

service cgconfig stop

service libvirtd restart

restart the 80 Windows guests

[root@intel-XE7450-512-1 tmp]# time virsh  list > /tmp/list

real	0m0.434s
user	0m0.132s
sys	0m0.031s
[root@intel-XE7450-512-1 tmp]# 

with 80 Windows guests and the patched libvirt from comment #24
With a full load of 128 Windows 2008 guests the machine doesn't feel sluggish
anymore it continues to "feel" fast 

[root@intel-XE7450-512-1 tmp]# ps auxwww | grep qemu-kvm | grep -v grep | wc -l
128
[root@intel-XE7450-512-1 tmp]# time virsh list > /tmp/list 

real	0m0.882s
user	0m0.227s
sys	0m0.040s
[root@intel-XE7450-512-1 tmp]# tail -5 /tmp/list
125 wintest125           running
126 wintest126           running
127 wintest127           running
128 wintest128           running

[root@intel-XE7450-512-1 tmp]# 


[root@intel-XE7450-512-1 ~]# vmstat 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
92 64      0 955395456 194832 17772168    0    0     7     5    8    2  0 11 87  1  0	
76 72      0 954403904 194832 17772040    0    0  7127  1227 88693 111074  7 35 39 19  0	
80  6      0 953933248 194832 17771900    0    0  5261   637 92868 109690  8 37 40 14  0	
86  5      0 953778624 194832 17771900    0    0  6006   108 92057 108078  7 38 51  4  0	

Daniel

libvirt-0.8.1-24.el6 has been built in RHEL-6-candidate with the second
patch needed for virsh list and virsh dominfo speedup under load improvements.
Please test this version instead,

  thanks

Daniel

Just another data point on scalability, the rescanning done on libvirtd
restart with 128 running Windows guests is done to 50 seconds once the
cgroup service is disabled, so it doesn't look bad in a normal setup.
(things could be improved but that's okay IMHO)

Daniel

Now 208 guests were booted up, since there are 128 guest running, 25 guests were boot after 10 seconds break, left 55 guests were boot after that and almost boot up at the same time. 
Here is the data:
[root@intel-XE7450-512-1 clone_vm]# rpm -q libvirt
libvirt-0.8.1-24.el6.x86_64
[root@intel-XE7450-512-1 clone_vm]# ps auxwww | grep qemu-kvm | grep -v grep | wc -l
208
[root@intel-XE7450-512-1 clone_vm]# time virsh list > /tmp/list

real	0m2.176s
user	0m0.315s
sys	0m0.082s

[root@intel-XE7450-512-1 clone_vm]# tail -5 /tmp/list
205 bbwin77              running
206 bbwin78              running
207 bbwin79              running
208 bbwin80              running

[root@intel-XE7450-512-1 clone_vm]# w
 14:29:02 up 1 day,  4:21,  4 users,  load average: 167.34, 163.70, 147.74

[root@intel-XE7450-512-1 clone_vm]# vmstat 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
173  7      0 593346880 262860 333000320    0    0     5    44    1    3  3 27 69  1  0	
111 18      0 592818560 262872 333000096    0    0  4224   612 120407 66131 12 87  1  0  0	
154  6      0 592117376 262900 332999360    0    0  4484   808 119987 78269 11 88  2  0  0	
191 12      0 591686720 262912 332999264    0    0  4960   645 119555 70040 12 87  1  0  0	
200 14      0 591078400 262924 332998656    0    0  5001   754 119119 66201 13 86  1  0  0	

As show above, i think this bug is verified.

After all 208 guests successfully boot up, each guest can get ip address, checking by nmap.
# nmap 192.168.100.*
...
Nmap done: 256 IP addresses (209 hosts up) scanned in 519.12 seconds

# time virsh list > /tmp/list

real	0m0.704s
user	0m0.069s
sys	0m0.087s

# tail -5 /tmp/list
205 bbwin77              running
206 bbwin78              running
207 bbwin79              running
208 bbwin80              running

# w
 15:35:23 up 1 day,  5:27,  4 users,  load average: 183.77, 201.95, 203.79

Red Hat Enterprise Linux 6.0 is now available and should resolve
the problem described in this bug report. This report is therefore being closed
with a resolution of CURRENTRELEASE. You may reopen this bug report if the
solution does not work for you.