cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Donal Lafferty <donal.laffe...@citrix.com>
Subject RE: How to diagnose massive delay in AttachVolume API calls?
Date Tue, 03 Jul 2012 00:42:49 GMT
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:Alena.Prokharchyk@citrix.com] 
Sent: 03 July 2012 01:19
To: cloudstack-users@incubator.apache.org
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" <donal.lafferty@citrix.com> wrote:

>I do have the full log.  Is there a protocol on where to post it?
>
>-----Original Message-----
>From: Alena Prokharchyk [mailto:Alena.Prokharchyk@citrix.com]
>Sent: 03 July 2012 00:51
>To: cloudstack-users@incubator.apache.org
>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" <donal.lafferty@citrix.com> 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
>>
>
>
>



Mime
View raw message