Bug 1141543
| Summary: | [scale] - getdisksvmguid hit the performance due to all_disks_including_snapshots view | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Eldad Marciano <emarcian> | ||||||||||
| Component: | ovirt-engine | Assignee: | Liran Zelkha <lzelkha> | ||||||||||
| Status: | CLOSED ERRATA | QA Contact: | Eldad Marciano <emarcian> | ||||||||||
| Severity: | high | Docs Contact: | |||||||||||
| Priority: | unspecified | ||||||||||||
| Version: | 3.4.1-1 | CC: | aberezin, amureini, bazulay, ecohen, emarcian, gklein, lpeer, oourfali, pstehlik, rbalakri, Rhev-m-bugs, tspeetje, yeylon | ||||||||||
| Target Milestone: | --- | Keywords: | ZStream | ||||||||||
| Target Release: | 3.5.1 | ||||||||||||
| Hardware: | x86_64 | ||||||||||||
| OS: | Linux | ||||||||||||
| Whiteboard: | infra | ||||||||||||
| Fixed In Version: | org.ovirt.engine-root-3.5.1-1 | Doc Type: | Bug Fix | ||||||||||
| Doc Text: | Story Points: | --- | |||||||||||
| Clone Of: | |||||||||||||
| : | 1155573 (view as bug list) | Environment: | |||||||||||
| Last Closed: | 2015-04-28 18:40:32 UTC | Type: | Bug | ||||||||||
| Regression: | --- | Mount Type: | --- | ||||||||||
| Documentation: | --- | CRM: | |||||||||||
| Verified Versions: | Category: | --- | |||||||||||
| oVirt Team: | Infra | RHEL 7.3 requirements from Atomic Host: | |||||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||||
| Embargoed: | |||||||||||||
| Bug Depends On: | |||||||||||||
| Bug Blocks: | 1155573, 1156162, 1186763, 1193058, 1197441 | ||||||||||||
| Attachments: |
|
||||||||||||
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? 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 |
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: