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
