Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id BA93A200BCA for ; Mon, 7 Nov 2016 02:52:45 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id B9187160AFC; Mon, 7 Nov 2016 01:52:45 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 3882B160B0D for ; Mon, 7 Nov 2016 02:52:44 +0100 (CET) Received: (qmail 84548 invoked by uid 500); 7 Nov 2016 01:52:43 -0000 Mailing-List: contact users-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@cloudstack.apache.org Delivered-To: mailing list users@cloudstack.apache.org Received: (qmail 84246 invoked by uid 99); 7 Nov 2016 01:52:42 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 07 Nov 2016 01:52:42 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 2AD141804C1 for ; Mon, 7 Nov 2016 01:52:42 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2.942 X-Spam-Level: ** X-Spam-Status: No, score=2.942 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, HTML_MESSAGE=2, HTML_OBFUSCATE_10_20=1.162, RCVD_IN_DNSWL_LOW=-0.7, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, RCVD_IN_SORBS_SPAM=0.5] autolearn=disabled Authentication-Results: spamd3-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=sg-or-id.20150623.gappssmtp.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id vbi7rEy-yq3b for ; Mon, 7 Nov 2016 01:52:32 +0000 (UTC) Received: from mail-it0-f46.google.com (mail-it0-f46.google.com [209.85.214.46]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id D8FF25FD63 for ; Mon, 7 Nov 2016 01:52:31 +0000 (UTC) Received: by mail-it0-f46.google.com with SMTP id u205so95004965itc.0 for ; Sun, 06 Nov 2016 17:52:31 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=sg-or-id.20150623.gappssmtp.com; s=20150623; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=6BI5okGSx3M7UkGA/a4E1YqBpOGzLaZ+V2wtt1JP+O0=; b=oy2faTa5XrNE6CICk6qKmZNaHggaEOWQgvFwUBfYFwg1/OlV6wAJ91CvXHQX33usPG 82dgUbQaH6xCp/YiAJrhwtqCcWPjTVra9+SQvjL37EJyxqwReeF8NzNoN7BSW/XfARfp ffl1hY5ruiwG1uRpGwwwiwRz/2m1B7a0wVNqI8J1kzDtOE3bRsH+Dh5sHb7mi/Krbhp3 fIvg4/jnTpAbGJJW7RqpfrGhKBQh8lQkd7VIyLkOcwkAOlb6AGzSAUZHWXif/hVTOa70 JNiPEubqmxC10FUPTYKUTzMcZDE1EDSPKmXhdOpLoStavDGBw17NXFPoVYVZBqsWowvC iPbg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=6BI5okGSx3M7UkGA/a4E1YqBpOGzLaZ+V2wtt1JP+O0=; b=V1wA2poGIHwwiM5nRM5DWzgaKjZ8VBRxyA3fVbPT9SO5lT9wJGmzlb4VXQJ9CPqapJ 2AZEz7YGqhLKmgFr2wv5XRHYATCoJYp6A17nkdgOO4fUTl4lVPFzXU9CUjAl8douqptW 1532xi23IKEW2k3iIHV8ZS9OA7Z4OnZl2lYNkUIL/bkO41dkSSuu35qSZLHRyI+jtCbk Sc3MtAVItVgKwSDBq7VqAZ/NX9nobbMrI1vc20nTXbLVr+Y4FQoLTVcgYhMpffYvq9cG +jcy+4N0rZbWBUH7X7eFcPo7VjZZCMlIuiQ6c2RNmsyXJbVJ/Z6LS0m7v+zemS1ew/uc 78Mg== X-Gm-Message-State: ABUngvfgDvHq7ultG6TsOrrUluqARbJ9AYTQ5xMFdyAuXBWzUOrMa8CQNNPgkMDfsFRobs6kACQQc2jnI5JgkA== X-Received: by 10.157.9.237 with SMTP id 42mr2067058otz.171.1478483549384; Sun, 06 Nov 2016 17:52:29 -0800 (PST) MIME-Version: 1.0 Received: by 10.202.56.196 with HTTP; Sun, 6 Nov 2016 17:52:28 -0800 (PST) In-Reply-To: References: From: Cloud List Date: Mon, 7 Nov 2016 09:52:28 +0800 Message-ID: Subject: Re: Long delay in listDomains API response To: Wei ZHOU Cc: "dev@cloudstack.apache.org" , "users@cloudstack.apache.org" , "dsclose@gmail.com" , "w.zhou@leaseweb.com" Content-Type: multipart/alternative; boundary=001a1134f346c48c1e0540ac46e9 archived-at: Mon, 07 Nov 2016 01:52:45 -0000 --001a1134f346c48c1e0540ac46e9 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable 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-Tuni= ng-Collab-2015.pdf https://www.percona.com/blog/2014/01/28/10-mysql-performance-tuning-setting= s-after-installation/ https://www.percona.com/blog/2012/01/06/mysql-high-number-connections-per-s= econ/ 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 of= f? > 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 t= he > 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.Levitskiy@autodesk.com> wrote: >>> >>>> Can you grep for this line =E2=80=98ctx-3f3ff343=E2=80=99 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 listDomain= s >>>> API >>>> > call, I see a lot of DB connections being created to the databas= e, >>>> > 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. >>>> > >>>> > =3D=3D=3D >>>> > 2016-11-06 09:36:04,893 DEBUG [c.c.a.ApiServlet] >>>> > (http-8080-10:ctx-3f3ff343) (logid:0429eaf0) =3D=3D=3DSTART=3D= =3D=3D X.X.X.X >>>> -- GET >>>> > apikey=3DXXXX&command=3DlistDomains&response=3Djson&signature=3D= 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D 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 =3D a.id AND u.api_key = =3D ? >>>> 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D ? 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) Closin= g: >>>> > 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 =3D a.id AND u.api_key =3D '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) Closin= g >>>> 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D 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 =3D ? >>>> > 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) Closin= g: >>>> > 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 =3D 2 >>>> > 2016-11-06 09:36:04,899 TRACE [c.c.u.d.T.Connection] >>>> > (http-8080-10:ctx-3f3ff343 ctx-e486fd2b) (logid:0429eaf0) Closin= g >>>> 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D ? 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D 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 =3D ? 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 =3D 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-admi= n] >>>> 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D ? 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=3Dvm_instance.id WHERE >>>> vm_instance.type=3D'User' >>>> > AND user_vm.id =3D 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=E2=80=99t need to restart Cloudstack since it wi= ll >>>> dynamically >>>> >> switch log level. Once switched it will start generating >>>> enormous amount of >>>> >> logging so once you capture the slowness switch it back to DEBU= G. >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> >>>> >> 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/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" >>>> 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. >>>> >> > >>>> >> > =3D=3D=3D=3D >>>> >> > 2016-11-06 03:40:42,891 DEBUG [c.c.a.ApiServlet] >>>> >> > (http-8080-2:ctx-faa0bcbd) >>>> >> > (logid:86b581fc) =3D=3D=3DSTART=3D=3D=3D X.X.X.X -- = GET >>>> >> > apikey=3DXXXXXXXXXXXXXXXXXXXXXX >>>> XXXXXXXXXXXXXXXXXXXXXXXX&command=3D >>>> >> > listDomains&response=3Djson&signature=3DYYYYYYYYYYYYYYYYY= YY >>>> >> > 2016-11-06 03:41:03,850 DEBUG [c.c.a.ApiServlet] >>>> >> > (http-8080-2:ctx-faa0bcbd >>>> >> > ctx-5653f761 ctx-cb1e1f59) (logid:86b581fc) =3D=3D=3D= END=3D=3D=3D >>>> X.X.X.X >>>> >> -- GET >>>> >> > apikey=3DXXXXXXXXXXXXXXXXXXXXXX >>>> XXXXXXXXXXXXXXXXXXXXXXXX&command=3D >>>> >> > listDomains&response=3Djson&signature=3DYYYYYYYYYYYYYYYYY= YY >>>> >> > =3D=3D=3D=3D >>>> >> > >>>> >> > Any advice on what caused the delay in the API reply >>>> and how we >>>> >> can >>>> >> > expedite? >>>> >> > >>>> >> > Thank you. >>>> >> > >>>> >> > >>>> >> > >>>> >> >>>> >> >>>> >> >>>> > >>>> >>>> >>>> >>> >> > --001a1134f346c48c1e0540ac46e9--