[GitHub] cloudstack issue #1578: CLOUDSTACK-9401 : Support for Internal DNS in Nuage ...
Github user prashanthvarma commented on the issue: https://github.com/apache/cloudstack/pull/1578 @jburwell @rhtyd We have briefly investigated the above test failures, and here are our findings: 1) No single test is failing across all the environments, and this PR doesn't contain any "hypervisor" specific changes. 2) The failed test on KVM "test_01_create_template" looks more like a timing issue, and we might not always hit it (refer above comment). Is there a way, we can re-trigger the above failing tests on your CI environment, and also get the management server logs for them to further debug these failures ? It will also be handy for us to get the results and logs of these tests when ran against latest master. Hope, we are not asking to much :) Meanwhile, we will try to reproduce these failures on our setups. --- If your project is set up for it, you can reply to this email and have your reply appear on GitHub as well. If your project does not have this feature enabled and wishes so, or if the feature is enabled but not working, please contact infrastructure at infrastruct...@apache.org or file a JIRA ticket with INFRA. ---
Long delay in listDomains API response
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&command=listDomains&response=json&signature=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&command=listDomains&response=json&signature=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
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&command=listDomains&response=json&signature=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&command=listDomains&response=json&signature=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
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&command= > listDomains&response=json&signature=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&command= > listDomains&response=json&signature=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
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&command= > listDomains&response=json&signature=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&command= > listDomains&response=json&signature=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
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=&command=listDomains&response=json&signature= 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_instan
Re: Long delay in listDomains API response
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=&command=listDomains&response=json&signature= > 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.invok
