Apologies for the delay. The link is https://citrix.sharefile.com/d/s88db2546e7144749
The task in question seems to complete well before the delayed command. -----Original Message----- From: Alena Prokharchyk [mailto:[email protected]] Sent: 03 July 2012 01:19 To: [email protected] Cc: Simon Waterhouse Subject: Re: How to diagnose massive delay in AttachVolume API calls? Not sure about the protocol, I think any public web server would do. On 7/2/12 5:10 PM, "Donal Lafferty" <[email protected]> wrote: >I do have the full log. Is there a protocol on where to post it? > >-----Original Message----- >From: Alena Prokharchyk [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? > >The log shows that the command wasn't sent to the backend server right >away, it was waiting for some other command to be finished (for most of >the commands, we serialize them on the hypervisor side, and don't send >the next one before the previous one is completed): > > >"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 >-a4 >8 >1-34e5-8268-52385b70fd7a","host":"cc-" > > >So we were waiting for 864566426 to complete. I don't see "Sending >command" statement in the log snipped you've provided (this statement >indicates that the command was actually sent to the backend), did you >do grep by jobId? Without this statement it's hard to tell whether we >were waiting for a 864566426 to complete for a long time, or the >createCommand itself took a lot of time to execute on the backend. > >Can you please place the entire management log somewhere online and >send the link to it > > >-Alena. > > >On 7/2/12 4:36 PM, "Donal Lafferty" <[email protected]> wrote: > >>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":"96dcf >>d >>0a- >>c681-48a4-98ac-e135d5f94206","ctxUserId":"2","ctxAccountId":"2","ctxSt >>a >>rtE >>ventId":"1515","signature":"hNSMvlbltQ1I1sBb9h+dkk0gP2I\u003d","apikey" >>:"H >>QZvbMQoIAlXeEp1GSfuDpRJTby3-kg4v3TpBsrJzn-mf0ZCI6VW1_CTSnhdWOM3fAaZUcW >>0 1fJ MQ-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":"266442d >>7 >>-a4 >>81-34e5-8268-52385b70fd7a","host":"cc-svr02.cambourne.cloud.com","path" >>:"/ >>var/nfs/formentera/cs1/primary","port":2049,"type":"NetworkFilesystem" >>} >>,"d >>iskCharacteristics":{"size":1073741824,"tags":[],"type":"DATADISK","name" >>: >>"XD- >>LondonSQ09_IdentityDisk","useLocalStorage":false,"recreatable":false," >>d isk OfferingId":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": >>"Ne >>tworkFilesystem","poolUuid":"266442d7-a481-34e5-8268-52385b70fd7a","vo >>l >>ume >>Folder":"/var/nfs/formentera/cs1/primary","volumePath":"cee97c46-1e3a- >>4 >>0b1 >>-bd13-7110b5801663","volumeName":"XD-LondonSQ09_IdentityDisk","deviceI >>d >>":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 >> > > >
