Re: Long delay in listDomains API response

[Cloud List]

Thanks Sergey, appreciate your reply. Points noted.

Cheers.

On Mon, Nov 7, 2016 at 10:44 AM, Sergey Levitskiy <
sergey.levits...@autodesk.com> wrote:

> What essentially happens here that for each domain, you have access with
> your key, ACS executes 12 queries to get domain limits.  Even if such query
> for each resource limit takes 0.03 sec it translates into 0.4 sec for each
> domain. If you have more than few domains, you will see rather lengthy
> total execution of listDomains in spite of some parallel execution of such
> queries. This is apparently far from optimal but I don’t see if it can be
> improved by optimizing MySQL alone.   I looked through the ACS code and
> there is a way to improve this big time since all resource limits are
> already in domain_view . We will try to fix it soon for 4.9-4.10 versions.
> It usually takes at least 2-3 weeks before the code will be reviewed and
> committed. Until then I suggest to increase any client timeouts accordingly.
>
> Thanks,
> Sergey
>
>
> On 11/6/16, 5:52 PM, "Cloud List"  wrote:
>
> Hi Wei,
>
> In addition, can you also advice any specific tweak or tuning of the
> CloudStack management server and MySQL database's configurations to
> improve
> the time it takes to perform the listDomains API query and result? We
> have
> tried CloudStack and MySQL tunings as per below documentations and it
> doesn't seem to improve the listDomains API query time.
>
> http://docs.cloudstack.apache.org/projects/cloudstack-
> administration/en/4.8/tuning.html
> http://events.linuxfoundation.org/sites/events/files/slides/
> CloudSTack-Tuning-Collab-2015.pdf
> https://www.percona.com/blog/2014/01/28/10-mysql-
> performance-tuning-settings-after-installation/
> https://www.percona.com/blog/2012/01/06/mysql-high-number-
> connections-per-secon/
>
> Any advice on this is greatly appreciated.
>
> Looking forward to your reply, thank you.
>
> Cheers.
>
>
>
> On Mon, Nov 7, 2016 at 2:35 AM, Cloud List 
> wrote:
>
> > Hi Wei,
> >
> > Thanks for your reply. Is it possible for us to remove the resource
> > limitation feature -- any global settings that we can set to turn
> this off?
> > If not, would you be able to let us know where on the source code
> this is
> > being set, so that we can try changing it and recompile ACS to turn
> off the
> > feature?
> >
> > If it's possible, how would be the impact to CloudStack operations in
> > general? May I know what was the original purpose the limitation is
> being
> > put in the first place?
> >
> > Thanks for the workaround recommendation -- will forward to our
> > application vendor to see if the app can be fine-tuned following your
> > recommendation.
> >
> > Looking forward to your reply, thank you.
> >
> > Cheers.
> >
> > On Mon, Nov 7, 2016 at 12:42 AM, Wei ZHOU 
> wrote:
> >
> >> I cannot say it is unnecessary or not for now.
> >> There are indeed many db connections when get resource
> limtiation/count
> >> of domains.
> >>
> >> A workaound is (1) listDomainChildren gets id of domain and
> sub-domains,
> >> then (2) listDomains with specified id.
> >>
> >> -Wei
> >>
> >>
> >>
> >> 2016-11-06 17:23 GMT+01:00 Cloud List :
> >>
> >>> Hi Sergey,
> >>>
> >>> Thanks for your reply. The grep result is a bit long, total 64K
> lines,
> >>> so I have uploaded it here:
> >>>
> >>> https://dl.dropboxusercontent.com/u/24788636/ctx-3f3ff343.txt
> >>>
> >>> It seems there are a lot of unnecessary creating and closing of
> >>> connections to the DB, causing the delay?
> >>>
> >>> Looking forward to your reply, thank you.
> >>>
> >>> Cheers.
> >>>
> >>>
> >>> On Sun, Nov 6, 2016 at 11:30 PM, Sergey Levitskiy <
> >>> sergey.levits...@autodesk.com> wrote:
> >>>
>  Can you grep for this line ‘ctx-3f3ff343’ in your log and post it
> here?
> 
> 
>  On 11/5/16, 11:01 PM, "Cloud List"  wrote:
> 
>  Dear all,
> 
>  After researching further, I found out that our problem is
> exactly
>  the one
>  reported on this JIRA bug:
> 
>  https://issues.apache.org/jira/browse/CLOUDSTACK-9405
> 
>  I am cc-ing dsclose and Wei Zhou on this email. Anyone know if
>  there's any
>  resolution to the above problem/bug?
> 
>  On the bug report, Wei Zhou mentioned that he added domain
> level
>  resource
>  limitation, may I know if this limitation is configurable? I
> can't
>  find it
>  on the Global Settings.
> 
>  Looking forward to your reply, thank you.
> 

Re: Long delay in listDomains API response

[Sergey Levitskiy]

What essentially happens here that for each domain, you have access with your 
key, ACS executes 12 queries to get domain limits.  Even if such query for each 
resource limit takes 0.03 sec it translates into 0.4 sec for each domain. If 
you have more than few domains, you will see rather lengthy total execution of 
listDomains in spite of some parallel execution of such queries. This is 
apparently far from optimal but I don’t see if it can be improved by optimizing 
MySQL alone.   I looked through the ACS code and there is a way to improve this 
big time since all resource limits are already in domain_view . We will try to 
fix it soon for 4.9-4.10 versions. It usually takes at least 2-3 weeks before 
the code will be reviewed and committed. Until then I suggest to increase any 
client timeouts accordingly.

Thanks,
Sergey


On 11/6/16, 5:52 PM, "Cloud List"  wrote:

Hi Wei,

In addition, can you also advice any specific tweak or tuning of the
CloudStack management server and MySQL database's configurations to improve
the time it takes to perform the listDomains API query and result? We have
tried CloudStack and MySQL tunings as per below documentations and it
doesn't seem to improve the listDomains API query time.


http://docs.cloudstack.apache.org/projects/cloudstack-administration/en/4.8/tuning.html

http://events.linuxfoundation.org/sites/events/files/slides/CloudSTack-Tuning-Collab-2015.pdf

https://www.percona.com/blog/2014/01/28/10-mysql-performance-tuning-settings-after-installation/

https://www.percona.com/blog/2012/01/06/mysql-high-number-connections-per-secon/

Any advice on this is greatly appreciated.

Looking forward to your reply, thank you.

Cheers.



On Mon, Nov 7, 2016 at 2:35 AM, Cloud List  wrote:

> Hi Wei,
>
> Thanks for your reply. Is it possible for us to remove the resource
> limitation feature -- any global settings that we can set to turn this 
off?
> If not, would you be able to let us know where on the source code this is
> being set, so that we can try changing it and recompile ACS to turn off 
the
> feature?
>
> If it's possible, how would be the impact to CloudStack operations in
> general? May I know what was the original purpose the limitation is being
> put in the first place?
>
> Thanks for the workaround recommendation -- will forward to our
> application vendor to see if the app can be fine-tuned following your
> recommendation.
>
> Looking forward to your reply, thank you.
>
> Cheers.
>
> On Mon, Nov 7, 2016 at 12:42 AM, Wei ZHOU  wrote:
>
>> I cannot say it is unnecessary or not for now.
>> There are indeed many db connections when get resource limtiation/count
>> of domains.
>>
>> A workaound is (1) listDomainChildren gets id of domain and sub-domains,
>> then (2) listDomains with specified id.
>>
>> -Wei
>>
>>
>>
>> 2016-11-06 17:23 GMT+01:00 Cloud List :
>>
>>> Hi Sergey,
>>>
>>> Thanks for your reply. The grep result is a bit long, total 64K lines,
>>> so I have uploaded it here:
>>>
>>> https://dl.dropboxusercontent.com/u/24788636/ctx-3f3ff343.txt
>>>
>>> It seems there are a lot of unnecessary creating and closing of
>>> connections to the DB, causing the delay?
>>>
>>> Looking forward to your reply, thank you.
>>>
>>> Cheers.
>>>
>>>
>>> On Sun, Nov 6, 2016 at 11:30 PM, Sergey Levitskiy <
>>> sergey.levits...@autodesk.com> wrote:
>>>
 Can you grep for this line ‘ctx-3f3ff343’ in your log and post it here?


 On 11/5/16, 11:01 PM, "Cloud List"  wrote:

 Dear all,

 After researching further, I found out that our problem is exactly
 the one
 reported on this JIRA bug:

 https://issues.apache.org/jira/browse/CLOUDSTACK-9405

 I am cc-ing dsclose and Wei Zhou on this email. Anyone know if
 there's any
 resolution to the above problem/bug?

 On the bug report, Wei Zhou mentioned that he added domain level
 resource
 limitation, may I know if this limitation is configurable? I can't
 find it
 on the Global Settings.

 Looking forward to your reply, thank you.

 Cheers.


 On Sun, Nov 6, 2016 at 10:30 AM, Cloud List 
 wrote:

 > Thanks Sergey for your assistance.
 >
 > I have enabled the TRACE logs as requested. After the listDomains
 API
 > call, I see a lot of DB connections being created 

Re: Long delay in listDomains API response

[Cloud List]

Hi Wei,

Thanks for your reply. Is it possible for us to remove the resource
limitation feature -- any global settings that we can set to turn this off?
If not, would you be able to let us know where on the source code this is
being set, so that we can try changing it and recompile ACS to turn off the
feature?

If it's possible, how would be the impact to CloudStack operations in
general? May I know what was the original purpose the limitation is being
put in the first place?

Thanks for the workaround recommendation -- will forward to our application
vendor to see if the app can be fine-tuned following your recommendation.

Looking forward to your reply, thank you.

Cheers.

On Mon, Nov 7, 2016 at 12:42 AM, Wei ZHOU  wrote:

> I cannot say it is unnecessary or not for now.
> There are indeed many db connections when get resource limtiation/count of
> domains.
>
> A workaound is (1) listDomainChildren gets id of domain and sub-domains,
> then (2) listDomains with specified id.
>
> -Wei
>
>
>
> 2016-11-06 17:23 GMT+01:00 Cloud List :
>
>> Hi Sergey,
>>
>> Thanks for your reply. The grep result is a bit long, total 64K lines, so
>> I have uploaded it here:
>>
>> https://dl.dropboxusercontent.com/u/24788636/ctx-3f3ff343.txt
>>
>> It seems there are a lot of unnecessary creating and closing of
>> connections to the DB, causing the delay?
>>
>> Looking forward to your reply, thank you.
>>
>> Cheers.
>>
>>
>> On Sun, Nov 6, 2016 at 11:30 PM, Sergey Levitskiy <
>> sergey.levits...@autodesk.com> wrote:
>>
>>> Can you grep for this line ‘ctx-3f3ff343’ in your log and post it here?
>>>
>>>
>>> On 11/5/16, 11:01 PM, "Cloud List"  wrote:
>>>
>>> Dear all,
>>>
>>> After researching further, I found out that our problem is exactly
>>> the one
>>> reported on this JIRA bug:
>>>
>>> https://issues.apache.org/jira/browse/CLOUDSTACK-9405
>>>
>>> I am cc-ing dsclose and Wei Zhou on this email. Anyone know if
>>> there's any
>>> resolution to the above problem/bug?
>>>
>>> On the bug report, Wei Zhou mentioned that he added domain level
>>> resource
>>> limitation, may I know if this limitation is configurable? I can't
>>> find it
>>> on the Global Settings.
>>>
>>> Looking forward to your reply, thank you.
>>>
>>> Cheers.
>>>
>>>
>>> On Sun, Nov 6, 2016 at 10:30 AM, Cloud List 
>>> wrote:
>>>
>>> > Thanks Sergey for your assistance.
>>> >
>>> > I have enabled the TRACE logs as requested. After the listDomains
>>> API
>>> > call, I see a lot of DB connections being created to the database,
>>> > preparing SELECT statements and then immediately being closed
>>> thereafter.
>>> > This happens many many times in the loop in the course of 10-15
>>> seconds.
>>> > For example:
>>> >
>>> > Creating a DB connection with  no txn
>>> > Preparing: SELECT
>>> > Closing: com.mysql.jdbc.PreparedStatement
>>> > Closing DB connection
>>> >
>>> > The above continues in a loop for 10-15 seconds, sometimes more.
>>> Is it
>>> > normal? Could it be something wrong during the database schema
>>> upgrade when
>>> > I upgraded from 4.2 to 4.8?
>>> >
>>> > Excerpts of the TRACE logs are below. Any advice on how I can
>>> resolve the
>>> > problem is highly appreciated.
>>> >
>>> > ===
>>> > 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
>>> > (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X
>>> -- GET
>>> > apikey==listDomains=json=
>>> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
>>> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
>>> current
>>> > transaction: http-8080-10 : http-8080-10,
>>> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
>>> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
>>> current
>>> > transaction: http-8080-10 : http-8080-10,
>>> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement]
>>> (StatsCollector-2:ctx-293a2a9e)
>>> > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedSt
>>> atement@1bda5f56:
>>> > SELECT vm_instance.id, vm_instance.name, vm_instance.vnc_password,
>>> > vm_instance.proxy_id, vm_instance.proxy_assign_time,
>>> vm_instance.state,
>>> > vm_instance.private_ip_address, vm_instance.instance_name,
>>> > vm_instance.vm_template_id, vm_instance.guest_os_id,
>>> vm_instance.host_id,
>>> > vm_instance.last_host_id, vm_instance.pod_id,
>>> vm_instance.private_mac_address,
>>> > vm_instance.data_center_id, vm_instance.vm_type,
>>> vm_instance.ha_enabled,
>>> > vm_instance.display_vm, vm_instance.limit_cpu_use,
>>> > vm_instance.update_count, vm_instance.created, vm_instance.removed,
>>> > vm_instance.update_time, vm_instance.domain_id,
>>> vm_instance.account_id,
>>> > vm_instance.user_id, vm_instance.service_offering_id,
>>> > 

Re: Long delay in listDomains API response

[Wei ZHOU]

I cannot say it is unnecessary or not for now.
There are indeed many db connections when get resource limtiation/count of
domains.

A workaound is (1) listDomainChildren gets id of domain and sub-domains,
then (2) listDomains with specified id.

-Wei



2016-11-06 17:23 GMT+01:00 Cloud List :

> Hi Sergey,
>
> Thanks for your reply. The grep result is a bit long, total 64K lines, so
> I have uploaded it here:
>
> https://dl.dropboxusercontent.com/u/24788636/ctx-3f3ff343.txt
>
> It seems there are a lot of unnecessary creating and closing of
> connections to the DB, causing the delay?
>
> Looking forward to your reply, thank you.
>
> Cheers.
>
>
> On Sun, Nov 6, 2016 at 11:30 PM, Sergey Levitskiy <
> sergey.levits...@autodesk.com> wrote:
>
>> Can you grep for this line ‘ctx-3f3ff343’ in your log and post it here?
>>
>>
>> On 11/5/16, 11:01 PM, "Cloud List"  wrote:
>>
>> Dear all,
>>
>> After researching further, I found out that our problem is exactly
>> the one
>> reported on this JIRA bug:
>>
>> https://issues.apache.org/jira/browse/CLOUDSTACK-9405
>>
>> I am cc-ing dsclose and Wei Zhou on this email. Anyone know if
>> there's any
>> resolution to the above problem/bug?
>>
>> On the bug report, Wei Zhou mentioned that he added domain level
>> resource
>> limitation, may I know if this limitation is configurable? I can't
>> find it
>> on the Global Settings.
>>
>> Looking forward to your reply, thank you.
>>
>> Cheers.
>>
>>
>> On Sun, Nov 6, 2016 at 10:30 AM, Cloud List 
>> wrote:
>>
>> > Thanks Sergey for your assistance.
>> >
>> > I have enabled the TRACE logs as requested. After the listDomains
>> API
>> > call, I see a lot of DB connections being created to the database,
>> > preparing SELECT statements and then immediately being closed
>> thereafter.
>> > This happens many many times in the loop in the course of 10-15
>> seconds.
>> > For example:
>> >
>> > Creating a DB connection with  no txn
>> > Preparing: SELECT
>> > Closing: com.mysql.jdbc.PreparedStatement
>> > Closing DB connection
>> >
>> > The above continues in a loop for 10-15 seconds, sometimes more. Is
>> it
>> > normal? Could it be something wrong during the database schema
>> upgrade when
>> > I upgraded from 4.2 to 4.8?
>> >
>> > Excerpts of the TRACE logs are below. Any advice on how I can
>> resolve the
>> > problem is highly appreciated.
>> >
>> > ===
>> > 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
>> > (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X
>> -- GET
>> > apikey==listDomains=json=
>> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
>> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
>> current
>> > transaction: http-8080-10 : http-8080-10,
>> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
>> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
>> current
>> > transaction: http-8080-10 : http-8080-10,
>> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement]
>> (StatsCollector-2:ctx-293a2a9e)
>> > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedSt
>> atement@1bda5f56:
>> > SELECT vm_instance.id, vm_instance.name, vm_instance.vnc_password,
>> > vm_instance.proxy_id, vm_instance.proxy_assign_time,
>> vm_instance.state,
>> > vm_instance.private_ip_address, vm_instance.instance_name,
>> > vm_instance.vm_template_id, vm_instance.guest_os_id,
>> vm_instance.host_id,
>> > vm_instance.last_host_id, vm_instance.pod_id,
>> vm_instance.private_mac_address,
>> > vm_instance.data_center_id, vm_instance.vm_type,
>> vm_instance.ha_enabled,
>> > vm_instance.display_vm, vm_instance.limit_cpu_use,
>> > vm_instance.update_count, vm_instance.created, vm_instance.removed,
>> > vm_instance.update_time, vm_instance.domain_id,
>> vm_instance.account_id,
>> > vm_instance.user_id, vm_instance.service_offering_id,
>> > vm_instance.reservation_id, vm_instance.hypervisor_type,
>> > vm_instance.dynamically_scalable, vm_instance.uuid,
>> > vm_instance.disk_offering_id, vm_instance.power_state,
>> > vm_instance.power_state_update_time, vm_instance.power_state_update
>> _count,
>> > vm_instance.power_host, user_vm.iso_id, user_vm.user_data,
>> > user_vm.display_name, user_vm.update_parameters FROM user_vm INNER
>> JOIN
>> > vm_instance ON user_vm.id=vm_instance.id  WHERE
>> vm_instance.type='User'
>> > AND user_vm.id = 4088  AND vm_instance.removed IS NULL
>> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Connection]
>> (StatsCollector-2:ctx-293a2a9e)
>> > (logid:725b6dd7) Closing DB connection: dbconn1208177431
>> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Transaction]
>> > (StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Using current
>> > 

Re: Long delay in listDomains API response

[Cloud List]

Hi Sergey,

Thanks for your reply. The grep result is a bit long, total 64K lines, so I
have uploaded it here:

https://dl.dropboxusercontent.com/u/24788636/ctx-3f3ff343.txt

It seems there are a lot of unnecessary creating and closing of connections
to the DB, causing the delay?

Looking forward to your reply, thank you.

Cheers.


On Sun, Nov 6, 2016 at 11:30 PM, Sergey Levitskiy <
sergey.levits...@autodesk.com> wrote:

> Can you grep for this line ‘ctx-3f3ff343’ in your log and post it here?
>
>
> On 11/5/16, 11:01 PM, "Cloud List"  wrote:
>
> Dear all,
>
> After researching further, I found out that our problem is exactly the
> one
> reported on this JIRA bug:
>
> https://issues.apache.org/jira/browse/CLOUDSTACK-9405
>
> I am cc-ing dsclose and Wei Zhou on this email. Anyone know if there's
> any
> resolution to the above problem/bug?
>
> On the bug report, Wei Zhou mentioned that he added domain level
> resource
> limitation, may I know if this limitation is configurable? I can't
> find it
> on the Global Settings.
>
> Looking forward to your reply, thank you.
>
> Cheers.
>
>
> On Sun, Nov 6, 2016 at 10:30 AM, Cloud List 
> wrote:
>
> > Thanks Sergey for your assistance.
> >
> > I have enabled the TRACE logs as requested. After the listDomains API
> > call, I see a lot of DB connections being created to the database,
> > preparing SELECT statements and then immediately being closed
> thereafter.
> > This happens many many times in the loop in the course of 10-15
> seconds.
> > For example:
> >
> > Creating a DB connection with  no txn
> > Preparing: SELECT
> > Closing: com.mysql.jdbc.PreparedStatement
> > Closing DB connection
> >
> > The above continues in a loop for 10-15 seconds, sometimes more. Is
> it
> > normal? Could it be something wrong during the database schema
> upgrade when
> > I upgraded from 4.2 to 4.8?
> >
> > Excerpts of the TRACE logs are below. Any advice on how I can
> resolve the
> > problem is highly appreciated.
> >
> > ===
> > 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
> > (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X --
> GET
> > apikey==listDomains=json=
> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
> current
> > transaction: http-8080-10 : http-8080-10,
> > 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using
> current
> > transaction: http-8080-10 : http-8080-10,
> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement]
> (StatsCollector-2:ctx-293a2a9e)
> > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedStatement@
> 1bda5f56:
> > SELECT vm_instance.id, vm_instance.name, vm_instance.vnc_password,
> > vm_instance.proxy_id, vm_instance.proxy_assign_time,
> vm_instance.state,
> > vm_instance.private_ip_address, vm_instance.instance_name,
> > vm_instance.vm_template_id, vm_instance.guest_os_id,
> vm_instance.host_id,
> > vm_instance.last_host_id, vm_instance.pod_id,
> vm_instance.private_mac_address,
> > vm_instance.data_center_id, vm_instance.vm_type,
> vm_instance.ha_enabled,
> > vm_instance.display_vm, vm_instance.limit_cpu_use,
> > vm_instance.update_count, vm_instance.created, vm_instance.removed,
> > vm_instance.update_time, vm_instance.domain_id,
> vm_instance.account_id,
> > vm_instance.user_id, vm_instance.service_offering_id,
> > vm_instance.reservation_id, vm_instance.hypervisor_type,
> > vm_instance.dynamically_scalable, vm_instance.uuid,
> > vm_instance.disk_offering_id, vm_instance.power_state,
> > vm_instance.power_state_update_time, vm_instance.power_state_
> update_count,
> > vm_instance.power_host, user_vm.iso_id, user_vm.user_data,
> > user_vm.display_name, user_vm.update_parameters FROM user_vm INNER
> JOIN
> > vm_instance ON user_vm.id=vm_instance.id  WHERE
> vm_instance.type='User'
> > AND user_vm.id = 4088  AND vm_instance.removed IS NULL
> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Connection]
> (StatsCollector-2:ctx-293a2a9e)
> > (logid:725b6dd7) Closing DB connection: dbconn1208177431
> > 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Transaction]
> > (StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Using current
> > transaction: StatsCollector-2 : StatsCollector-2,
> > 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection]
> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Creating a
> DB
> > connection with  no txn:  for 0: dbconn1379204259. Stack:
> > -TransactionLegacy.prepareStatement:457-TransactionLegacy.
> > prepareAutoCloseStatement:450-AccountDaoImpl.
> findUserAccountByApiKey:129-
> > 

Re: Long delay in listDomains API response

[Sergey Levitskiy]

Can you grep for this line ‘ctx-3f3ff343’ in your log and post it here?


On 11/5/16, 11:01 PM, "Cloud List"  wrote:

Dear all,

After researching further, I found out that our problem is exactly the one
reported on this JIRA bug:

https://issues.apache.org/jira/browse/CLOUDSTACK-9405

I am cc-ing dsclose and Wei Zhou on this email. Anyone know if there's any
resolution to the above problem/bug?

On the bug report, Wei Zhou mentioned that he added domain level resource
limitation, may I know if this limitation is configurable? I can't find it
on the Global Settings.

Looking forward to your reply, thank you.

Cheers.


On Sun, Nov 6, 2016 at 10:30 AM, Cloud List  wrote:

> Thanks Sergey for your assistance.
>
> I have enabled the TRACE logs as requested. After the listDomains API
> call, I see a lot of DB connections being created to the database,
> preparing SELECT statements and then immediately being closed thereafter.
> This happens many many times in the loop in the course of 10-15 seconds.
> For example:
>
> Creating a DB connection with  no txn
> Preparing: SELECT
> Closing: com.mysql.jdbc.PreparedStatement
> Closing DB connection
>
> The above continues in a loop for 10-15 seconds, sometimes more. Is it
> normal? Could it be something wrong during the database schema upgrade 
when
> I upgraded from 4.2 to 4.8?
>
> Excerpts of the TRACE logs are below. Any advice on how I can resolve the
> problem is highly appreciated.
>
> ===
> 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
> (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X -- GET
> apikey==listDomains=json=
> 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
> transaction: http-8080-10 : http-8080-10,
> 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
> transaction: http-8080-10 : http-8080-10,
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement] 
(StatsCollector-2:ctx-293a2a9e)
> (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedStatement@1bda5f56:
> SELECT vm_instance.id, vm_instance.name, vm_instance.vnc_password,
> vm_instance.proxy_id, vm_instance.proxy_assign_time, vm_instance.state,
> vm_instance.private_ip_address, vm_instance.instance_name,
> vm_instance.vm_template_id, vm_instance.guest_os_id, vm_instance.host_id,
> vm_instance.last_host_id, vm_instance.pod_id, 
vm_instance.private_mac_address,
> vm_instance.data_center_id, vm_instance.vm_type, vm_instance.ha_enabled,
> vm_instance.display_vm, vm_instance.limit_cpu_use,
> vm_instance.update_count, vm_instance.created, vm_instance.removed,
> vm_instance.update_time, vm_instance.domain_id, vm_instance.account_id,
> vm_instance.user_id, vm_instance.service_offering_id,
> vm_instance.reservation_id, vm_instance.hypervisor_type,
> vm_instance.dynamically_scalable, vm_instance.uuid,
> vm_instance.disk_offering_id, vm_instance.power_state,
> vm_instance.power_state_update_time, vm_instance.power_state_update_count,
> vm_instance.power_host, user_vm.iso_id, user_vm.user_data,
> user_vm.display_name, user_vm.update_parameters FROM user_vm INNER JOIN
> vm_instance ON user_vm.id=vm_instance.id  WHERE vm_instance.type='User'
> AND user_vm.id = 4088  AND vm_instance.removed IS NULL
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Connection] 
(StatsCollector-2:ctx-293a2a9e)
> (logid:725b6dd7) Closing DB connection: dbconn1208177431
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Transaction]
> (StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Using current
> transaction: StatsCollector-2 : StatsCollector-2,
> 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Creating a DB
> connection with  no txn:  for 0: dbconn1379204259. Stack:
> -TransactionLegacy.prepareStatement:457-TransactionLegacy.
> prepareAutoCloseStatement:450-AccountDaoImpl.findUserAccountByApiKey:129-
> GeneratedMethodAccessor234.invoke:-1-DelegatingMethodAccessorImpl.
> invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingReflection:317-
> ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMethodInvocation.
> proceed:150-TransactionContextInterceptor.invoke:34-
> ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.
> invoke:91
> 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Statement]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Preparing: 
SELECT
> u.id, u.username, u.account_id, u.secret_key, u.state, a.id,
> a.account_name, a.type, a.domain_id, a.state FROM 

Re: Long delay in listDomains API response

[Cloud List]

Dear all,

After researching further, I found out that our problem is exactly the one
reported on this JIRA bug:

https://issues.apache.org/jira/browse/CLOUDSTACK-9405

I am cc-ing dsclose and Wei Zhou on this email. Anyone know if there's any
resolution to the above problem/bug?

On the bug report, Wei Zhou mentioned that he added domain level resource
limitation, may I know if this limitation is configurable? I can't find it
on the Global Settings.

Looking forward to your reply, thank you.

Cheers.


On Sun, Nov 6, 2016 at 10:30 AM, Cloud List  wrote:

> Thanks Sergey for your assistance.
>
> I have enabled the TRACE logs as requested. After the listDomains API
> call, I see a lot of DB connections being created to the database,
> preparing SELECT statements and then immediately being closed thereafter.
> This happens many many times in the loop in the course of 10-15 seconds.
> For example:
>
> Creating a DB connection with  no txn
> Preparing: SELECT
> Closing: com.mysql.jdbc.PreparedStatement
> Closing DB connection
>
> The above continues in a loop for 10-15 seconds, sometimes more. Is it
> normal? Could it be something wrong during the database schema upgrade when
> I upgraded from 4.2 to 4.8?
>
> Excerpts of the TRACE logs are below. Any advice on how I can resolve the
> problem is highly appreciated.
>
> ===
> 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
> (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X -- GET
> apikey==listDomains=json=
> 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
> transaction: http-8080-10 : http-8080-10,
> 2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
> transaction: http-8080-10 : http-8080-10,
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement] 
> (StatsCollector-2:ctx-293a2a9e)
> (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedStatement@1bda5f56:
> SELECT vm_instance.id, vm_instance.name, vm_instance.vnc_password,
> vm_instance.proxy_id, vm_instance.proxy_assign_time, vm_instance.state,
> vm_instance.private_ip_address, vm_instance.instance_name,
> vm_instance.vm_template_id, vm_instance.guest_os_id, vm_instance.host_id,
> vm_instance.last_host_id, vm_instance.pod_id, vm_instance.private_mac_address,
> vm_instance.data_center_id, vm_instance.vm_type, vm_instance.ha_enabled,
> vm_instance.display_vm, vm_instance.limit_cpu_use,
> vm_instance.update_count, vm_instance.created, vm_instance.removed,
> vm_instance.update_time, vm_instance.domain_id, vm_instance.account_id,
> vm_instance.user_id, vm_instance.service_offering_id,
> vm_instance.reservation_id, vm_instance.hypervisor_type,
> vm_instance.dynamically_scalable, vm_instance.uuid,
> vm_instance.disk_offering_id, vm_instance.power_state,
> vm_instance.power_state_update_time, vm_instance.power_state_update_count,
> vm_instance.power_host, user_vm.iso_id, user_vm.user_data,
> user_vm.display_name, user_vm.update_parameters FROM user_vm INNER JOIN
> vm_instance ON user_vm.id=vm_instance.id  WHERE vm_instance.type='User'
> AND user_vm.id = 4088  AND vm_instance.removed IS NULL
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Connection] 
> (StatsCollector-2:ctx-293a2a9e)
> (logid:725b6dd7) Closing DB connection: dbconn1208177431
> 2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Transaction]
> (StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Using current
> transaction: StatsCollector-2 : StatsCollector-2,
> 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Creating a DB
> connection with  no txn:  for 0: dbconn1379204259. Stack:
> -TransactionLegacy.prepareStatement:457-TransactionLegacy.
> prepareAutoCloseStatement:450-AccountDaoImpl.findUserAccountByApiKey:129-
> GeneratedMethodAccessor234.invoke:-1-DelegatingMethodAccessorImpl.
> invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingReflection:317-
> ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMethodInvocation.
> proceed:150-TransactionContextInterceptor.invoke:34-
> ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.
> invoke:91
> 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Statement]
> (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Preparing: SELECT
> u.id, u.username, u.account_id, u.secret_key, u.state, a.id,
> a.account_name, a.type, a.domain_id, a.state FROM `cloud`.`user` u,
> `cloud`.`account` a WHERE u.account_id = a.id AND u.api_key = ? and
> u.removed IS NULL
> 2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection] 
> (StatsCollector-2:ctx-293a2a9e)
> (logid:725b6dd7) Creating a DB connection with  no txn:  for 0:
> dbconn710552474. Stack: -TransactionLegacy.prepareStatement:457-
> TransactionLegacy.prepareAutoCloseStatement:450-
> GenericDaoBase.findById:1005-GenericDaoBase.lockRow:991-
> GenericDaoBase.findById:949-GeneratedMethodAccessor42.invoke:-1-

Re: Long delay in listDomains API response

[Cloud List]

Thanks Sergey for your assistance.

I have enabled the TRACE logs as requested. After the listDomains API call,
I see a lot of DB connections being created to the database, preparing
SELECT statements and then immediately being closed thereafter. This
happens many many times in the loop in the course of 10-15 seconds. For
example:

Creating a DB connection with  no txn
Preparing: SELECT
Closing: com.mysql.jdbc.PreparedStatement
Closing DB connection

The above continues in a loop for 10-15 seconds, sometimes more. Is it
normal? Could it be something wrong during the database schema upgrade when
I upgraded from 4.2 to 4.8?

Excerpts of the TRACE logs are below. Any advice on how I can resolve the
problem is highly appreciated.

===
2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet]
(http-8080-10:ctx-3f3ff343) (logid:0429eaf0) ===START===  X.X.X.X -- GET
apikey==listDomains=json=
2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
(http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
transaction: http-8080-10 : http-8080-10,
2016-11-06 09:36:04,893 TRACE [c.c.u.d.T.Transaction]
(http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Using current
transaction: http-8080-10 : http-8080-10,
2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Statement]
(StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Closing:
com.mysql.jdbc.JDBC4PreparedStatement@1bda5f56: SELECT vm_instance.id,
vm_instance.name, vm_instance.vnc_password, vm_instance.proxy_id,
vm_instance.proxy_assign_time, vm_instance.state,
vm_instance.private_ip_address, vm_instance.instance_name,
vm_instance.vm_template_id, vm_instance.guest_os_id, vm_instance.host_id,
vm_instance.last_host_id, vm_instance.pod_id,
vm_instance.private_mac_address, vm_instance.data_center_id,
vm_instance.vm_type, vm_instance.ha_enabled, vm_instance.display_vm,
vm_instance.limit_cpu_use, vm_instance.update_count, vm_instance.created,
vm_instance.removed, vm_instance.update_time, vm_instance.domain_id,
vm_instance.account_id, vm_instance.user_id,
vm_instance.service_offering_id, vm_instance.reservation_id,
vm_instance.hypervisor_type, vm_instance.dynamically_scalable,
vm_instance.uuid, vm_instance.disk_offering_id, vm_instance.power_state,
vm_instance.power_state_update_time, vm_instance.power_state_update_count,
vm_instance.power_host, user_vm.iso_id, user_vm.user_data,
user_vm.display_name, user_vm.update_parameters FROM user_vm INNER JOIN
vm_instance ON user_vm.id=vm_instance.id  WHERE vm_instance.type='User' AND
user_vm.id = 4088  AND vm_instance.removed IS NULL
2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Connection]
(StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Closing DB connection:
dbconn1208177431
2016-11-06 09:36:04,894 TRACE [c.c.u.d.T.Transaction]
(StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Using current transaction:
StatsCollector-2 : StatsCollector-2,
2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection]
(http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Creating a DB
connection with  no txn:  for 0: dbconn1379204259. Stack:
-TransactionLegacy.prepareStatement:457-TransactionLegacy.prepareAutoCloseStatement:450-AccountDaoImpl.findUserAccountByApiKey:129-GeneratedMethodAccessor234.invoke:-1-DelegatingMethodAccessorImpl.invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingReflection:317-ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-TransactionContextInterceptor.invoke:34-ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.invoke:91
2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Statement]
(http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Preparing: SELECT
u.id, u.username, u.account_id, u.secret_key, u.state, a.id,
a.account_name, a.type, a.domain_id, a.state FROM `cloud`.`user` u,
`cloud`.`account` a WHERE u.account_id = a.id AND u.api_key = ? and
u.removed IS NULL
2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Connection]
(StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Creating a DB connection
with  no txn:  for 0: dbconn710552474. Stack:
-TransactionLegacy.prepareStatement:457-TransactionLegacy.prepareAutoCloseStatement:450-GenericDaoBase.findById:1005-GenericDaoBase.lockRow:991-GenericDaoBase.findById:949-GeneratedMethodAccessor42.invoke:-1-DelegatingMethodAccessorImpl.invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingReflection:317-ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-TransactionContextInterceptor.invoke:34
2016-11-06 09:36:04,895 TRACE [c.c.u.d.T.Statement]
(StatsCollector-2:ctx-293a2a9e) (logid:725b6dd7) Preparing: SELECT
vm_instance.id, vm_instance.name, vm_instance.vnc_password,
vm_instance.proxy_id, vm_instance.proxy_assign_time, vm_instance.state,
vm_instance.private_ip_address, vm_instance.instance_name,
vm_instance.vm_template_id, vm_instance.guest_os_id, vm_instance.host_id,
vm_instance.last_host_id, vm_instance.pod_id,
vm_instance.private_mac_address, vm_instance.data_center_id,
vm_instance.vm_type, 

Re: Long delay in listDomains API response

[Sergey Levitskiy]

Please change DEBUG to TRACE for the following classes so they look like below. 
You don’t need to restart Cloudstack since it will dynamically switch log 
level. Once switched it will start generating enormous amount of logging so 
once you capture the slowness switch it back to DEBUG.

  
 
   
   
   
  
   


Thanks,
Sergey




On 11/5/16, 6:11 PM, "Cloud List"  wrote:

Hi Sergey,

Thanks for your reply. May I know logging for which class I need to modify
to TRACE? Is it for the c.c.a.ApiServelet class? Not too sure what does the
c.c.a stands for -- how do I check that? So I can put the correct full name
of the class category on /etc/cloudstack/management/log4j-cloud.xml.

Looking forward to your reply, thank you.

Cheers.


On Sun, Nov 6, 2016 at 5:50 AM, Sergey Levitskiy <
sergey.levits...@autodesk.com> wrote:

> You will probably need to enable TRACE logging and see what SQL query took
> long time to execute.
>
> On 11/5/16, 1:21 PM, "Cloud List"  wrote:
>
> Hi,
>
> We have upgraded ACS from 4.2 to 4.8.1.1. We noted that a
> "listDomains" API
> call from our billing system took 21 seconds for our CloudStack to
> reply,
> resulting in time-out.
>
> 
> 2016-11-06 03:40:42,891 DEBUG [c.c.a.ApiServlet]
> (http-8080-2:ctx-faa0bcbd)
> (logid:86b581fc) ===START===  X.X.X.X -- GET
> apikey=XX=
> listDomains=json=YYY
> 2016-11-06 03:41:03,850 DEBUG [c.c.a.ApiServlet]
> (http-8080-2:ctx-faa0bcbd
> ctx-5653f761 ctx-cb1e1f59) (logid:86b581fc) ===END===  X.X.X.X -- GET
> apikey=XX=
> listDomains=json=YYY
> 
>
> Any advice on what caused the delay in the API reply and how we can
> expedite?
>
> Thank you.
>
>
>

Re: Long delay in listDomains API response

[Sergey Levitskiy]

You will probably need to enable TRACE logging and see what SQL query took long 
time to execute.

On 11/5/16, 1:21 PM, "Cloud List"  wrote:

Hi,

We have upgraded ACS from 4.2 to 4.8.1.1. We noted that a "listDomains" API
call from our billing system took 21 seconds for our CloudStack to reply,
resulting in time-out.


2016-11-06 03:40:42,891 DEBUG [c.c.a.ApiServlet] (http-8080-2:ctx-faa0bcbd)
(logid:86b581fc) ===START===  X.X.X.X -- GET

apikey=XX=listDomains=json=YYY
2016-11-06 03:41:03,850 DEBUG [c.c.a.ApiServlet] (http-8080-2:ctx-faa0bcbd
ctx-5653f761 ctx-cb1e1f59) (logid:86b581fc) ===END===  X.X.X.X -- GET

apikey=XX=listDomains=json=YYY


Any advice on what caused the delay in the API reply and how we can
expedite?

Thank you.