CPU usage very high provisioning VM on vcloud-director

[aledsage]

CPU usage is high when deploying to private vcloud-director environment (e.g. 80% CPU usage when deploying 4 VMs concurrently, using 4 separate calls to createNodesInGroup, but probably (?) sharing the same ComputeContext for all of them).

Doing some light-weight profiling, it looks like deserializing the vCD messages is expensive, particularly when querying for lots of information - e.g. for all vApp Templates, or all VMs, and then for each of those independently.

e.g. to get all vApp Templates, we made 58 consecutive GET calls (two per vApp Template - one with the suffix /ovf). Each call returned approx 90 lines of XML (which we logged at debug) - taking 97 seconds in total.

Similarly we made 51 sequential calls to get each individual vApp (230 lines of XML each) - taking 32 seconds in total.

It seems we are listing all vApps because of the call to org.jclouds.compute.strategy.impl.CreateNodesWithGroupEncodedIntoNameThenAddToSet.getNextNames, from BaseComputeService.createNodesInGroup. Can we avoid this?

Are we caching the vApp Templates anywhere in the ComputeService to avoid repeated calls?

[andreaturli]

This PR mitigates the issues reported here #25

[aledsage]

Here's how I investigated the performance. It was just a quick look, rather than any real profiling...

The 80% was when doing top on the Brooklyn server, while deploying to various vcloud-director environments (including private clouds and vCloud Air).

For the number of calls and time taken, I just grep'ed the debug log on my local machine and looked at the timestamps in the log, along with the number of consecutive calls, e.g. something like:

grep -E ">> (GET|POST|DELETE) .*acme01.acme.com" brooklyn.debug.log

For knowing it was in the naming method, when getting all vApps, I'd previously run Alex's jstack-active script which does some smart filtering of the results of jstack to only show the runnable threads (i.e. only those consuming CPU). e.g.:

for i in {1..20}; do echo run $i; date; jstack-active 6811; done >  ~/jstack-active.out

The jstack-active is a useful light-weight thing to use. It's not really a substitute for a proper profiler, but it can quickly indicate where big problems are if something repeatedly shows up (and easy to run. even if you haven't got a profiler already attached or ready to hand).

[aledsage]

With PR #25 merged, here is the output from grep'ing the log.

Looking at 4 concurrent VM deployments, it looks like we do the following:

• once: lookup the org (1 call)
• once: lookup each vcd (8 calls; 4 seconds elapsed)
• once: lookup all the vAppTemplates (89 calls; 90 seconds)
• 4 times concurrently (i.e. once per VM)
  • retrieve all vApps (56 calls; 93 seconds)
  • retrieve more details of the chosen vAppTemplate (6ish calls)
  • one POST to composeVApp
  • polling for the task to finish (e.g. 36 calls, approx 1 second apart; but starts faster - e.g. 5 in first second)

[aledsage]

For getting the vAppTemplates, we only make one call per vAppTemplate, such as:

GET https://emea01.canopy-cloud.com/api/vAppTemplate/vappTemplate-80f4451d-bc1b-48a1-a683-350ba01e4084/ovf