cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Cloud List <cloud-l...@sg.or.id>
Subject Re: Long delay in listDomains API response
Date Mon, 07 Nov 2016 12:45:43 GMT
Thanks Sergey, appreciate your reply. Points noted.

Cheers.

On Mon, Nov 7, 2016 at 10:44 AM, Sergey Levitskiy <
Sergey.Levitskiy@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" <cloud-list@sg.or.id> 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 <cloud-list@sg.or.id>
> 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 <ustcweizhou@gmail.com>
> 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 <cloud-list@sg.or.id>:
>     >>
>     >>> 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.Levitskiy@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" <cloud-list@sg.or.id> 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 <
> cloud-list@sg.or.id>
>     >>>> 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=XXXX&command=listDomains&response=json&
> signature=YYYY
>     >>>>     > 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
>     >>>>     > 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.findUserAccount
>     >>>> ByApiKey:129-
>     >>>>     > GeneratedMethodAccessor234.invoke:-1-
> DelegatingMethodAccesso
>     >>>> rImpl.
>     >>>>     > invoke:43-Method.invoke:606-AopUtils.
> invokeJoinpointUsingRef
>     >>>> lection:317-
>     >>>>     > ReflectiveMethodInvocation.invokeJoinpoint:183-
> ReflectiveMet
>     >>>> hodInvocation.
>     >>>>     > proceed:150-TransactionContextInterceptor.invoke:34-
>     >>>>     > ReflectiveMethodInvocation.proceed:161-
> ExposeInvocationInter
>     >>>> ceptor.
>     >>>>     > 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-
> Aop
>     >>>> Utils.
>     >>>>     > 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,
>     >>>> 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 = ?  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,896 TRACE [c.c.u.d.T.Statement]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0)
> Closing:
>     >>>>     > com.mysql.jdbc.PreparedStatement@727fe420: 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 = 'XXXX' and u.removed
> IS NULL
>     >>>>     > 2016-11-06 09:36:04,897 TRACE [c.c.u.d.T.Connection]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0)
> Closing
>     >>>> DB
>     >>>>     > connection: dbconn1379204259
>     >>>>     > 2016-11-06 09:36:04,897 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,897 TRACE [c.c.u.d.T.Statement]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedSt
>     >>>> atement@4dff949a:
>     >>>>     > 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 = 4130  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,897 TRACE [c.c.u.d.T.Connection]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing DB connection: dbconn710552474
>     >>>>     > 2016-11-06 09:36:04,898 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,898 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: dbconn1500776736. Stack:
>     >>>>     > -TransactionLegacy.prepareStatement:457-TransactionLegacy.
>     >>>>     > prepareAutoCloseStatement:450-
> GenericDaoBase.findById:1005-G
>     >>>> enericDaoBase.
>     >>>>     > findByIdIncludingRemoved:972-GeneratedMethodAccessor115.
> invo
>     >>>> ke:-1-
>     >>>>     > DelegatingMethodAccessorImpl.invoke:43-Method.invoke:606-
> Aop
>     >>>> Utils.
>     >>>>     > invokeJoinpointUsingReflection:317-
> ReflectiveMethodInvocation.
>     >>>>     > invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-
>     >>>>     > TransactionContextInterceptor.
> invoke:34-ReflectiveMethodInvo
>     >>>> cation.
>     >>>>     > proceed:161
>     >>>>     > 2016-11-06 09:36:04,898 TRACE [c.c.u.d.T.Statement]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0)
>     >>>> Preparing: SELECT
>     >>>>     > account.id, account.account_name, account.type,
>     >>>> account.domain_id,
>     >>>>     > account.state, account.removed, account.cleanup_needed,
>     >>>>     > account.network_domain, account.uuid,
> account.default_zone_id,
>     >>>>     > account.default FROM account WHERE account.id = ?
>     >>>>     > 2016-11-06 09:36:04,899 TRACE [c.c.u.d.T.Connection]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Creating a DB connection with  no txn:
> for 0:
>     >>>>     > dbconn1143455433. 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-
> Aop
>     >>>> Utils.
>     >>>>     > invokeJoinpointUsingReflection:317-
> ReflectiveMethodInvocation.
>     >>>>     > invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-
>     >>>>     > TransactionContextInterceptor.invoke:34
>     >>>>     > 2016-11-06 09:36:04,899 TRACE [c.c.u.d.T.Statement]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0)
> Closing:
>     >>>>     > com.mysql.jdbc.PreparedStatement@7cc28d54: SELECT
> account.id,
>     >>>>     > account.account_name, account.type, account.domain_id,
>     >>>> account.state,
>     >>>>     > account.removed, account.cleanup_needed,
> account.network_domain,
>     >>>>     > account.uuid, account.default_zone_id, account.default
FROM
>     >>>> account WHERE
>     >>>>     > account.id = 2
>     >>>>     > 2016-11-06 09:36:04,899 TRACE [c.c.u.d.T.Connection]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0)
> Closing
>     >>>> DB
>     >>>>     > connection: dbconn1500776736
>     >>>>     > 2016-11-06 09:36:04,899 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,
>     >>>> 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 = ?  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,900 TRACE [c.c.u.d.T.Transaction]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Using current transaction: http-8080-10 : http-8080-10,
>     >>>>     > 2016-11-06 09:36:04,900 TRACE [c.c.u.d.T.Statement]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedSt
>     >>>> atement@1259275a:
>     >>>>     > 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 = 4191  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,901 TRACE [c.c.u.d.T.Connection]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing DB connection: dbconn1143455433
>     >>>>     > 2016-11-06 09:36:04,901 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,901 TRACE [c.c.u.d.T.Connection]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Creating a DB connection with  no txn:  for 0:
> dbconn1688317537.
>     >>>> 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.
> invokeJoinpointUsingRef
>     >>>> lection:317-
>     >>>>     > ReflectiveMethodInvocation.invokeJoinpoint:183-
> ReflectiveMet
>     >>>> hodInvocation.
>     >>>>     > proceed:150-TransactionContextInterceptor.invoke:34
>     >>>>     > 2016-11-06 09:36:04,901 TRACE [c.c.u.d.T.Statement]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Preparing: SELECT account.id, account.account_name,
> account.type,
>     >>>>     > account.domain_id, account.state, account.removed,
>     >>>> account.cleanup_needed,
>     >>>>     > account.network_domain, account.uuid,
> account.default_zone_id,
>     >>>>     > account.default FROM account WHERE account.id = ?  AND
>     >>>> account.removed IS
>     >>>>     > NULL
>     >>>>     > 2016-11-06 09:36:04,902 TRACE [c.c.u.d.T.Statement]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Closing: com.mysql.jdbc.JDBC4PreparedStatement@7efdf10:
> SELECT
>     >>>> account.id,
>     >>>>     > account.account_name, account.type, account.domain_id,
>     >>>> account.state,
>     >>>>     > account.removed, account.cleanup_needed,
> account.network_domain,
>     >>>>     > account.uuid, account.default_zone_id, account.default
FROM
>     >>>> account WHERE
>     >>>>     > account.id = 2  AND account.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,902 TRACE [c.c.u.d.T.Connection]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Closing DB connection: dbconn1688317537
>     >>>>     > 2016-11-06 09:36:04,902 TRACE [c.c.u.d.T.Connection]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Creating a DB connection with  no txn:
> for 0:
>     >>>>     > dbconn1632185236. 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-
> Aop
>     >>>> Utils.
>     >>>>     > invokeJoinpointUsingReflection:317-
> ReflectiveMethodInvocation.
>     >>>>     > invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-
>     >>>>     > TransactionContextInterceptor.invoke:34
>     >>>>     > 2016-11-06 09:36:04,902 TRACE [c.c.u.AccountManagerImpl]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0) Root
>     >>>>     > Access granted to Acct[0bb6751b-eaa1-11e2-b078-
> 6d70ed52d122-admin]
>     >>>> by
>     >>>>     > AffinityGroupAccessChecker
>     >>>>     > 2016-11-06 09:36:04,902 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,
>     >>>> 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 = ?  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,902 TRACE [c.c.u.d.T.Transaction]
>     >>>>     > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b ctx-f5ec429d)
>     >>>> (logid:0429eaf0)
>     >>>>     > Using current transaction: http-8080-10 : http-8080-10,
>     >>>>     > 2016-11-06 09:36:04,903 TRACE [c.c.u.d.T.Statement]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing: com.mysql.jdbc.JDBC4PreparedSt
>     >>>> atement@107795cb:
>     >>>>     > 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 = 4221  AND vm_instance.removed IS NULL
>     >>>>     > 2016-11-06 09:36:04,904 TRACE [c.c.u.d.T.Connection]
>     >>>> (StatsCollector-2:ctx-293a2a9e)
>     >>>>     > (logid:725b6dd7) Closing DB connection: dbconn1632185236
>     >>>>     >
>     >>>>     >
>     >>>>     >
>     >>>>     > On Sun, Nov 6, 2016 at 9:37 AM, Sergey Levitskiy <
>     >>>>     > Sergey.Levitskiy@autodesk.com> wrote:
>     >>>>     >
>     >>>>     >> 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.
>     >>>>     >>
>     >>>>     >>   <category name="com.cloud">
>     >>>>     >>      <priority value="TRACE"/>
>     >>>>     >>    </category>
>     >>>>     >>
>     >>>>     >>    <category name="org.apache.cloudstack">
>     >>>>     >>       <priority value="TRACE"/>
>     >>>>     >>    </category>
>     >>>>     >>
>     >>>>     >>
>     >>>>     >> Thanks,
>     >>>>     >> Sergey
>     >>>>     >>
>     >>>>     >>
>     >>>>     >>
>     >>>>     >>
>     >>>>     >> On 11/5/16, 6:11 PM, "Cloud List" <cloud-list@sg.or.id>
> 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/log
>     >>>> 4j-cloud.xml.
>     >>>>     >>
>     >>>>     >>     Looking forward to your reply, thank you.
>     >>>>     >>
>     >>>>     >>     Cheers.
>     >>>>     >>
>     >>>>     >>
>     >>>>     >>     On Sun, Nov 6, 2016 at 5:50 AM, Sergey Levitskiy
<
>     >>>>     >>     Sergey.Levitskiy@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" <
> cloud-list@sg.or.id>
>     >>>> 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=XXXXXXXXXXXXXXXXXXXXXX
>     >>>> XXXXXXXXXXXXXXXXXXXXXXXX&command=
>     >>>>     >>     > listDomains&response=json&
> signature=YYYYYYYYYYYYYYYYYYY
>     >>>>     >>     >     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=XXXXXXXXXXXXXXXXXXXXXX
>     >>>> XXXXXXXXXXXXXXXXXXXXXXXX&command=
>     >>>>     >>     > listDomains&response=json&
> signature=YYYYYYYYYYYYYYYYYYY
>     >>>>     >>     >     ====
>     >>>>     >>     >
>     >>>>     >>     >     Any advice on what caused the delay in
the API
> reply
>     >>>> and how we
>     >>>>     >> can
>     >>>>     >>     >     expedite?
>     >>>>     >>     >
>     >>>>     >>     >     Thank you.
>     >>>>     >>     >
>     >>>>     >>     >
>     >>>>     >>     >
>     >>>>     >>
>     >>>>     >>
>     >>>>     >>
>     >>>>     >
>     >>>>
>     >>>>
>     >>>>
>     >>>
>     >>
>     >
>
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message