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:15:49 GMT
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:Nitin.Mehta@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?

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:donal.lafferty@citrix.com]
Sent: Tuesday, July 03, 2012 5:07 AM
To: cloudstack-users@incubator.apache.org
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

Mime
View raw message