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 Tue, 03 Jul 2012 01:21:44 GMT
There was a sequence of commands waiting for each other. I analyzed the
log, and looks like StopVM command takes about 6 mins to complete on the
backend; and your attachVolume commands were waiting for 2 Stop commands
to complete (about 14 mins per both). What hypervisor do you use? If it's
xen, then Xen developers should help you to analyze why it took so long to
complete the commands on the backend.


Here is the commands queue:

Command4->Command3->Command2->Command1


Command4 Seq 1-864566441 (attachVoluem command, jobId=459). This command
is waiting on command 3 to finish
========================

Scheduled:

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: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-a48
1-34e5-8268-52385b70fd7a","host":"cc-svr02.cambourne.cloud.com","path":"/va
r/nfs/formentera/cs1/primary","port":2049,"type":"NetworkFilesystem"},"disk
Characteristics":{"size":1073741824,"tags":[],"type":"DATADISK","name":"XD-
LondonSQ09_IdentityDisk","useLocalStorage":false,"recreatable":false,"diskO
fferingId":6,"volumeId":66,"hyperType":"XenServer"},"wait":0}}] }

The command is waiting for all the commands in the Agent queue ahead to
finish (the current seq is 864566426, but there are few more ahead as well)


The command is sent at 14:36:

2012-07-02 14:36:06,423 DEBUG [agent.manager.AgentAttache]
(DirectAgent-412:null) Seq 1-864566441: Sending now. is current sequence.



Command3 - Seq 864566426 (attach command, job-454). Command3 is waiting on
Command2 to finish:
===========================================================================
=======================
2012-07-02 14:19:07,162 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-122:job-454) Executing
com.cloud.api.commands.AttachVolumeCmd for job-454.

ŠŠŠŠ
2012-07-02 14:19:07,298 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-122:job-454) Trying to create Vol[65|vm=null|DATADISK] on
Pool[200|NetworkFilesystem]
2012-07-02 14:19:07,306 DEBUG [agent.transport.Request]
(Job-Executor-122:job-454) Seq 1-864566426: Waiting for Seq 864566422
Scheduling: { Cmd , MgmtId: 86110410570143, via: 1, Ver: v1, Flags:
100111,
[{"storage.CreateCommand":{"volId":65,"pool":{"id":200,"uuid":"266442d7-a48
1-34e5-8268-52385b70fd7a","host":"cc-svr02.cambourne.cloud.com","path":"/va
r/nfs/formentera/cs1/primary","port":2049,"type":"NetworkFilesystem"},"disk
Characteristics":{"size":1073741824,"tags":[],"type":"DATADISK","name":"XD-
LondonSQ10_IdentityDisk","useLocalStorage":false,"recreatable":false,"diskO
fferingId":6,"volumeId":65,"hyperType":"XenServer"},"wait":0}}] }
2012-07-02 14:22:30,675 DEBUG [agent.transport.Request]
(Job-Executor-122:job-454) Seq 1-864566426: Received: { Ans: , MgmtId:
86110410570143, via: 1, Ver: v1, Flags: 110, { CreateAnswer } }
2012-07-02 14:22:30,738 DEBUG [agent.transport.Request]
(Job-Executor-122:job-454) Seq 1-864566442: Waiting for Seq 864566438
Scheduling: { Cmd , MgmtId: 86110410570143, via: 1, Ver: v1, Flags:
100111,
[{"AttachVolumeCommand":{"attach":true,"vmName":"i-2-32-VM","pooltype":"Net
workFilesystem","poolUuid":"266442d7-a481-34e5-8268-52385b70fd7a","volumeFo
lder":"/var/nfs/formentera/cs1/primary","volumePath":"8dc370f6-df56-45ce-84
f5-d552b3fd4987","volumeName":"XD-LondonSQ10_IdentityDisk","deviceId":2,"wa
it":0}}] }
2012-07-02 14:36:08,492 DEBUG [agent.transport.Request]
(Job-Executor-122:job-454) Seq 1-864566442: Received: { Ans: , MgmtId:
86110410570143, via: 1, Ver: v1, Flags: 110, { AttachVolumeAnswer } }
2012-07-02 14:36:08,585 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-122:job-454) Complete async job-454, jobStatus: 1,
resultCode: 0, result: com.cloud.api.response.VolumeResponse@5e0170b6
2012-07-02 14:36:08,628 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-122:job-454) Done executing
com.cloud.api.commands.AttachVolumeCmd for job-454
2012-07-02 14:36:08,736 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-6:null) Async job-454 completed



Command2 Seq 1-864566439, Stop command. Took 6 mins to complete on the
backend + it was waiting on Command1 to finish:
===========================================================================
==========
2012-07-02 14:22:21,591 DEBUG [agent.transport.Request]
(Job-Executor-124:job-456) Seq 1-864566439: Waiting for Seq 864566425
Scheduling:  { Cmd , MgmtId: 86110410570143, via: 1, Ver: v1, Flags:
100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-38-VM","wait":0}}] }
........
2012-07-02 14:28:35,911 DEBUG [agent.transport.Request]
(DirectAgent-421:null) Seq 1-864566439: Executing:  { Cmd , MgmtId:
86110410570143, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-38-VM","wait":0}}] }
2012-07-02 14:28:35,912 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-112:null) Seq 1-864566439: Executing request
......................
2012-07-02 14:34:12,183 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-112:null) Seq 1-864566439: Response Received:


Command1 Seq 1-864566438, Stop command, took 6 mins to complete on the
backend

==============================================================

2012-07-02 14:22:30,677 DEBUG [agent.transport.Request]
(DirectAgent-211:null) Seq 1-864566438: Executing: { Cmd , MgmtId:
86110410570143, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-39-VM","wait":0}}] }
2012-07-02 14:22:30,677 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-421:null) Seq 1-864566438: Executing request
.....................
2012-07-02 14:28:35,905 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-421:null) Seq 1-864566438: Response Received:




-Alena.


On 7/2/12 5:42 PM, "Donal Lafferty" <donal.lafferty@citrix.com> wrote:

>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