Single cluster scenario. However, I think Alena's email offers best incite. There is a backlog of commands. Not sure whether the backlog was 12 mins worth of commands, so may also be a scheduler issue.
DL -----Original Message----- From: Nitin Mehta [mailto:[email protected]] Sent: 03 July 2012 00:51 To: [email protected] Cc: Simon Waterhouse Subject: RE: How to diagnose massive delay in AttachVolume API calls? Attach calls can slow if the destination vm is in a different cluster than the data disk. The reason being that the volume is copied from PS -> SS and then from SS to PS. Do you see CopyVolumeCommand in the CS logs ? Generally speaking you can track the command operations till the agent layer using command below (where 1044 is the async job id) grep "job-1044)" /var/log/cloud/management/management-server.log -----Original Message----- From: Donal Lafferty [mailto:[email protected]] Sent: Tuesday, July 03, 2012 5:07 AM To: [email protected] Cc: Simon Waterhouse Subject: How to diagnose massive delay in AttachVolume API calls? I'm using CS 3.0.3 on XenServer (sanibel), and I find that after a moderate number of Attach / Detach calls the API slows down considerable. In the snippet below taken from the management's /var/run/log/cloud/management-server.log, we see about twelve minutes pass between the first agent.transport.Request entry and the follow up. To be sure, the target VM is running a supported guest O/S (Debian 6.0), but I don't see any evidence of activity during until after the delay I notice below (e.g. nothing out of the ordinary in the /var/log/messages file). How would I go about diagnosing the cause of this issue? 2012-07-02 14:22:26,927 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-127:job-459) Executing com.cloud.api.commands.AttachVolumeCmd for job-459 2012-07-02 14:22:26,931 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-16:null) submit async job-459, details: AsyncJobVO {id:459, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 66, cmd: com.cloud.api.commands.AttachVolumeCmd, cmdOriginator: null, cmdInfo: {"id":"4a034979-9082-4f2e-80f1-a2215351afdb","virtualmachineid":"96dcfd0a-c681-48a4-98ac-e135d5f94206","ctxUserId":"2","ctxAccountId":"2","ctxStartEventId":"1515","signature":"hNSMvlbltQ1I1sBb9h+dkk0gP2I\u003d","apikey":"HQZvbMQoIAlXeEp1GSfuDpRJTby3-kg4v3TpBsrJzn-mf0ZCI6VW1_CTSnhdWOM3fAaZUcW01fJMQ-qeqjHHYQ","deviceid":"4"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 86110410570143, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2012-07-02 14:22:27,105 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-127:job-459) Looking for pools in dc: 1 pod:1 cluster:1 2012-07-02 14:22:27,107 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-127:job-459) FirstFitStoragePoolAllocator has 1 pools to check for allocation 2012-07-02 14:22:27,107 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-127:job-459) Checking if storage pool is suitable, name: PrimaryStorage ,poolId: 200 2012-07-02 14:22:27,107 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-127:job-459) Is localStorageAllocationNeeded? false 2012-07-02 14:22:27,107 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-127:job-459) Is storage pool shared? true 2012-07-02 14:22:27,108 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-127:job-459) Attempting to look for pool 200 for storage, totalSize: 1968993992704, usedBytes: 116645691392, usedPct: 0.05924126321574583, disable threshold: 0.85 2012-07-02 14:22:27,111 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-127:job-459) Attempting to look for pool 200 for storage, maxSize : 3937987985408, totalAllocatedSize : 369253742592, askingSize : 1073741824, allocated disable threshold: 0.85 2012-07-02 14:22:27,111 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-127:job-459) FirstFitStoragePoolAllocator returning 1 suitable storage pools 2012-07-02 14:22:27,111 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-127:job-459) Trying to create Vol[66|vm=null|DATADISK] on Pool[200|NetworkFilesystem] 2012-07-02 14:22:27,117 DEBUG [agent.transport.Request] (Job-Executor-127:job-459) Seq 1-864566441: Waiting for Seq 864566426 Scheduling: { Cmd , MgmtId: 86110410570143, via: 1, Ver: v1, Flags: 100111, [{"storage.CreateCommand":{"volId":66,"pool":{"id":200,"uuid":"266442d7-a481-34e5-8268-52385b70fd7a","host":"cc-svr02.cambourne.cloud.com","path":"/var/nfs/formentera/cs1/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":1073741824,"tags":[],"type":"DATADISK","name":"XD- LondonSQ09_IdentityDisk","useLocalStorage":false,"recreatable":false,"diskOfferingId":6,"volumeId":66,"hyperType":"XenServer"},"wait":0}}] } 2012-07-02 14:36:07,250 DEBUG [agent.transport.Request] (Job-Executor-127:job-459) Seq 1-864566441: Received: { Ans: , MgmtId: 86110410570143, via: 1, Ver: v1, Flags: 110, { CreateAnswer } } 2012-07-02 14:36:07,346 DEBUG [agent.transport.Request] (Job-Executor-127:job-459) Seq 1-864566482: Waiting for Seq 864566442 Scheduling: { Cmd , MgmtId: 86110410570143, via: 1, Ver: v1, Flags: 100111, [{"AttachVolumeCommand":{"attach":true,"vmName":"i-2-32-VM","pooltype":"NetworkFilesystem","poolUuid":"266442d7-a481-34e5-8268-52385b70fd7a","volumeFolder":"/var/nfs/formentera/cs1/primary","volumePath":"cee97c46-1e3a-40b1-bd13-7110b5801663","volumeName":"XD-LondonSQ09_IdentityDisk","deviceId":4,"wait":0}}] } 2012-07-02 14:36:09,848 DEBUG [agent.transport.Request] (Job-Executor-127:job-459) Seq 1-864566482: Received: { Ans: , MgmtId: 86110410570143, via: 1, Ver: v1, Flags: 110, { AttachVolumeAnswer } } 2012-07-02 14:36:10,077 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-127:job-459) Complete async job-459, jobStatus: 1, resultCode: 0, result: com.cloud.api.response.VolumeResponse@9b3bbb0 2012-07-02 14:36:10,129 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-127:job-459) Done executing com.cloud.api.commands.AttachVolumeCmd for job-459 2012-07-02 14:36:10,735 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-10:null) Async job-459 completed
