vCenter driver seems slow spinning up new VMs

Community Support
1

Hi Devs,

I’m currently in the process of automating environment deployments with OpenNebula and vCenter. Our application has been divided so that only one service lives and operates on a right sized VM. For this reason, we have large deployments of VMs for each environment we deploy. The amount of VMs can be anywhere between 140 and 180 VMs per environment. While testing deployments of VMs with OpenNebula with vCenter drivers, it seems that the driver takes a long time to deploy VMs. Starting a deployment of 170 VMs took on average an hour and 30 minutes to complete. Is it because the vCenter driver is running in sync mode? If it is, is there a reason for it to run in sync mode instead of async? Is it possible to update the vCenter driver so that it can deploy VMs in async mode?

The setup is 4 ESXi Hosts managed with vCenter 5.5 and PureStorage SSD SAN.

Thanks,
Jesus

2

vCenter drivers deploy VM operation is indeed synchronous, due to OpenNebula internal design, and cannot be trivially changed.

What you can do to make OpenNebula launch more VMs simultaneously is to increment the number of threads of the VM driver. In /etc/one/oned.conf:

#-------------------------------------------------------------------------------
#VM_MAD = [
#    name       = "vcenter",
#    executable = "one_vmm_sh",
#    arguments  = "-p -t 15 -r 0 vcenter -s sh",
#    default    = "vmm_exec/vmm_exec_vcenter.conf",
#    type       = "xml" ]
#--------------------------------------------------------------------------------

Change the -t 15 to -t 100 for instance. This will launch simultaneously 100 VMs instead of just in batches of 15.

Please let us know if this alleviates the problem.

3

Hi Tino,

Thanks for providing this insight. Despite me making this change though, the provisioning of VMs is basically the same speed. Below is a screenshot of how this looks like in Sunstone UI.

http://imgur.com/0QjUbhB

As you can see once a specific VM goes from BOOT to RUNNING, then the next PENDING VM goes from PENDING to BOOT. This is the time when the commands are sent to vCenter to clone the template I’m using and booting the VM.

Below is the log oned.log. As you can see the VMs don’t seem to get deployed in batches, but one at a time:

Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:7760 UID:0 VirtualMachineDeploy invoked , 938, 2, false, -1
Mon Oct 26 17:45:47 2015 [Z0][DiM][D]: Deploying VM 938
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:7760 UID:0 VirtualMachineDeploy result SUCCESS, 938
Mon Oct 26 17:45:47 2015 [Z0][VMM][D]: Message received: LOG I 938 Successfully execute network driver operation: pre.

Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:9376 UID:0 VirtualMachineInfo invoked , 938
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:9376 UID:0 VirtualMachineInfo result SUCCESS, "<VM><ID>938</ID><UID..."
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:1360 UID:0 SystemConfig invoked 
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:1360 UID:0 SystemConfig result SUCCESS, "<TEMPLATE><AUTH_MAD>..."
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:6000 UID:0 HostInfo invoked , 2
Mon Oct 26 17:45:47 2015 [Z0][ReM][D]: Req:6000 UID:0 HostInfo result SUCCESS, "<HOST><ID>2</ID><NAM..."
Mon Oct 26 17:45:55 2015 [Z0][ReM][D]: Req:704 UID:1 DocumentPoolInfo invoked , -2, -1, -1, 100
Mon Oct 26 17:45:55 2015 [Z0][ReM][D]: Req:704 UID:1 DocumentPoolInfo result SUCCESS, "<DOCUMENT_POOL></DOC..."
Mon Oct 26 17:45:59 2015 [Z0][VMM][D]: Message received: LOG I 938 Successfully execute virtualization driver operation: deploy.

Mon Oct 26 17:45:59 2015 [Z0][VMM][D]: Message received: LOG I 938 Successfully execute network driver operation: post.

Mon Oct 26 17:45:59 2015 [Z0][VMM][D]: Message received: DEPLOY SUCCESS 938 42213b08-70d0-8369-ad96-bcaa1e4c6766

Mon Oct 26 17:46:00 2015 [Z0][InM][D]: Monitoring datastore default (1)
Mon Oct 26 17:46:00 2015 [Z0][InM][D]: Monitoring datastore files (2)
Mon Oct 26 17:46:00 2015 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Mon Oct 26 17:46:00 2015 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Mon Oct 26 17:46:15 2015 [Z0][InM][D]: Monitoring host SJCCLUSTER (2)
Mon Oct 26 17:46:15 2015 [Z0][ReM][D]: Req:2832 UID:0 SystemConfig invoked 
Mon Oct 26 17:46:15 2015 [Z0][ReM][D]: Req:2832 UID:0 SystemConfig result SUCCESS, "<TEMPLATE><AUTH_MAD>..."
Mon Oct 26 17:46:15 2015 [Z0][ReM][D]: Req:5520 UID:0 HostInfo invoked , 2
Mon Oct 26 17:46:15 2015 [Z0][ReM][D]: Req:5520 UID:0 HostInfo result SUCCESS, "<HOST><ID>2</ID><NAM..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6176 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6176 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>176..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6768 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6768 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>176..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:9536 UID:0 DatastorePoolInfo invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:9536 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6208 UID:0 DatastorePoolInfo invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6208 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6416 UID:0 HostPoolInfo invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6416 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><HOST><ID..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:5968 UID:0 ClusterPoolInfo invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:5968 UID:0 ClusterPoolInfo result SUCCESS, "<CLUSTER_POOL><CLUST..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:4032 UID:0 AclInfo invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:4032 UID:0 AclInfo result SUCCESS, "<ACL_POOL><ACL><ID>0..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:9920 UID:0 VirtualMachineDeploy invoked , 939, 2, false, -1
Mon Oct 26 17:46:17 2015 [Z0][DiM][D]: Deploying VM 939
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:9920 UID:0 VirtualMachineDeploy result SUCCESS, 939
Mon Oct 26 17:46:17 2015 [Z0][VMM][D]: Message received: LOG I 939 Successfully execute network driver operation: pre.

Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6128 UID:0 VirtualMachineInfo invoked , 939
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6128 UID:0 VirtualMachineInfo result SUCCESS, "<VM><ID>939</ID><UID..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:16 UID:0 SystemConfig invoked 
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:16 UID:0 SystemConfig result SUCCESS, "<TEMPLATE><AUTH_MAD>..."
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6080 UID:0 HostInfo invoked , 2
Mon Oct 26 17:46:17 2015 [Z0][ReM][D]: Req:6080 UID:0 HostInfo result SUCCESS, "<HOST><ID>2</ID><NAM..."
Mon Oct 26 17:46:25 2015 [Z0][ReM][D]: Req:8640 UID:1 DocumentPoolInfo invoked , -2, -1, -1, 100
Mon Oct 26 17:46:25 2015 [Z0][ReM][D]: Req:8640 UID:1 DocumentPoolInfo result SUCCESS, "<DOCUMENT_POOL></DOC..."
Mon Oct 26 17:46:31 2015 [Z0][VMM][D]: Message received: LOG I 939 Successfully execute virtualization driver operation: deploy.

Mon Oct 26 17:46:31 2015 [Z0][VMM][D]: Message received: LOG I 939 Successfully execute network driver operation: post.

Mon Oct 26 17:46:31 2015 [Z0][VMM][D]: Message received: DEPLOY SUCCESS 939 42218819-1931-74aa-f32f-c3424e02d100

Thanks for looking into this.

Jesus