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" <cloud-l...@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-l...@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 <ustcweiz...@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-l...@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.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" <cloud-l...@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-l...@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.levits...@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-l...@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.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" < > cloud-l...@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. > >>>> >> > > >>>> >> > > >>>> >> > > >>>> >> > >>>> >> > >>>> >> > >>>> > > >>>> > >>>> > >>>> > >>> > >> > > > > >
