I'm testing on 12 Cores x 2 HT per code. As I'm working on teasing out software bottlenecks, I'm intentionally running fewer tasks (20 parallel creations) than the number of logical cores (24). The memory, disk and network are also well over provisioned. I hadn't tuned libvirtd.conf at all. I have just increased max_{clients,workers,requests,client_requests} to 50 and repeated my experiment. As you expected, virtConnectGetLibVersion is now very fast. Unfortunately, the median VM creation time didn't change. Unless there are other parameters to tweak, I believe I'm still hitting a bottleneck. Booting 1 VM vs booting 20 VMs in parallel, the times for libvirt calls are virConnectDefineXML*: 13ms vs 4.5s virDomainCreateWithFlags*: 1.8s vs 20s * I had said that virConnectDefineXML wasn't serialized in my first email. I based that observation on a single trace I looked at :-) In the average case, virConnectDefineXML is affected by a bottleneck. Note that when I took these measurements, I also monitored CPU & disk utilization. During the 20 VM test, both CPU & disk were well below 100% for 97% of the test (i.e., 60s test duration, measured utilization with atop using a 2 second interval, CPU was pegged for 2s). Testing your hypothesis would be straightforward. I'll add some instrumentation to measure the time spent waiting for the locks and repeat my 20 VM experiment. Or, if there's some systematic lock profiling in place, then I can turn that on and report the results. Thanks, Peter

On Thu, May 16, 2013 at 1:18 PM, Daniel P. Berrange <berrange(a)redhat.com&gt; wrote: Okay cool, I'll measure this. I'll also try to figure out what virDomainCreateWithFlags is waiting on. A straightforward way to keep lock statistics with low overhead and w/out affecting concurrency would be to use thread local storage (TLS). At the end of a run, or periodically, the stats could be aggregated and reported. Since the stats don't have to be precise, it's OK to do the aggregation racily. Simple statistics to keep are * For each lock L, the time spent waiting. * For each lock L and callsite C, the time spent waiting. It would probably be sufficient to identify L as the lock's parent class name. If per-instance stats are necessary, then we could add the address of the object to the identity of L. So pseudo code would look something like this: struct lock_stats { map of (lock_class) to unsigned long: wait_time; map of (lock_class, stack_trace) to unsigned long: callsite_wait_time; }; __thread struct lock_stats * lock_stats; thread_local_storage_init() { lock_stats = new lock_stats; } /* return microseconds elapsed since some arbitrary start time */ unsigned long timestamp(void) { struct timespec timespec; clock_gettime(CLOCK_MONOTONIC, &timespec); return timespec.tv_sec * 1e6 + timespec.tv_sec / 10; } void virObjectLock(void *anyobj) { unsigned long start, elapsed; virObjectLockablePtr obj = anyobj; start = timestamp(); virMutexLock(&obj->lock); elapsed = timestamp() - start; lock_stats->wait_time[obj->parent.klass->name] += elapsed lock_stats->wait_time[obj->parent.klass->name, get_stack_trace()] += elapsed }

... Cool! The systemtap approach was very fruitful. BTW, at the time of writing, the example script has a bug. See http://sourceware.org/ml/systemtap/2013-q2/msg00169.html for the fix. So the root cause of my bottleneck is the virSecurityManager lock. parts of the mutex-contention.stp report are pasted at the end of this email. Here's the summary & my analysis: When a domain is created (domainCreateWithFlags), the domain object's lock is held. During the domain creation, various virSecurity functions are called, which all grab the security manager's lock. Since the security manager's lock is global, some fraction of domainCreateWithFlags is serialized by this lock. Since some virSecurity functions can take a long time, such as virSecurityManagerGenLabel for the apparmor security driver, which takes around 1s, the serialization that the security manager lock induces in domainCreateWithFlags is substantial. Since the domain's object lock is held all of this time, virDomainObjListSearchName blocks, thereby serializing virConnectDefineXML via virDomainObjListAdd, as you suggested earlier. Moreover, since the virDomainObjList lock is held while blocking in virDomainObjListSearchName, there's measurable contention whilst looking up domains during domainCreateWithFlags. Since some security driver operations are costly, I think it's worthwhile to reduce the scope of the security manager lock or increase the granularity by introducing more locks. After a cursory look, the security manager lock seems to have a much broader scope than necessary. The system / library calls underlying the security drivers are all thread safe (e.g., defining apparmor security profiles or chowning disk files), so a global lock isn't strictly necessary. Moreover, since most virSecurity calls are made whilst a virDomainObj lock is held and the security calls are generally domain specific, *most* of the security calls are probably thread safe in the absence of the global security manager lock. Obviously some work will have to be done to see where the security lock actually matters and some finer-grained locks will have to be introduced to handle these situations. I also think it's worthwhile to eliminate locking from the the virDomainObjList lookups and traversals. Since virDomainObjLists are accessed in a bunch of places, I think it's a good defensive idea to decouple the performance of these accesses from virDomainObj locks, which are held during potentially long-running operations like domain creation. An easy way to divorce virDomainObjListSearchName from the virDomainObj lock would be to keep a copy of the domain names in the virDomainObjList and protect that list with the virDomainObjList lock. What do you think? Peter ============== stack contended 4 times, 261325 avg usec, 576521 max usec, 1045301 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] virDomainObjListFindByUUID+0x21 [libvirt.so.0.1000.4] qemuDomainGetXMLDesc+0x48 [libvirt_driver_qemu.so] virDomainGetXMLDesc+0xf5 [libvirt.so.0.1000.4] remoteDispatchDomainGetXMLDescHelper+0xb6 [libvirtd] virNetServerProgramDispatch+0x498 [libvirt.so.0.1000.4] virNetServerProcessMsg+0x2a [libvirt.so.0.1000.4] virNetServerHandleJob+0x73 [libvirt.so.0.1000.4] virThreadPoolWorker+0x10e ============== stack contended 12 times, 128053 avg usec, 992567 max usec, 1536640 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] virDomainObjListFindByUUID+0x21 [libvirt.so.0.1000.4] qemuDomainStartWithFlags+0x5a [libvirt_driver_qemu.so] virDomainCreateWithFlags+0xf5 [libvirt.so.0.1000.4] remoteDispatchDomainCreateWithFlagsHelper+0xbe [libvirtd] virNetServerProgramDispatch+0x498 [libvirt.so.0.1000.4] virNetServerProcessMsg+0x2a [libvirt.so.0.1000.4] virNetServerHandleJob+0x73 [libvirt.so.0.1000.4] virThreadPo ============== stack contended 24 times, 289502 avg usec, 3441079 max usec, 6948070 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] virDomainObjListSearchName+0x19 [libvirt.so.0.1000.4] virHashSearch+0x65 [libvirt.so.0.1000.4] virDomainObjListAddLocked.isra.37+0x1f4 [libvirt.so.0.1000.4] virDomainObjListAdd+0x45 [libvirt.so.0.1000.4] qemuDomainDefine+0xfa [libvirt_driver_qemu.so] virDomainDefineXML+0x8b [libvirt.so.0.1000.4] remoteDispatchDomainDefineXMLHelper+0x84 [libvirtd] virNetServerProgramDispatch+0x498 [l ============== stack contended 15 times, 3454756 avg usec, 5041310 max usec, 51821341 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] virDomainObjListAdd+0x2e [libvirt.so.0.1000.4] qemuDomainDefine+0xfa [libvirt_driver_qemu.so] virDomainDefineXML+0x8b [libvirt.so.0.1000.4] remoteDispatchDomainDefineXMLHelper+0x84 [libvirtd] virNetServerProgramDispatch+0x498 [libvirt.so.0.1000.4] virNetServerProcessMsg+0x2a [libvirt.so.0.1000.4] virNetServerHandleJob+0x73 [libvirt.so.0.1000.4] virThreadPoolWorker+0x10e [libvirt.so. ============== stack contended 6 times, 3291567 avg usec, 7098148 max usec, 19749405 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] qemuProcessStart+0x1014 [libvirt_driver_qemu.so] qemuDomainObjStart+0x24e [libvirt_driver_qemu.so] qemuDomainStartWithFlags+0x152 [libvirt_driver_qemu.so] virDomainCreateWithFlags+0xf5 [libvirt.so.0.1000.4] remoteDispatchDomainCreateWithFlagsHelper+0xbe [libvirtd] virNetServerProgramDispatch+0x498 [libvirt.so.0.1000.4] virNetServerProcessMsg+0x2a [libvirt.so.0.1000.4] virNetServerHa ============== stack contended 16 times, 3708683 avg usec, 7936168 max usec, 59338928 total usec, at __lll_lock_wait+0x1c [libpthread-2.15.so] _L_lock_858+0xf [libpthread-2.15.so] __pthread_mutex_lock+0x3a [libpthread-2.15.so] virSecurityManagerGenLabel+0x50 [libvirt.so.0.1000.4] qemuProcessStart+0x297 [libvirt_driver_qemu.so] qemuDomainObjStart+0x24e [libvirt_driver_qemu.so] qemuDomainStartWithFlags+0x152 [libvirt_driver_qemu.so] virDomainCreateWithFlags+0xf5 [libvirt.so.0.1000.4] remoteDispatchDomainCreateWithFlagsHelper+0xbe [libvirtd] virNetServerProgramDispatch+0x498 [libvirt.so.0.1000.4] virNetServe

On Fri, May 24, 2013 at 11:37:04AM -0400, Peter Feiner wrote: Yep, that sounds like a sane approach to me. Previously the security drivers had no locking at all, since they were relying on the global lock at the QEMU driver level. When I introduced the lock into the security manager module, I was pessimistic and used coarse locking. As you say, we can clearly relax this somewhat, if we have the locking in the individual security drivers. Yep, I had a patch to add a security hash table to the domain object list, hashing based on name, but I lost the code when a disk died. I didn't find it made any difference, but agree we should just do it anyway, since it'll almost certainly be a problem in some scenarios. Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|