Description of problem: The stored procedure getdisksvmguid running too slow 3-5 in high ratio. looks like this query affected from all_disks_including_snapshots view which is running to slow on scale setup (10K rows table). by looking at the explain analyze for all_disks_including_snapshots the most expensive part sorting: "Hash Left Join (cost=56631.27..65684.14 rows=24601 width=1405) (actual time=2297.225..2668.236 rows=10723 loops=1)" " Hash Cond: ("*SELECT* 1".image_group_id = bd.disk_id)" " -> Unique (cost=54381.30..56902.90 rows=24601 width=1152) (actual time=2287.766..2633.585 rows=10723 loops=1)" " -> Sort (cost=54381.30..54442.80 rows=24601 width=1152) (actual time=2287.764..2622.109 rows=10723 loops=1)" Version-Release number of selected component (if applicable): 3.4.2 and also tested for 3.5 master (reproduced too) How reproducible: 100% Steps to Reproduce: 1.scale setup (500 hosts \ 10K vms) 2.set log_duration at (postgres log) 3.read the postgres logs (reproduced on idle probably as part of the monitors threads \ Quartz). Actual results: 3-5 sec for each stored procedure. Expected results: faster results \ from cache \ indexing Additional info:
What activity causes this query?
(In reply to Liran Zelkha from comment #1) > What activity causes this query? Idle, just scale setup(500 hotst, 10K vms) no users load or any other automation. probably related to the monitor \ quratz threads.
Eldad - can you provide jstack files?
Hi Eldad, I set up an environment with >100VMs and 50 hosts. I can't see a single call to this DB method. Can you give more info on how to reproduce? 1. Is there a UI open? 2. Are VMs up?
This caused due to rest API when we creating vms via jmeter. searching for the disk status: '/api/disks/<disk_id>/'
This specific API calls getdiskbydiskid, which I think should run OK even under load. Actual API call is /api/vms/1e8c3a11-6704-4250-82f0-71d79b44ffd3/disks
Eldad - can you please run the file I attach (it will replace the procedure) and tell me if there is a performance improvement?
Created attachment 940416 [details] Function replacement
Liran, there is no 'disk_profile_id' column on 3.4.2. as described in query: LEFT OUTER JOIN disk_profiles ON image_storage_domain_map.disk_profile_id = disk_profiles.id
The target release is 3.5... I'll try to provide the same patch for 3.4
Created attachment 942610 [details] Function replacement for 3.4.2
Added. Eldad can you check?
Liran, looks like the following rest api going bad since i have update the store procedure when running this: https://<host>/api/vms/<vmid> getting this xml response: <?xml version="1.0" encoding="UTF-8" standalone="yes" ?> <fault> <reason>Operation Failed</reason> <detail>preparedstatementcallback; bad sql grammar [select * from getdisksvmguid(?, ?, ?, ?)]; nested exception is org.postgresql.util.psqlexception: error: structure of query does not match function result type detail: returned type uuid does not match expected type text in column 2. where: pl/pgsql function "getdisksvmguid" line 2 at return query</detail> </fault> version 3.4.2
Created attachment 943920 [details] Function replacement for 3.4.2 v2
Please see new uploaded version
now it's ok. but postgres still logged the function. not like before see the explain plain. Nested Loop (cost=81285.03..87553.01 rows=1 width=1405) (actual time=2468.359..2476.963 rows=1 loops=1) Join Filter: ((((public.vm_device.snapshot_id IS NULL) AND ("*SELECT* 1".active IS NOT FALSE)) OR (public.vm_device.snapshot_id = "*SELECT* 1".vm_snapshot_id)) AND (bd.disk_id = "*SELECT* 1".image_group_id)) -> Nested Loop (cost=0.00..3164.25 rows=1 width=610) (actual time=21.782..24.456 rows=1 loops=1) -> Seq Scan on vm_device (cost=0.00..3106.28 rows=7 width=32) (actual time=5.291..24.371 rows=7 loops=1) Filter: (vm_id = 'f49a67d2-d1d3-4441-ac3e-7bf53174b70d'::uuid) -> Index Scan using idx_bd_id on base_disks bd (cost=0.00..8.27 rows=1 width=578) (actual time=0.008..0.009 rows=0 loops=7) Index Cond: (bd.disk_id = public.vm_device.device_id) -> Unique (cost=81285.03..83780.18 rows=24343 width=1409) (actual time=2436.614..2448.070 rows=10731 loops=1) -> Sort (cost=81285.03..81345.88 rows=24343 width=1409) (actual time=2436.612..2439.368 rows=10731 loops=1) Sort Key: (0), "*SELECT* 1".storage_id, "*SELECT* 1".storage_path, "*SELECT* 1".storage_name, "*SELECT* 1".storage_type, "*SELECT* 1".storage_pool_id, "*SELECT* 1".image_guid, "*SELECT* 1".creation_date, "*SELECT* 1".actua l_size, "*SELECT* 1".read_rate, "*SELECT* 1".write_rate, "*SELECT* 1".read_latency_seconds, "*SELECT* 1".write_latency_seconds, "*SELECT* 1".flush_latency_seconds, "*SELECT* 1".size, "*SELECT* 1".it_guid, "*SELECT* 1".imagestatus, "*SELE CT* 1".lastmodified, "*SELECT* 1".volume_type, "*SELECT* 1".volume_format, "*SELECT* 1".image_group_id, "*SELECT* 1".description, "*SELECT* 1".parentid, "*SELECT* 1".app_list, "*SELECT* 1".vm_snapshot_id, "*SELECT* 1".active, "*SELECT* 1 ".entity_type, "*SELECT* 1".number_of_vms, "*SELECT* 1".vm_names, "*SELECT* 1".quota_id, "*SELECT* 1".quota_name, "*SELECT* 1".quota_enforcement_type, (NULL::character varying), (NULL::character varying), (NULL::character varying), (NULL ::character varying), (NULL::integer), (NULL::character varying), (NULL::character varying), (NULL::integer) Sort Method: external sort Disk: 3456kB -> Append (cost=40841.73..49551.49 rows=24343 width=1409) (actual time=458.590..716.906 rows=10731 loops=1) -> Subquery Scan "*SELECT* 1" (cost=40841.73..43990.18 rows=10583 width=1107) (actual time=458.590..666.182 rows=10731 loops=1) -> Subquery Scan images_storage_domain_view (cost=40841.73..43884.35 rows=10583 width=1107) (actual time=458.587..661.005 rows=10731 loops=1) -> GroupAggregate (cost=40841.73..43778.52 rows=10583 width=2118) (actual time=458.584..655.831 rows=10731 loops=1) -> Sort (cost=40841.73..40868.19 rows=10583 width=2118) (actual time=458.474..467.270 rows=10731 loops=1) Sort Key: images.image_guid, snapshots.description, snapshots.app_list, vms_for_disk_view.entity_type, (array_to_string(vms_for_disk_view.array_vm_names, ','::text)), (COALESCE(array_upper(vms _for_disk_view.array_vm_names, 1), 0)), base_disks.disk_id, public.storage_pool.id Sort Method: external merge Disk: 4104kB -> Hash Left Join (cost=12383.94..20744.29 rows=10583 width=2118) (actual time=199.755..408.499 rows=10731 loops=1) Hash Cond: (image_storage_domain_map.quota_id = quota.id) -> Hash Left Join (cost=12371.69..20639.43 rows=10583 width=1970) (actual time=199.709..393.243 rows=10731 loops=1) Hash Cond: (images.vm_snapshot_id = snapshots.snapshot_id) -> Hash Left Join (cost=10876.56..13810.34 rows=10583 width=1928) (actual time=183.076..343.906 rows=10731 loops=1) Hash Cond: (storage_pool_iso_map.storage_pool_id = public.storage_pool.id) -> Hash Left Join (cost=10875.47..13663.73 rows=10583 width=1924) (actual time=183.028..333.152 rows=10731 loops=1) Hash Cond: (images.image_guid = disk_image_dynamic.image_id) -> Hash Left Join (cost=10293.02..12882.85 rows=10583 width=1893) (actual time=170.027..303.158 rows=10731 loops=1) Hash Cond: (image_storage_domain_map.storage_domain_id = storage_domain_static.id) -> Hash Left Join (cost=10289.69..12734.00 rows=10583 width=841) (actual time=169.910..292.304 rows=10731 loops=1) Hash Cond: (images.image_guid = image_storage_domain_map.image_id) -> Hash Left Join (cost=8694.48..10940.36 rows=10583 width=809) (actual time=156.926..264.747 rows=10731 loops=1) Hash Cond: (images.image_group_id = base_disks.disk_id) -> Merge Left Join (cost=6444.51..7077.88 rows=10583 width=231) (actual time=135.573..209.057 rows=10731 loops=1) Merge Cond: (images.image_group_id = vms_for_disk_view.device_id) -> Sort (cost=1714.94..1740.55 rows=10244 width=117) (actual time=40.745..48.222 rows=10731 loops=1) Sort Key: images.image_group_id Sort Method: external merge Disk: 1328kB -> Seq Scan on images (cost=0.00..399.06 rows=10244 width=117) (actual time=0.010..8.109 rows=10731 loops=1) Filter: (image_guid <> '00000000-0000-0000-0000-000000000000'::uuid) -> Materialize (cost=4729.57..5179.43 rows=10585 width=130) (actual time=94.817..142.118 rows=10704 loops=1) -> Subquery Scan vms_for_disk_view (cost=4729.57..5073.58 rows=10585 width=130) (actual time=94.811..135.035 rows=10704 loops=1) -> GroupAggregate (cost=4729.57..4967.73 rows=10585 width=33) (actual time=94.809..131.242 rows=10704 loops=1) -> Sort (cost=4729.57..4756.03 rows=10585 width=33) (actual time=94.778..99.859 rows=10704 loops=1) Sort Key: public.vm_device.device_id, public.vm_static.entity_type Sort Method: external merge Disk: 464kB -> Hash Join (cost=715.62..4021.98 rows=10585 width=33) (actual time=16.574..62.228 rows=10704 loops=1) Hash Cond: (public.vm_device.vm_id = public.vm_static.vm_guid) -> Seq Scan on vm_device (cost=0.00..3106.28 rows=10769 width=32) (actual time=0.016..33.019 rows=10704 loops=1) Filter: ((device)::text = 'disk'::text) -> Hash (cost=583.61..583.61 rows=10561 width=33) (actual time=16.509..16.509 rows=10753 loops=1) -> Seq Scan on vm_static (cost=0.00..583.61 rows=10561 width=33) (actual time=0.004..10.148 rows=10753 loo ps=1) -> Hash (cost=1309.43..1309.43 rows=10843 width=578) (actual time=20.639..20.639 rows=10731 loops=1) -> Seq Scan on base_disks (cost=0.00..1309.43 rows=10843 width=578) (actual time=0.029..10.562 rows=10731 loops=1) -> Hash (cost=1459.54..1459.54 rows=10854 width=48) (actual time=12.942..12.942 rows=10731 loops=1) -> Seq Scan on image_storage_domain_map (cost=0.00..1459.54 rows=10854 width=48) (actual time=0.023..8.304 rows=10731 loops=1) -> Hash (cost=3.29..3.29 rows=3 width=1068) (actual time=0.089..0.089 rows=4 loops=1) -> Hash Left Join (cost=2.18..3.29 rows=3 width=1068) (actual time=0.075..0.085 rows=4 loops=1) Hash Cond: (storage_pool_iso_map.storage_pool_id = public.storage_pool.id) -> Hash Left Join (cost=1.09..2.16 rows=3 width=1068) (actual time=0.041..0.046 rows=4 loops=1) Hash Cond: (storage_domain_static.id = storage_pool_iso_map.storage_id) -> Seq Scan on storage_domain_static (cost=0.00..1.03 rows=3 width=1052) (actual time=0.004..0.005 rows=4 loops=1) -> Hash (cost=1.04..1.04 rows=4 width=32) (actual time=0.012..0.012 rows=4 loops=1) -> Seq Scan on storage_pool_iso_map (cost=0.00..1.04 rows=4 width=32) (actual time=0.006..0.007 rows=4 loops=1) -> Hash (cost=1.04..1.04 rows=4 width=16) (actual time=0.011..0.011 rows=4 loops=1) -> Seq Scan on storage_pool (cost=0.00..1.04 rows=4 width=16) (actual time=0.007..0.008 rows=4 loops=1) -> Hash (cost=448.31..448.31 rows=10731 width=47) (actual time=12.963..12.963 rows=10731 loops=1) -> Seq Scan on disk_image_dynamic (cost=0.00..448.31 rows=10731 width=47) (actual time=0.006..5.192 rows=10731 loops=1) -> Hash (cost=1.04..1.04 rows=4 width=20) (actual time=0.012..0.012 rows=4 loops=1) -> Seq Scan on storage_pool (cost=0.00..1.04 rows=4 width=20) (actual time=0.006..0.006 rows=4 loops=1) -> Hash (cost=1240.39..1240.39 rows=10939 width=58) (actual time=16.122..16.122 rows=10752 loops=1) -> Seq Scan on snapshots (cost=0.00..1240.39 rows=10939 width=58) (actual time=0.023..9.411 rows=10752 loops=1) -> Hash (cost=11.00..11.00 rows=100 width=164) (actual time=0.002..0.002 rows=0 loops=1) -> Seq Scan on quota (cost=0.00..11.00 rows=100 width=164) (actual time=0.001..0.001 rows=0 loops=1) -> Subquery Scan "*SELECT* 2" (cost=4778.02..5561.31 rows=13760 width=1642) (actual time=48.444..48.444 rows=0 loops=1) -> Merge Right Join (cost=4778.02..5423.71 rows=13760 width=1642) (actual time=48.430..48.430 rows=0 loops=1) Merge Cond: (public.vm_device.device_id = dlm.disk_id) -> GroupAggregate (cost=4729.57..4967.73 rows=10585 width=33) (actual time=48.414..48.414 rows=1 loops=1) -> Sort (cost=4729.57..4756.03 rows=10585 width=33) (actual time=48.390..48.391 rows=2 loops=1) Sort Key: public.vm_device.device_id, public.vm_static.entity_type Sort Method: external merge Disk: 464kB -> Hash Join (cost=715.62..4021.98 rows=10585 width=33) (actual time=8.676..32.847 rows=10704 loops=1) Hash Cond: (public.vm_device.vm_id = public.vm_static.vm_guid) -> Seq Scan on vm_device (cost=0.00..3106.28 rows=10769 width=32) (actual time=0.020..17.892 rows=10704 loops=1) Filter: ((device)::text = 'disk'::text) -> Hash (cost=583.61..583.61 rows=10561 width=33) (actual time=8.632..8.632 rows=10753 loops=1) -> Seq Scan on vm_static (cost=0.00..583.61 rows=10561 width=33) (actual time=0.004..5.470 rows=10753 loops=1) -> Sort (cost=48.45..49.10 rows=260 width=1528) (actual time=0.013..0.013 rows=0 loops=1) Sort Key: dlm.disk_id Sort Method: quicksort Memory: 25kB -> Hash Join (cost=11.12..38.03 rows=260 width=1528) (actual time=0.001..0.001 rows=0 loops=1) Hash Cond: ((dlm.lun_id)::text = (l.lun_id)::text) -> Seq Scan on disk_lun_map dlm (cost=0.00..20.40 rows=1040 width=48) (actual time=0.001..0.001 rows=0 loops=1) -> Hash (cost=10.50..10.50 rows=50 width=1512) (never executed) -> Seq Scan on luns l (cost=0.00..10.50 rows=50 width=1512) (never executed) Total runtime: 2480.508 ms (95 rows)
So lets try adding the following indexes: create index i_vm_device_plugged on vm_device(is_plugged); create index i_vm_device_snapshot on vm_device(snapshot_id);
doesn't help what about the this sub query ? Subquery Scan vms_for_disk_view (cost=4729.57..5073.58 rows=10585 width=130) (actual time=94.811 or remove the group by lines?
Let's try. Please add this index: create index i_vm_device_device on vm_device(device); Can you send me in a mail your DB connection info, so I can test this for myself?
Created attachment 946306 [details] Function replacement for 3.4.2 v3
Eldad please check
there is no change same results.
Eldad can you please check?
+1 including this fix the SP execution time runs ~2sec.
It already run at ~2s...
Patch broke existing functionality. Reopening.
*** Bug 1168572 has been marked as a duplicate of this bug. ***
http://gerrit.ovirt.org/#/c/36376 is missing that bug reproduced in 3.5 VT13.7
*** Bug 1097160 has been marked as a duplicate of this bug. ***
this bug were not reproduced on vt14.1
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHSA-2015-0888.html