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 3C0E5200BB5 for ; Sun, 6 Nov 2016 17:42:21 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 3AA2B160B0D; Sun, 6 Nov 2016 16:42:21 +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 0867C160AE8 for ; Sun, 6 Nov 2016 17:42:19 +0100 (CET) Received: (qmail 62244 invoked by uid 500); 6 Nov 2016 16:42:19 -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 62218 invoked by uid 99); 6 Nov 2016 16:42:18 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 06 Nov 2016 16:42:18 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id EFC84C03B7; Sun, 6 Nov 2016 16:42:17 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2.841 X-Spam-Level: ** X-Spam-Status: No, score=2.841 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-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, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd4-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id pNfUnAwxKvtO; Sun, 6 Nov 2016 16:42:09 +0000 (UTC) Received: from mail-it0-f47.google.com (mail-it0-f47.google.com [209.85.214.47]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id C4B7A5FD29; Sun, 6 Nov 2016 16:42:08 +0000 (UTC) Received: by mail-it0-f47.google.com with SMTP id e187so53834168itc.0; Sun, 06 Nov 2016 08:42:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=TdJDkfuDMaCSYJcBRsJVudZbwPM2ExWSx+h8KBRKxLo=; b=VoCsayHxUioqYIso9mVYleJv9Qt9JGTsotU8aDJJjzISAmTggXOLYQNaY7yajDTcP1 R6SmU8z+0TweA+esYBBguSasAby9wDtC6a+0qgCqTyyHvB0airv+mqLqqn7G8aVEuhNp Y+XHXC37SWcNwsKV69WLxHv4mhhLWcHsWlaM9Jc0ABusTB0tDCtQSwEvvmi7arZyyJLa pmh+amPal7ssRiNBXAF7c94IUXVe+Q/XyVOP2MUPcRVe9UlYZ+ktNRU3ZENDET3N/V2X hCkiP3p8IbDCW8MBmYYtmv1ejydK0suRmePDlNOid18qOGNL3uv0MwgaUVTAvw8KVG71 GkRA== 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=TdJDkfuDMaCSYJcBRsJVudZbwPM2ExWSx+h8KBRKxLo=; b=JJA5/62Bw/pc+vytj5VFsTDDXsWYD8EjpNppRNXrGvQiMFkIe86vA9TQQte/jQmg8b ku6Dh9zhrQS6vdcAtvOHTi5D6NIylcGUh7HR45wMZeXSB9szWbaTYkMDMZvKfB2+25G5 ABURDHfxxWFfY4sZClM05Wr5mO6QSSfH6+e8x3tOYzT+C1mlHlzycV63ZhKn4Kd+9sYD OxSBHqnryDCxqZy6AQHqHteQvl/toTe2kFZUw/WH1DpsrrYtLIsvxwc5BWBYJ+iAX7Ts HHV3hgaiP5YTjo8XJgBqp86LUjsyU3pmmhmBapvfrH0WBUko+Hf+U+i0T62Lh03TLa0M tXJw== X-Gm-Message-State: ABUngvdPbZ7t4wADNvUuHmnqgJG7ORQuc+bmB0LYyqRLM43f1YHaNyLj4R+ZepAaoFUOYQ5EcG+xBD8GT2aGdg== X-Received: by 10.107.20.133 with SMTP id 127mr3619404iou.187.1478450527847; Sun, 06 Nov 2016 08:42:07 -0800 (PST) MIME-Version: 1.0 Received: by 10.64.30.107 with HTTP; Sun, 6 Nov 2016 08:42:07 -0800 (PST) In-Reply-To: References: From: Wei ZHOU Date: Sun, 6 Nov 2016 17:42:07 +0100 Message-ID: Subject: Re: Long delay in listDomains API response To: Cloud List Cc: "dev@cloudstack.apache.org" , "users@cloudstack.apache.org" , "dsclose@gmail.com" , "w.zhou@leaseweb.com" Content-Type: multipart/alternative; boundary=001a114fa64287cc0a0540a49652 archived-at: Sun, 06 Nov 2016 16:42:21 -0000 --001a114fa64287cc0a0540a49652 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable 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 an= d post it here? >> >> >> On 11/5/16, 11:01 PM, "Cloud List" wrote: >> >> Dear all, >> >> After researching further, I found out that our problem is exactly >> the one >> reported on this JIRA bug: >> >> https://issues.apache.org/jira/browse/CLOUDSTACK-9405 >> >> I am cc-ing dsclose and Wei Zhou on this email. Anyone know if >> there's any >> resolution to the above problem/bug? >> >> On the bug report, Wei Zhou mentioned that he added domain level >> resource >> limitation, may I know if this limitation is configurable? I can't >> find it >> on the Global Settings. >> >> Looking forward to your reply, thank you. >> >> Cheers. >> >> >> On Sun, Nov 6, 2016 at 10:30 AM, Cloud List >> wrote: >> >> > Thanks Sergey for your assistance. >> > >> > I have enabled the TRACE logs as requested. After the listDomains >> API >> > call, I see a lot of DB connections being created to the database, >> > preparing SELECT statements and then immediately being closed >> thereafter. >> > This happens many many times in the loop in the course of 10-15 >> seconds. >> > For example: >> > >> > Creating a DB connection with no txn >> > Preparing: SELECT >> > Closing: com.mysql.jdbc.PreparedStatement >> > Closing DB connection >> > >> > The above continues in a loop for 10-15 seconds, sometimes more. I= s >> 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=3DYY= YY >> > 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_updat= e >> _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-DelegatingMethodAccessorImpl. >> > invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingRef >> lection:317- >> > ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMet >> hodInvocation. >> > 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 =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-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.nam= e >> , >> > 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_updat= e >> _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) 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 =3D a.id AND u.api_key =3D 'XXXX' and u.removed IS NU= LL >> > 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_updat= e >> _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.invoke:-1- >> > DelegatingMethodAccessorImpl.invoke:43-Method.invoke:606-AopUtils. >> > invokeJoinpointUsingReflection:317-ReflectiveMethodInvocation. >> > invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150- >> > TransactionContextInterceptor.invoke:34-ReflectiveMethodInvocation= . >> > 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-AopUtils. >> > 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 accoun= t >> 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) 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.nam= e >> , >> > 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_updat= e >> _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_updat= e >> _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 accoun= t >> 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-AopUtils. >> > 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.nam= e >> , >> > 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_updat= e >> _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_updat= e >> _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 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/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 -- GE= T >> >> > apikey=3DXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX= & >> command=3D >> >> > listDomains&response=3Djson&signature=3DYYYYYYYYYYYYYYYYYYY >> >> > 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=3DEN= D=3D=3D=3D >> X.X.X.X >> >> -- GET >> >> > apikey=3DXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX= & >> command=3D >> >> > listDomains&response=3Djson&signature=3DYYYYYYYYYYYYYYYYYYY >> >> > =3D=3D=3D=3D >> >> > >> >> > Any advice on what caused the delay in the API reply an= d >> how we >> >> can >> >> > expedite? >> >> > >> >> > Thank you. >> >> > >> >> > >> >> > >> >> >> >> >> >> >> > >> >> >> > --001a114fa64287cc0a0540a49652--