See also upstream commit 8e532d34, for another ramification of how caching qemu capabilities up front (including QMP monitor capabilities) would be desirable.

Now this bug is even more severe for us that libvirtd checks caps on each startup:

https://bugzilla.gnome.org/show_bug.cgi?id=688791
https://www.redhat.com/archives/libvir-list/2013-January/msg00563.html

(In reply to comment #1)
> See also upstream commit 8e532d34, for another ramification of how caching
> qemu capabilities up front (including QMP monitor capabilities) would be
> desirable.

Did capability caching ever get committed upstream, btw?

(In reply to comment #3)
> (In reply to comment #1)
> > See also upstream commit 8e532d34, for another ramification of how caching
> > qemu capabilities up front (including QMP monitor capabilities) would be
> > desirable.
> 
> Did capability caching ever get committed upstream, btw?

Yes, capabilities are cached as much as is possible now. Each distinct qemu binary on the host will now only ever be invoked once, unless its timestamp changes.

This complaint is about the fact that even though we're only running each QEMU binary once, this still takes non-negligable time. Approx 300ms per QEMU binary on my laptop. Multiply by anywhere between 10-20 binaries.....

The performance hit has moved from the 'virConnectGetCapabilities' command, to initial libvirtd startup instead. You'll never notice this for the systemd libvirtd since that's started on boot. You will notice it for session libvirtd if your app is what triggers it to launch.  Overall there should not have been any worsening of performance though - given that GNOMES queries capabilities, it will suffer the same delay regardless of where it occurs. And in fact starting VMs should now be 300-600ms faster, since we removed re-probing of QEMU in the VM startup path.

Capability caching is upstream, but done on startup; in comment 2, Zeeshan already pointed to the thread suggesting that we defer caps checks to first use instead of startup, but that has not yet been implemented upstream.

(In reply to comment #4)
> (In reply to comment #3)
> > (In reply to comment #1)
> > > See also upstream commit 8e532d34, for another ramification of how caching
> > > qemu capabilities up front (including QMP monitor capabilities) would be
> > > desirable.
> > 
> > Did capability caching ever get committed upstream, btw?
> 
> Yes, capabilities are cached as much as is possible now. Each distinct qemu
> binary on the host will now only ever be invoked once, unless its timestamp
> changes.
> 
> This complaint is about the fact that even though we're only running each
> QEMU binary once, this still takes non-negligable time. Approx 300ms per
> QEMU binary on my laptop. Multiply by anywhere between 10-20 binaries.....
> 
> The performance hit has moved from the 'virConnectGetCapabilities' command,
> to initial libvirtd startup instead. You'll never notice this for the
> systemd libvirtd since that's started on boot. You will notice it for
> session libvirtd if your app is what triggers it to launch.

But if we KNOW which binary we are using, we only have to probe ONE binary for the guest startup, instead of 10-20 binaries.  Caching would still allow us to avoid reprobing, but delaying the cache population until we need it, instead of probing every single binary, should make things feel faster.  Of course, that depends on whether the guest XML calls out a specific binary to use, vs. the default of leaving it up to us to choose the best binary to use by probing all of them.

(In reply to comment #5)
> Capability caching is upstream, but done on startup; in comment 2, Zeeshan
> already pointed to the thread suggesting that we defer caps checks to first
> use instead of startup, but that has not yet been implemented upstream.

First use of capabilities is when we load configs from disk....which is during startup, so that's not going to help matters.

(In reply to comment #6)
> (In reply to comment #4)
> > (In reply to comment #3)
> > > (In reply to comment #1)
> > > > See also upstream commit 8e532d34, for another ramification of how caching
> > > > qemu capabilities up front (including QMP monitor capabilities) would be
> > > > desirable.
> > > 
> > > Did capability caching ever get committed upstream, btw?
> > 
> > Yes, capabilities are cached as much as is possible now. Each distinct qemu
> > binary on the host will now only ever be invoked once, unless its timestamp
> > changes.
> > 
> > This complaint is about the fact that even though we're only running each
> > QEMU binary once, this still takes non-negligable time. Approx 300ms per
> > QEMU binary on my laptop. Multiply by anywhere between 10-20 binaries.....
> > 
> > The performance hit has moved from the 'virConnectGetCapabilities' command,
> > to initial libvirtd startup instead. You'll never notice this for the
> > systemd libvirtd since that's started on boot. You will notice it for
> > session libvirtd if your app is what triggers it to launch.
> 
> But if we KNOW which binary we are using, we only have to probe ONE binary
> for the guest startup, instead of 10-20 binaries.  Caching would still allow
> us to avoid reprobing, but delaying the cache population until we need it,
> instead of probing every single binary, should make things feel faster.  Of
> course, that depends on whether the guest XML calls out a specific binary to
> use, vs. the default of leaving it up to us to choose the best binary to use
> by probing all of them.

You're mixing 2 different uses of capabilities probing here. During guest startup we need to probe the specific QEMU we're about to run which is fine - we do the right thing here already. Populating a virCapabilitiesPtr struct though requires all QEMUs to be probed, and we need this struct when parsing XML on startup, hence startup requires probing all QEMUs.

Actually I what I wrote earlier was slightly incorrect. Both new and old libvirt *would* create capabilities at startup, but old libvirt would do more work on later virConnectGetCapabilities() calls, where as new libvirt has fully cached them.

The core problem seems to be simply that creating capabilities has gone from 1.5 seconds to approx 6 seconds. 50% of this is due to the fact that new libvirt is probing 25 binaries, where as old libvirt was probing 11 binaries. I'm guessing the other 3 seconds overhead comes from using QMP to probe instead of parsing -help.

Can we use the file system to our advantage, and persistently store capabilities and timestamps of each known qemu binary somewhere under /etc/libvirt/, so that we can reread that file at startup instead of connecting to qemu all over again, in the common case where the file still has the same timestamp?

I'd like to focus on improving our impl before we resort to adding in yet more layers of caching.

Looking at libvirt 0.10.2.1, hacked to print out timing info on caps probing:

2013-01-23 20:41:05.049+0000: 2725: info : libvirt version: 0.10.2.1
2013-01-23 20:41:05.049+0000: 2725: error : qemuCreateCapabilities:334 : CAPS start
2013-01-23 20:41:05.301+0000: 2725: error : qemuCapsInit:1057 : qemu-system-i386: 202ms
2013-01-23 20:41:05.499+0000: 2725: error : qemuCapsInit:1057 : qemu-system-x86_64: 198ms
2013-01-23 20:41:05.586+0000: 2725: error : qemuCapsInit:1057 : qemu-system-arm: 87ms
2013-01-23 20:41:05.669+0000: 2725: error : qemuCapsInit:1057 : qemu-system-microblaze: 83ms
2013-01-23 20:41:05.750+0000: 2725: error : qemuCapsInit:1057 : qemu-system-microblazeel: 81ms
2013-01-23 20:41:05.835+0000: 2725: error : qemuCapsInit:1057 : qemu-system-mips: 85ms
2013-01-23 20:41:05.919+0000: 2725: error : qemuCapsInit:1057 : qemu-system-mipsel: 84ms
2013-01-23 20:41:06.002+0000: 2725: error : qemuCapsInit:1057 : qemu-system-sparc: 83ms
2013-01-23 20:41:06.087+0000: 2725: error : qemuCapsInit:1057 : qemu-system-ppc: 85ms
2013-01-23 20:41:06.202+0000: 2725: error : qemuCapsInit:1057 : qemu-system-ppc64: 115ms
2013-01-23 20:41:06.202+0000: 2725: error : qemuCapsInit:1057 : qemu-system-ia64: 0ms
2013-01-23 20:41:06.284+0000: 2725: error : qemuCapsInit:1057 : qemu-system-s390x: 82ms
2013-01-23 20:41:06.284+0000: 2725: error : qemuCreateCapabilities:339 : CAPS end

The reason i386/x86_64 take twice as long is because they (stupidly) probe the same binary twice - once for qemu mode and once for kvm mode! Each probe launches qemu at least 3 times (for -help, -M ? and -device ? and optionally -cpu ?) It is impressive it is only 85 ms for this.

Now compare libvirt GIT 1.0.1

2013-01-23 20:43:39.357+0000: 3082: info : libvirt version: 1.0.1
2013-01-23 20:43:39.357+0000: 3082: error : qemuCreateCapabilities:424 : Caps start
2013-01-23 20:43:39.405+0000: 3082: error : qemuCapsInit:930 : none: 0ms
2013-01-23 20:43:39.473+0000: 3082: error : qemuCapsInit:930 : alpha: 68ms
2013-01-23 20:43:39.729+0000: 3082: error : qemuCapsInit:930 : armv7l: 256ms
2013-01-23 20:43:39.978+0000: 3082: error : qemuCapsInit:930 : cris: 249ms
2013-01-23 20:43:40.496+0000: 3082: error : qemuCapsInit:930 : i686: 518ms
2013-01-23 20:43:40.497+0000: 3082: error : qemuCapsInit:930 : ia64: 0ms
2013-01-23 20:43:40.736+0000: 3082: error : qemuCapsInit:930 : lm32: 239ms
2013-01-23 20:43:40.994+0000: 3082: error : qemuCapsInit:930 : m68k: 258ms
2013-01-23 20:43:41.240+0000: 3082: error : qemuCapsInit:930 : microblaze: 245ms
2013-01-23 20:43:41.489+0000: 3082: error : qemuCapsInit:930 : microblazeel: 249ms
2013-01-23 20:43:41.746+0000: 3082: error : qemuCapsInit:930 : mips: 257ms
2013-01-23 20:43:42.005+0000: 3082: error : qemuCapsInit:930 : mipsel: 259ms
2013-01-23 20:43:42.019+0000: 3054: error : qemuMonitorIORead:502 : Unable to read from monitor: Connection reset by peer
2013-01-23 20:43:42.111+0000: 3082: error : qemuCapsInit:930 : mips64: 106ms
2013-01-23 20:43:42.367+0000: 3082: error : qemuCapsInit:930 : mips64el: 256ms
2013-01-23 20:43:42.367+0000: 3082: error : qemuCapsInit:930 : openrisc: 0ms
2013-01-23 20:43:42.367+0000: 3082: error : qemuCapsInit:930 : parisc: 0ms
2013-01-23 20:43:42.367+0000: 3082: error : qemuCapsInit:930 : parisc64: 0ms
2013-01-23 20:43:42.642+0000: 3082: error : qemuCapsInit:930 : ppc: 275ms
2013-01-23 20:43:42.917+0000: 3082: error : qemuCapsInit:930 : ppc64: 275ms
2013-01-23 20:43:43.175+0000: 3082: error : qemuCapsInit:930 : ppcemb: 258ms
2013-01-23 20:43:43.175+0000: 3082: error : qemuCapsInit:930 : s390: 0ms
2013-01-23 20:43:43.425+0000: 3082: error : qemuCapsInit:930 : s390x: 250ms
2013-01-23 20:43:43.681+0000: 3082: error : qemuCapsInit:930 : sh4: 255ms
2013-01-23 20:43:43.689+0000: 3054: error : qemuMonitorIORead:502 : Unable to read from monitor: Connection reset by peer
2013-01-23 20:43:43.782+0000: 3082: error : qemuCapsInit:930 : sh4eb: 101ms
2013-01-23 20:43:44.030+0000: 3082: error : qemuCapsInit:930 : sparc: 248ms
2013-01-23 20:43:44.286+0000: 3082: error : qemuCapsInit:930 : sparc64: 256ms
2013-01-23 20:43:44.537+0000: 3082: error : qemuCapsInit:930 : unicore32: 251ms
2013-01-23 20:43:44.797+0000: 3082: error : qemuCapsInit:930 : x86_64: 260ms
2013-01-23 20:43:45.045+0000: 3082: error : qemuCapsInit:930 : xtensa: 248ms
2013-01-23 20:43:45.293+0000: 3082: error : qemuCapsInit:930 : xtensaeb: 248ms
2013-01-23 20:43:45.293+0000: 3082: error : qemuCreateCapabilities:429 : Caps end


The time to probe is roughly the same for each arch, which is what we expect, since the do the exact same work for all. Oddly I see random failures as see by the errors above.  The wierdest thing is that it takes soo much longer to run qemu just once & query via QMP, than to run qemu multiple times. I think we need to investigate just why QMP is taking soo much longer. If we could get back to < 100ms per binary we'd be much closer to previous release performance

BTW, with reference to the original bug report about 'virConnectGetCapabilities' API being slow here is current time for that API

# time virsh capabilities  &> /tmp/caps

real	0m0.040s
user	0m0.007s

so you can see our caching is effective. We thus need to focus on libvirtd startup time - in fact there are quite a few other things in libvirtd startup that time a while - particularly if any VMs are running.

Looking at the debug logs I see these interesting lines

2013-01-23 21:03:23.579+0000: 6041: debug : qemuCapsHook:300 : Switch QEMU uid:gid to 0:0
2013-01-23 21:03:23.781+0000: 6010: debug : qemuMonitorOpenInternal:747 : QEMU_MONITOR_NEW: mon=0x7f9ea80ac830 refs=2 fd=16


So between fork()ing qemu and connecting to the monitor, we have 200ms runtime.

Now looking at qemuMonitorOpenUnix I see

    do {                                                                                                                                              
        ret = connect(monfd, (struct sockaddr *) &addr, sizeof(addr));                                                                                
                                                                                                                                                      
        if (ret == 0)                                                                                                                                 
            break;                                                                                                                                    
                                                                                                                                                      
        if ((errno == ENOENT || errno == ECONNREFUSED) &&                                                                                             
            (!cpid || virProcessKill(cpid, 0) == 0)) {                                                                                                
            /* ENOENT       : Socket may not have shown up yet                                                                                        
             * ECONNREFUSED : Leftover socket hasn't been removed yet */                                                                              
            continue;                                                                                                                                 
        }                                                                                                                                             
                                                                                                                                                      
        virReportSystemError(errno, "%s",                                                                                                             
                             _("failed to connect to monitor socket"));                                                                               
        goto error;                                                                                                                                   
                                                                                                                                                      
    } while ((++i <= timeout*5) && (usleep(.2 * 1000000) <= 0));     

So this indicates we're failing to connect initially, sleeping 200ms then trying again. Of course this 200ms sleep is horrific when multiplied by 25 QEMU binaries to run

So this is the root cause of the 200ms sleep problem

commit 5227a718fceccc98e2d837e279b467c468de0ca2
Author: Viktor Mihajlovski <mihajlov@linux.vnet.ibm.com>
Date:   Mon Nov 26 15:17:13 2012 +0100

    qemu: Fix QMP Capabability Probing Failure
    
    QMP Capability probing will fail if QEMU cannot bind to the
    QMP monitor socket in the qemu_driver->libDir directory.
    That's because the child process is stripped of all
    capabilities and this directory is chown'ed to the configured
    QEMU user/group (normally qemu:qemu) by the QEMU driver.
    
    To prevent this from happening, the driver startup will now pass
    the QEMU uid and gid down to the capability probing code.
    All capability probing invocations of QEMU will be run with
    the configured QEMU uid instead of libvirtd's.
    
    Furter, the pid file handling is moved to libvirt, as QEMU
    cannot write to the qemu_driver->runDir (root:root). This also
    means that the libvirt daemonizing must be used.
    
    Signed-off-by: Viktor Mihajlovski <mihajlov@linux.vnet.ibm.com>

When I first wrote the code, I intentionally used QEMU's -daemonize arg so that we'd be guaranteed that the monitor socket was present when control returned to libvirt. This code removed that arg, meaning that libvirt would run before QEMU was ready, thus getting into the 200ms sleep loop. It is also the cause of the periodic failures to probe emulators seen in the log

2013-01-23 20:43:43.689+0000: 3054: error : qemuMonitorIORead:502 : Unable to read from monitor: Connection reset by peer

Need to revert much of this change and fix the UID handling properly

Fix proposed here

https://www.redhat.com/archives/libvir-list/2013-January/msg01816.html

(In reply to comment #16)
> Fix proposed here
> 
> https://www.redhat.com/archives/libvir-list/2013-January/msg01816.html

Seems this and some other related fixes has already landed. Should we treat this as fixed then?

ping?

(In reply to Zeeshan Ali from comment #0)
> Description of problem:
> 
> virConnectGetCapabilities() is slow:
> 
> $ time virsh capabilities &> /tmp/caps 
> 
> real	0m0.663s
> user	0m0.013s
> sys	0m0.010s
> 
> $ time virsh capabilities &> /tmp/caps
> 
> real	0m1.064s
> user	0m0.008s
> sys	0m0.012s

Wow, this is not fixed by a long shot (at least not in libvirt 1.1.3.3 in Fedora 20: 

$ time virsh capabilities &> /tmp/caps 

real	0m3.246s
user	0m0.013s
sys	0m0.015s


Can we do something about this rather critical regression anytime soon?

I think you're not measuring the sped of the capabilities API call there. Instead I'd guess libvirtd was not already running, so you're instead measuring libvirtd start up time.

eg the first call will be slow, but the remaining ones very fast

$ killall libvirtd

$ time virsh capabilities > /tmp/a

real	0m1.536s
user	0m0.008s
sys	0m0.007s

$ time virsh capabilities > /tmp/a

real	0m0.020s
user	0m0.009s
sys	0m0.007s

$ time virsh capabilities > /tmp/a

real	0m0.019s
user	0m0.008s
sys	0m0.006s

(In reply to Daniel Berrange from comment #20)
> I think you're not measuring the sped of the capabilities API call there.

The thing is that this bug was about slow startup of libvirt and the reason to use capabilities command as example and for the title of this bug was that I was told by a libvirt dev (you I think?) back then that slow startup is coming from caps probing.

> Instead I'd guess libvirtd was not already running, so you're instead
> measuring libvirtd start up time.
> 
> eg the first call will be slow, but the remaining ones very fast

With libvirtd timing out at 30seconds, this is what is going to be the case most often for Boxes users. I've added a spinner in Boxes because of this but we really shouldn't need that.

This series adds caching of capabilities information. So the first time libvirtd starts it will be slow as now, but thereafter it'll be fast.

https://www.redhat.com/archives/libvir-list/2014-March/msg00297.html

Merged upstream:
commit cbde35899b901ab3f3108110f23ebf944d7aed74
Author:     Daniel P. Berrange <berrange@redhat.com>
AuthorDate: 2014-03-05 16:51:59 +0000
Commit:     Daniel P. Berrange <berrange@redhat.com>
CommitDate: 2014-03-11 10:59:00 +0000

    Cache result of QEMU capabilities extraction
    
    Extracting capabilities from QEMU takes a notable amount of time
    when all QEMU binaries are installed. Each system emulator
    needs about 200-300ms multiplied by 26 binaries == ~5-8 seconds.
    
    This change causes the QEMU driver to save an XML file containing
    the content of the virQEMUCaps object instance in the cache
    dir eg /var/cache/libvirt/qemu/capabilities/$SHA256(binarypath).xml
    or $HOME/.cache/libvirt/qemu/cache/capabilities/$SHA256(binarypath).xml
    
    We attempt to load this and only if it fails, do we fallback to
    probing the QEMU binary. The ctime of the QEMU binary and libvirtd
    are stored in the cached file and its data discarded if either
    of them change.
    
    Signed-off-by: Daniel P. Berrange <berrange@redhat.com>

git describe: v1.2.2-81-gcbde358 contains: v1.2.3-rc1~306