[CLOUDSTACK-8485] listAPIs are taking too long to return results

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 4.5.1, 4.6.0
• Fix Version/s: 4.6.1, 4.7.0
• Component/s: Management Server
• Security Level: Public (Anyone can view this level - this is the default.)
• Assignee: Koushik Das
• Reporter: Sowmya Krishnan
• Created: 20/May/15 04:18
• Updated: 05/Feb/16 03:38
• Resolved: 13/Dec/15 21:23

Description

listAPIs are taking significantly longer than before (4.2.x)

I tried out few listAPI calls using a simulator set up with ~ 10K VMs and 8K Routers. Here are few results:
listVirtualMachines is taking > 25 sec to return with pagesize set to 50. This is in comparison to 2 sec in earlier cases such as 4.2.

listVolumes with pagesize = 1000 took more than 10 mins and finally times out.

Further observations show that there are also lot of slow queries being logged in catalina.out and in MySQL slow query logs. I am not sure if this could be the reason for DB performance getting impacted in turn causing an impact on listAPIs too.

Here's a sample of slow queries from catalina.out:

Mon May 11 07:31:15 UTC 2015 INFO: Profiler Event: [SLOW QUERY] at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) duration: 3305 ms, connection-id: 637759, statement-id: 3218312, resultset-id: 0, message: Slow query (exceeded 2,000 ms, duration: 3,305 ms):SELECT user_vm_details.id, user_vm_details.vm_id, user_vm_details.name, user_vm_details.value, user_vm_details.display FROM user_vm_details WHERE user_vm_details.vm_id = 9117Mon May 11 07:31:15 UTC 2015 INFO: Profiler Event: [SLOW QUERY] at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) duration: 3305 ms, connection-id: 637843, statement-id: 3218311, resultset-id: 0, message: Slow query (exceeded 2,000 ms, duration: 3,305 ms):SELECT host.id, host.disconnected, host.name, host.status, host.type, host.private_ip_address, host.private_mac_address, host.private_netmask, host.public_netmask, host.public_ip_address, host.public_mac_address, host.storage_ip_address, host.cluster_id, host.storage_netmask, host.storage_mac_address, host.storage_ip_address_2, host.storage_netmask_2, host.storage_mac_address_2, host.hypervisor_type, host.proxy_port, host.resource, host.fs_type, host.available, host.setup, host.resource_state, host.hypervisor_version, host.update_count, host.uuid, host.data_center_id, host.pod_id, host.cpu_sockets, host.cpus, host.url, host.speed, host.ram, host.parent, host.guid, host.capabilities, host.total_size, host.last_ping, host.mgmt_server_id, host.dom0_memory, host.version, host.created, host.removed FROM host WHERE host.id = 345 AND host.removed IS NULL
Mon May 11 07:31:17 UTC 2015 INFO: Profiler Event: [SLOW QUERY] at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) duration: 6458 ms, connection-id: 637623, statement-id: 3218243, resultset-id: 0, message: Slow query (exceeded 2,000 ms, duration: 6,458 ms):SELECT storage_pool_host_ref.host_id FROM storage_pool_host_ref INNER JOIN host ON storage_pool_host_ref.host_id=host.id WHERE storage_pool_host_ref.pool_id = 197 AND (host.status = 'Up' AND host.resource_state = 'Enabled' )Mon May 11 07:31:17 UTC 2015 INFO: Profiler Event: [SLOW QUERY] at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) duration: 2402 ms, connection-id: 637754, statement-id: 3218371, resultset-id: 0, message: Slow query (exceeded 2,000 ms, duration: 2,402 ms):SELECT host.id, host.disconnected, host.name, host.status, host.type, host.private_ip_address, host.private_mac_address, host.private_netmask, host.public_netmask, host.public_ip_address, host.public_mac_address, host.storage_ip_address, host.cluster_id, host.storage_netmask, host.storage_mac_address, host.storage_ip_address_2, host.storage_netmask_2, host.storage_mac_address_2, host.hypervisor_type, host.proxy_port, host.resource, host.fs_type, host.available, host.setup, host.resource_state, host.hypervisor_version, host.update_count, host.uuid, host.data_center_id, host.pod_id, host.cpu_sockets, host.cpus, host.url, host.speed, host.ram, host.parent, host.guid, host.capabilities, host.total_size, host.last_ping, host.mgmt_server_id, host.dom0_memory, host.version, host.created, host.removed FROM host WHERE host.id = 669 AND host.removed IS NULL

The following is from MySQL slow query log:

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.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 FROM vm_instance WHERE vm_instance.instance_name = _binary'r-16916-VM' AND vm_instance.removed IS NULL ORDER BY RAND() LIMIT 1;# User@Host: cloud[cloud] @ x3 [10.81.28.128] Id: 637881# Query_time: 8.193784 Lock_time: 0.000107 Rows_sent: 1 Rows_examined: 19935SET timestamp=1431329557;

SET timestamp=1431329601;SELECT host.id, host.disconnected, host.name, host.status, host.type, host.private_ip_address, host.private_mac_address, host.private_netmask, host.public_netmask, host.public_ip_address, host.public_mac_address, host.storage_ip_address, host.cluster_id, host.storage_netmask, host.storage_mac_address, host.storage_ip_address_2, host.storage_netmask_2, host.storage_mac_address_2, host.hypervisor_type, host.proxy_port, host.resource, host.fs_type, host.available, host.setup, host.resource_state, host.hypervisor_version, host.update_count, host.uuid, host.data_center_id, host.pod_id, host.cpu_sockets, host.cpus, host.url, host.speed, host.ram, host.parent, host.guid, host.capabilities, host.total_size, host.last_ping, host.mgmt_server_id, host.dom0_memory, host.version, host.created, host.removed FROM host WHERE host.id = 913 AND host.removed IS NULL;# User@Host: cloud[cloud] @ x3 [10.81.28.128] Id: 637865# Query_time: 5.861241 Lock_time: 0.000139 Rows_sent: 1 Rows_examined: 1

Issue Links

• relates to: CLOUDSTACK-9023 private keys get logged when UpdateCustomCertificate gets called