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:10:46 GMT
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-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":"96dcfd
>0a- 
>c681-48a4-98ac-e135d5f94206","ctxUserId":"2","ctxAccountId":"2","ctxSta
>rtE 
>ventId":"1515","signature":"hNSMvlbltQ1I1sBb9h+dkk0gP2I\u003d","apikey"
>:"H 
>QZvbMQoIAlXeEp1GSfuDpRJTby3-kg4v3TpBsrJzn-mf0ZCI6VW1_CTSnhdWOM3fAaZUcW0
>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":"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,"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","vol
>ume
>Folder":"/var/nfs/formentera/cs1/primary","volumePath":"cee97c46-1e3a-4
>0b1
>-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