Slow vCloud Director after upgrade to 5.5.3 from 5.1.2

[acasanovanex]

Last saturday we upgraded our vCloud Director to version 5.5.3 and vShield manager to 5.5.4.1.

The fact is after the upgrade vApp operations (poweron, poweroff) are much slower than before. The sluggishness is not happening always but when it does, vCloud logs are filled with the following messages:

2015-07-08 09:24:01,466 | WARN     | ValidationThread          | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,475 | WARN     | pool-validationservice-13-thread-7237 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,479 | WARN     | pool-validationservice-13-thread-7232 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,480 | WARN     | pool-validationservice-13-thread-7235 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,485 | WARN     | ValidationThread          | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,503 | WARN     | pool-validationservice-13-thread-7235 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,503 | WARN     | pool-validationservice-13-thread-7232 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,504 | WARN     | pool-validationservice-13-thread-7237 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,508 | WARN     | ValidationThread          | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,510 | WARN     | pool-validationservice-13-thread-7231 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:01,523 | WARN     | pool-validationservice-13-thread-7237 | ReactionServiceImpl            | Dropping reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b, 10 of 10 reactions already running. |

2015-07-08 09:24:31,259 | WARN     | pool-validationservice-13-thread-7232 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

2015-07-08 09:24:31,260 | WARN     | pool-validationservice-13-thread-7236 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

2015-07-08 09:24:31,278 | WARN     | pool-validationservice-13-thread-7236 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

2015-07-08 09:24:31,312 | WARN     | pool-validationservice-13-thread-7232 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

2015-07-08 09:24:31,313 | WARN     | pool-validationservice-13-thread-7236 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

2015-07-08 09:24:31,316 | WARN     | pool-validationservice-13-thread-7235 | ReactionServiceImpl            | Scheduling reaction com.vmware.vcloud.backend.reactions.SyncCrosshostWithHostReaction@45b7601b for execution. |

Support has told us to lower vcenter statistics level (currently 3) and to delete the content of inventory tables from vCloud director database but the problem persists after doing that.

Any help?

[acasanovanex]

I discovered that reactions have nothing to do with our performance problems. In this particular case, reactions are triggered for hosts that aren't upgraded to the last vCloud agent version.

We have discovered that when the problem occurs backend activity pools remain in a waiting state much more than usual. In the screenshot you can see the threads tree while performing a reconfigure for 6 VMs (operations belonging to a vApp poweron operation)

Looking at pool-161 closely we see::

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.3:2015-07-15 11:05:42,926 | INFO    | backend-activity-pool-161 | VC20VirtualServer | Invoking reconfigure for vm with valref [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=vm-561093]. ConfigSpec change version = 2015-07-15T09:02:47.2151Z. | vcd=0530717f-2e1c-418f-82f4-fce336295513,task=6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:76f358a3-2e05-49e7-8472-bd030cfdec13

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.5:2015-07-15 11:05:43,449 | INFO    | backend-activity-pool-161 | TaskManager | waitForCompletion invoked on task [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] | vcd=0530717f-2e1c-418f-82f4-fce336295513,task=6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:76f358a3-2e05-49e7-8472-bd030cfdec13

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.5:2015-07-15 11:05:43,449 | DEBUG    | backend-activity-pool-161 | TaskManager | Created wait handle for task [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] | vcd=0530717f-2e1c-418f-82f4-fce336295513,task=6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:76f358a3-2e05-49e7-8472-bd030cfdec13

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.5:2015-07-15 11:05:43,449 | DEBUG    | backend-activity-pool-161 | TaskManager | Task [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] will wait for 900 seconds to receive completion notification before timing out | vcd=0530717f-2e1c-418f-82f4-fce336295513,task=6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:6fdced51-1a9c-4fc6-9f90-c795917ec111 activity=urn:uuid:76f358a3-2e05-49e7-8472-bd030cfdec13

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.4:2015-07-15 11:06:31,603 | INFO    | e80575a-6db7-4760-a63a-b28bdf350c6dListener (9381) | TaskManager | inserted task in db. Task = [vcId = 1e80575a-6db7-4760-a63a-b28bdf350c6d, moref = task-2258528, status = 3, completionDate = Wed Jul 15 11:05:49 CEST 2015, age = 0] |

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.4:2015-07-15 11:07:14,412 | DEBUG    | e80575a-6db7-4760-a63a-b28bdf350c6dListener (9381) | MessageBusAdapter | Publishing TaskUpdate [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] |

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.4:2015-07-15 11:07:14,414 | DEBUG    | ActiveMQ Session Task    | MessageBusAdapter | Received TaskUpdate [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] (JMS message ID ID:nex-vcloud-06-v.ucs.datacenter.nexica.com-56690-1436746707406-2:3:1:1:37686) |

/opt/vmware/vcloud-director/logs/vcloud-container-debug.log.4:2015-07-15 11:07:14,415 | DEBUG    | ActiveMQ Session Task    | TaskManager | Handling completion update from MessageBusAdapter for task [vcId=1e80575a-6db7-4760-a63a-b28bdf350c6d, moref=task-2258528] with state SUCCESS |

Looking at vCenter we know for sure the task lasted for a few seconds only:

Looking at vCenter we know that the task lasted for a few seconds:

TASK_ID	NAME	DESCRIPTIONID	START_TIME	QUEUE_TIME	COMPLETE_TIME	ENTITY_ID	ENTITY_TYPE	ENTITY_NAME
2258528	vim.VirtualMachine.reconfigure	vim.VirtualMachine.reconfigure	15/07/2015 09:05:43	15/07/2015 09:05:43	15/07/2015 09:05:49	561093	0	master (687610d8-b8a7-46df-8e56-730dae5f321c)

But the thread backend-activity-pool-161 doesn’t notice about the task update until 11:07:14, more than 80 seconds later…

The question would be, what can be the cause of the delay between the effective task ending and the “MessageBusAdapter | Publishing TaskUpdate” that occurs at 11:07:14. Some problems with activeMQ maybe?