cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alena Prokharchyk <Alena.Prokharc...@citrix.com>
Subject Re: How to diagnose massive delay in AttachVolume API calls?
Date Mon, 02 Jul 2012 23:51:17 GMT
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-a48
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":"96dcfd0a-
>c681-48a4-98ac-e135d5f94206","ctxUserId":"2","ctxAccountId":"2","ctxStartE
>ventId":"1515","signature":"hNSMvlbltQ1I1sBb9h+dkk0gP2I\u003d","apikey":"H
>QZvbMQoIAlXeEp1GSfuDpRJTby3-kg4v3TpBsrJzn-mf0ZCI6VW1_CTSnhdWOM3fAaZUcW01fJ
>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":"266442d7-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,"disk
>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","volume
>Folder":"/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
>



Mime
View raw message