Webinaire - Juin 2021
(Pierre Giraud & Christophe Courtois)
Outil pour mieux comprendre et analyser des plans d’exécution.
Librairie JavaScript
utilisable :
Soumettre un plan, l’afficher.
https://github.com/agneum/plan-exporter
psql
postgres=# \o | plan-exporter --target dalibo
postgres=# explain select 1;
[…]
Posting to the visualizer...
The plan has been posted successfully.
URL: https://explain.dalibo.com/plan/XXX
Requête avec un prédicat sur un champ :
QUERY PLAN
------------------------------------------------
Seq Scan on product_data (cost=0.00..2583.00 rows=1 width=73) (actual time=0.027..8.598 rows=1 loops=1)
Filter: (organization_id = '00032877-ec6a-4d21-bfb4-864c307a5ecb'::text)
Rows Removed by Filter: 99999
Planning Time: 0.051 ms
Execution Time: 8.657 ms
(5 rows)
QUERY PLAN
------------------------------------------------
Index Scan using product_data_organization_id_idx on product_data (cost=0.42..8.44 rows=1 width=73) (actual time=0.040..0.055 rows=1 loops=1)
Index Cond: (organization_id = '00032877-ec6a-4d21-bfb4-864c307a5ecb'::text)
Planning Time: 0.237 ms
Execution Time: 0.216 ms
(4 rows)
Gros plan un peu complexe :
Merge Right Join (cost=10086.13..15466.11 rows=44275 width=974) (actual time=14228.389..14242.194 rows=2216 loops=1)
Merge Cond: (mike.uniform_foxtrot = two_romeo.tango_foxtrot)
Buffers: shared hit=7136483 read=854 dirtied=5, temp read=8401 written=8389
I/O Timings: read=188.443
CTE six_lima
-> GroupAggregate (cost=7673.62..8271.22 rows=5312 width=630) (actual time=59.103..63.169 rows=2216 loops=1)
Group Key: kilo_foxtrot.tango_foxtrot, oscar_mike1.tango_foxtrot, alpha_quebec.tango_foxtrot, (CASE WHEN $0 THEN ((lima_sierra(lima_four((alpha_quebec.sierra_sierra)::text, ''juliet_alpha' 'tango_golf' '::text) || (alpha_quebec.juliet_five_echo)::text) (...)
Buffers: shared hit=3271 read=22
I/O Timings: read=0.209
InitPlan
-> Nested Loop (cost=0.00..7.85 rows=1 width=1) (actual time=0.062..0.062 rows=0 loops=1)
Join Filter: (papa_india.quebec_oscar = kilo_hotel.tango_foxtrot)
Rows Removed by Join Filter: 66
Buffers: shared hit=5
-> Seq Scan on india_six kilo_hotel (cost=0.00..2.37 rows=1 width=4) (actual time=0.015..0.032 rows=1 loops=1)
Filter: ((hotel_papa)::name = session_user())
Rows Removed by Filter: 77
Buffers: shared hit=1
-> Seq Scan on kilo_bravo papa_india (cost=0.00..4.66 rows=66 width=5) (actual time=0.003..0.013 rows=66 loops=1)
Buffers: shared hit=4
-> Sort (cost=7665.77..7679.05 rows=5312 width=637) (actual time=59.081..59.297 rows=2216 loops=1)
Sort Key: kilo_foxtrot.tango_foxtrot, alpha_quebec.tango_foxtrot, (CASE WHEN $0 THEN ((lima_sierra(lima_four((alpha_quebec.sierra_sierra)::text, ''juliet_alpha' 'tango_golf' '::text) || (alpha_quebec.juliet_five_echo)::text) END), tango_mike_bravo (...)
Sort Method: quicksort Memory: 1239kB
Buffers: shared hit=3271 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=6658.06..7337.09 rows=5312 width=637) (actual time=48.143..56.245 rows=2216 loops=1)
Hash Cond: (six_five.tango_foxtrot = five_hotel.tango_foxtrot)
Buffers: shared hit=3265 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=6394.15..6845.25 rows=4117 width=574) (actual time=48.024..53.306 rows=2216 loops=1)
Hash Cond: (golf_victor.tango_foxtrot = four_xray_juliet.tango_foxtrot)
Buffers: shared hit=3256 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=6130.24..6528.20 rows=3191 width=535) (actual time=47.924..52.303 rows=2216 loops=1)
Hash Cond: (papa_kilo.tango_foxtrot = india_two_golf.tango_foxtrot)
Buffers: shared hit=3240 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=5866.32..6250.80 rows=3191 width=539) (actual time=47.899..51.603 rows=2216 loops=1)
Hash Cond: (kilo_foxtrot.seven_hotel = lima_juliet.tango_foxtrot)
Buffers: shared hit=3237 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=5865.28..6209.47 rows=3191 width=505) (actual time=47.881..50.869 rows=2216 loops=1)
Hash Cond: (kilo_foxtrot.hotel_seven = kilo_tango.tango_foxtrot)
Buffers: shared hit=3236 read=22
I/O Timings: read=0.209
-> Hash Left Join (cost=4147.38..4448.01 rows=3191 width=446) (actual time=41.248..43.311 rows=2216 loops=1)
Hash Cond: (kilo_foxtrot.three_romeo_sierra = november_mike.tango_foxtrot)
Buffers: shared hit=2571 read=22
I/O Timings: read=0.209
[…]
-> Sort (cost=60.08..62.58 rows=1000 width=136) (actual time=12705.096..12705.178 rows=1272 loops=1)
Sort Key: november_uniform.uniform_foxtrot
Sort Method: quicksort Memory: 148kB
Buffers: shared hit=5770068 read=100, temp read=4331 written=4325
I/O Timings: read=67.367
-> Function Scan on five_zulu november_uniform (cost=0.25..10.25 rows=1000 width=136) (actual time=12704.656..12704.824 rows=1272 loops=1)
Buffers: shared hit=5770068 read=100, temp read=4331 written=4325
I/O Timings: read=67.367
Planning time: 55.406 ms
Execution time: 14244.278 ms
Beaucoup de temps passé dans un nœud “Function Scan”
Le nœud en détail :
La fonction lit 44Go de données en cache.
Le reste n’a pas d’importance.
Solution : revoir le code de la fonction elle-même.
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------
Nested Loop Semi Join (cost=9866.25..490324.00 rows=1 width=8) (actual time=12270.481..12270.481 rows=0 loops=1)
Join Filter: (node.id = prop_4.node_id)
Buffers: shared hit=750059 read=575209 written=224
-> Nested Loop Semi Join (cost=9865.42..490315.41 rows=1 width=56) (actual time=12270.481..12270.481 rows=0 loops=1)
Buffers: shared hit=750059 read=575209 written=224
-> Nested Loop Semi Join (cost=9864.59..490307.21 rows=1 width=48) (actual time=12270.477..12270.477 rows=0 loops=1)
Join Filter: (node.id = prop_2.node_id)
Buffers: shared hit=750059 read=575209 written=224
-> Nested Loop Semi Join (cost=9863.76..490298.62 rows=1 width=40) (actual time=12270.468..12270.468 rows=0 loops=1)
Buffers: shared hit=750059 read=575209 written=224
-> Nested Loop Semi Join (cost=9862.93..490290.41 rows=1 width=32) (actual time=12270.455..12270.455 rows=0 loops=1)
Join Filter: (node.id = prop.node_id)
Buffers: shared hit=750059 read=575209 written=224
-> Nested Loop Semi Join (cost=9862.10..490281.83 rows=1 width=24) (actual time=12257.875..12269.108 rows=96 loops=1)
Buffers: shared hit=749544 read=575148 written=224
-> Nested Loop (cost=9861.52..490251.89 rows=17 width=16) (actual time=12257.706..12266.990 rows=96 loops=1)
Buffers: shared hit=749204 read=574973 written=224
-> HashAggregate (cost=63.80..64.30 rows=50 width=8) (actual time=19.649..19.782 rows=342 loops=1)
Group Key: prop_5.node_id
Buffers: shared hit=136 read=155
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_5 (cost=0.83..63.68 rows=50 width=8) (actual time=16.098..19.53
9 rows=342 loops=1)
Index Cond: ((qname_id = '649'::bigint) AND (string_value = '01121298'::text))
Heap Fetches: 257
Buffers: shared hit=136 read=155
-> Index Scan using alf_node_pkey on alf_node node (cost=9797.72..9803.74 rows=1 width=8) (actual time=35.810..35.810 rows=0 loops=342)
Index Cond: (id = prop_5.node_id)
Filter: ((type_qname_id <> '145'::bigint) AND (NOT (hashed SubPlan 1)) AND (store_id = '6'::bigint))
Rows Removed by Filter: 1
Buffers: shared hit=749068 read=574818 written=224
SubPlan 1
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_6 (cost=0.83..9776.84 rows=8123 width=8) (actual time=0.118..
11052.664 rows=2017906 loops=1)
Index Cond: ((qname_id = '377'::bigint) AND (string_value = 'EXLIBRIS_PROCESSED'::text))
Heap Fetches: 1093606
Buffers: shared hit=747762 read=574388 written=224
-> Index Only Scan using alf_node_aspects_pkey on alf_node_aspects aspect (cost=0.57..10.78 rows=9 width=8) (actual time=0.021..0.021 rows=1 loo
ps=96)
Index Cond: ((node_id = node.id) AND (qname_id = '266'::bigint))
Heap Fetches: 67
Buffers: shared hit=340 read=175
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop (cost=0.83..4.70 rows=1 width=8) (actual time=0.013..0.013 rows=0 loops=96)
Index Cond: ((qname_id = '260'::bigint) AND (string_value = 'GEDUP'::text) AND (node_id = aspect.node_id))
Heap Fetches: 0
Buffers: shared hit=515 read=61
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_1 (cost=0.83..4.72 rows=1 width=8) (never executed)
Index Cond: ((qname_id = '265'::bigint) AND (string_value = 'MR'::text) AND (node_id = node.id))
Heap Fetches: 0
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_2 (cost=0.83..4.70 rows=1 width=8) (never executed)
Index Cond: ((qname_id = '258'::bigint) AND (string_value = 'Facture'::text) AND (node_id = aspect.node_id))
Heap Fetches: 0
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_3 (cost=0.83..4.72 rows=1 width=8) (never executed)
Index Cond: ((qname_id = '264'::bigint) AND (string_value = 'FIDEXP'::text) AND (node_id = node.id))
Heap Fetches: 0
-> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop_4 (cost=0.83..4.70 rows=1 width=8) (never executed)
Index Cond: ((qname_id = '257'::bigint) AND (string_value = 'FactureImmobilisation'::text) AND (node_id = aspect.node_id))
Heap Fetches: 0
Planning time: 9.554 ms
Execution time: 12287.688 ms
(56 lignes)
heap fetches
sur 2 millions de lignes pour un Index Only Scan
! et pas qu’en cacheVACUUM ANALYZE
urgent !https://explain.dalibo.com/plan/eQP
Durée 1h37 !
Seq scan
*_collapse_limit
pour chercher de meilleurs plans
Avant :
Après :
-> planification x 7, durée totale / 5513 !
Unique (cost=945.99..946.07 rows=16 width=4) (actual time=2176.085..2176.092 rows=21 loops=1)
Buffers: shared hit=15823
-> Sort (cost=945.99..946.03 rows=16 width=4) (actual time=2176.083..2176.085 rows=45 loops=1)
Sort Key: soc2_.idsoc
Sort Method: quicksort Memory: 27kB
Buffers: shared hit=15823
-> Nested Loop (cost=10.10..945.67 rows=16 width=4) (actual time=123.211..2176.033 rows=45 loops=1)
Buffers: shared hit=15823
-> Nested Loop (cost=9.67..936.72 rows=16 width=4) (actual time=123.189..2175.738 rows=45 loops=1)
Buffers: shared hit=15684
-> Bitmap Heap Scan on area area0_ (cost=9.26..577.48 rows=43 width=4) (actual time=123.155..2173.905 rows=232 loops=1)
Recheck Cond: (geometrie && '0103000020E6100000010000002B000000F05C5F414D5003400CB7CA8872734840EF5C5F418B4E0340C0E1882A63734840F05C5F612E4F03402075AB3B5C734840F05C5F51994E03409847BF1258734840EF5C5F91694D0340B000D5765C734840E949BD1F5C4103403C66DD16FC724840E649BD9FE8430340A4508015DF724840CB21763C024303401825B423D9724840CA2176DC833F0340241B00E2FA724840CB21765C894103405C9CC2E709734840E649BD1F7B400340645EFFED117348400105B3918F3F03407C3815B71D7348400105B351113A03407C300E02487348400105B3D10E350340C00E22FD6F7348400005B3B103330340300BE1147B734840F238DE72FC2F0340D0E68105817348400105B3B10C2A0340E006534E417348400005B331F32C0340A02566901F7348400605B39117300340AC213885FB7248400705B3B17F2F03404C556697F77248400005B391B5280340A06EFFD7407348400105B3B19E2E03409074F63F857348400105B3511D20340ECDE68F57348409B12AEBD02340340E04B7F1DBF7448409B12AEBD1E3603406C0E1D8EAD7448400705B3E9A828034010AECA35F47348400605B3B9D52B034090A3B43ED57348409C12AEFDCD2803407413964CB07348400505B3B1252F034028BD7C088C7348400405B3714135034090A5E948D2734840C52176BCEB4203409467EEFD79734840C421767CD2410340B0E0E30C6D7348400405B3D16835034094B1BBE1C47348400505B351933003400CB70AF4897348400405B3F10B360340380304F1777348400605B33144360340C473A01673734840C52176BC0D3F0340FC5896932F734840CA21763C7B420340D486DE7412734840CA2176FC9E4F034064BDF69A78734840F05C5F414D5003400CB7CA8872734840'::geometry)
Filter: (_st_intersects(geometrie, '0103000020E6100000010000002B000000F05C5F414D5003400CB7CA8872734840EF5C5F418B4E0340C0E1882A63734840F05C5F612E4F03402075AB3B5C734840F05C5F51994E03409847BF1258734840EF5C5F91694D0340B000D5765C734840E949BD1F5C4103403C66DD16FC724840E649BD9FE8430340A4508015DF724840CB21763C024303401825B423D9724840CA2176DC833F0340241B00E2FA724840CB21765C894103405C9CC2E709734840E649BD1F7B400340645EFFED117348400105B3918F3F03407C3815B71D7348400105B351113A03407C300E02487348400105B3D10E350340C00E22FD6F7348400005B3B103330340300BE1147B734840F238DE72FC2F0340D0E68105817348400105B3B10C2A0340E006534E417348400005B331F32CFFD7407348400105B3B19E2E03409074F63F857348400105B3511D2E0340ECDE685487734840F338DE32A02603408C76F0EDAC7348400605B389CA2A034064277165D37348400305B32145270340A0635D6CF57348409B12AEBD02340340E04B7F1DBF7448409B12AEBD1E3603406C0E1D8EAD7448400705B3E9A828034010AECA35F47348400605B3B9D52B034090A3B43ED57348409C12AEFDCD2803407413964CB07348400505B3B1252F034028BD7C088C7348400405B3714135034090A5E948D2734840C52176BCEB4203409467EEFD79734840C421767CD2410340B0E0E30C6D7348400405B3D16835034094B1BBE1C47348400505B351933003400CB70AF4897348400405B3F10B360340380304F1777348400605B33144360340C473A01673734840C52176BC0D3F0340FC5896932F734840CA21763C7B420340D486DE7412734840CA2176FC9E4F034064BDF69A78734840F05C5F414D5003400CB7CA8872734840'::geometry) AND ((NOT (geometrie && '0103000020E6100000010000002B000000F05C5F414D5003400CB7CA8872734840EF5C5F418B4E0340C0E1882A63734840F05C5F612E4F03402075AB3B5C734840F05C5F51994E03409847BF1258734840EF5C5F91694D0340B000D5765C734840E949BD1F5C4103403C66DD16FC724840E649BD9FE8430340A4508015DF724840CB21763C024303401825B423D9724840CA2176DC833F0340241B00E2FA724840CB21765C894103405C9CC2E709734840E649BD1F7B400340645EFFED117348400105B3918F3F03407C3815B71D7348400105B351113A03407C300E02487348400105B3D10E350340C00E22E006534E417348400005B331F32C0340A02566901F7348400605B39117300340AC213885FB7248400705B3B17F2F03404C556697F77248400005B391B5280340A06EFFD7407348400105B3B19E2E03409074F63F857348400105B3511D2E0340ECDE685487734840F338DE32A02603408C76F0EDAC7348400605B389CA2A034064277165D37348400305B32145270340A0635D6CF57348409B12AEBD02340340E04B7F1DBF7448409B12AEBD1E3603406C0E1D8EAD7448400705B3E9A828034010AECA35F47348400605B3B9D52B034090A3B43ED57348409C12AEFDCD2803407413964CB07348400505B3B1252F034028BD7C088C7348400405B3714135034090A5E948D2734840C52176BCEB4203409467EEFD79734840C421767CD2410340B0E0E30C6D7348400405B3D16835034094B1BBE1C47348400505B351933003400CB70AF4897348400405B3F10B360340380304F1777348400605B33144360340C473A01673734840C52176BC0D3F0340FC5896932F734840CA21763C7B420340D486DE7412734840CA2176FC9E4F034064BDF69A78734840F05C5F414D5003400CB7CA8872734840'::geometry)) OR (NOT _st_touches(geometrie, '0103000020E6100000010000002B000000F05C5F414D5003400CB7CA8872734840EF5C5F418B4E0340C0E1882A63734840F05C5F612E4F03402075AB3B5C734840F05C5F51994E03409847BF1258734840EF5C5F91694D0340B000D5765C734840E949BD1F5C4103403C66DD16FC724840E649BD9FE8430340A4508015DF724840CB21763C024303401825B423D9724840CA2176DC833F0340241B00E2FA724840CB21765C894103405C9CC2E709734840E649BD1F7B400340645EFFED117348400105B3918F3F03407C3815B71D7348400105B351113A03407C300E02487348400105B3D10E350340C00E22FD2A0340E006534E417348400005B331F32C0340A02566901F7348400605B39117300340AC213885FB7248400705B3B17F2F03404C556697F77248400005B391B5280340A06EFFD7407348400105B3B19E2E03409074F63F857348400105B3511D2E0340ECDE685487734840F338DE32A02603408C76F0EDAC7348400605B389CA2A034064277165D37348400305B32145270340A0635D6CF57348409B12AEBD02340340E04B7F1DBF7448409B12AEBD1E3603406C0E1D8EAD7448400705B3E9A828034010AECA35F47348400605B3B9D52B034090A3B43ED57348409C12AEFDCD2803407413964CB07348400505B3B1252F034028BD7C088C7348400405B3714135034090A5E948D2734840C52176BCEB4203409467EEFD79734840C421767CD2410340B0E0E30C6D7348400405B3D16835034094B1BBE1C47348400505B351933003400CB70AF4897348400405B3F10B360340380304F1777348400605B33144360340C473A01673734840C52176BC0D3F0340FC5896932F734840CA21763C7B420340D486DE7412734840CA2176FC9E4F034064BDF69A78734840F05C5F414D5003400CB7CA8872734840'::geometry))))
Rows Removed by Filter: 443
Heap Blocks: exact=531
Buffers: shared hit=14749
-> Bitmap Index Scan on idx_area_geometry (cost=0.00..9.25 rows=128 width=0) (actual time=0.436..0.436 rows=692 loops=1)
Index Cond: (geometrie && '0103000020E6100000010000002B000000F05C5F414D5003400CB7CA8872734840EF5C5F418B4E0340C0E1882A63734840F05C5F612E4F03402075AB3B5C734840F05C5F51994E03409847BF1258734840EF5C5F91694D0340B000D5765C734840E949BD1F5C4103403C66DD16FC724840E649BD9FE8430340A4508015DF724840CB21763C024303401825B423D9724840CA2176DC8A724840CB21765C894103405C9CC2E709734840E649BD1F7B400340645EFFED117348400105B3918F3F03407C3815B71D7348400105B351113A03407C300E02487348400105B3D10E350340C00E22FD6F7348400005B3B103330340300BE1147B734840F238DE72FC2F0340D0E68105817348400105B3B10C2A0340E006534E417348400005B331F32C0340A02566901F7348400605B39117300340AC213885FB7248400705B3B17F2F03404C556697F77248400005B391B5280340A06EFFD7407348400105B3B19E2E03409074F63F857348400105B3511D2E0340ECDE685487734840F338DE32A02603408C76F0EDAC7348400605B389CA2A034064277165D37348400305B32145270340A0635D6CF57348409B12AEBD02340340E04B7F1DBF7448409B12AEBD1E3603406C0E1D8EAD7448400705B3E9A828034010AECA35F47348400605B3B9D52B034090A3B43ED57348409C12AEFDCD2803407413964CB07348400505B3B1252F034028BD7C088C7348400405B3714135034090A5E948D2734840C52176BCEB4203409467EEFD79734840C421767CD2410340B0E0E30C6D7348400405B3D16835034094B1BBE1C47348400505B351933003400CB70AF4897348400405B3F10B360340380304F1777348400605B33144360340C473A01673734840C52176BC0D3F0340FC5896932F734840CA21763C7B420340D486DE7412734840CA2176FC9E4F034064BDF69A78734840F05C5F414D5003400CB7CA8872734840'::geometry)
Buffers: shared hit=28
-> Index Scan using feature_pk on feature feature1_ (cost=0.42..8.34 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=232)
Index Cond: (idfeature = area0_.idfeature)
Filter: (statut = 1)
Rows Removed by Filter: 1
Buffers: shared hit=935
-> Index Only Scan using soc_pk on soc soc2_ (cost=0.42..0.55 rows=1 width=4) (actual time=0.005..0.005 rows=1 loops=45)
Index Cond: (idsoc = feature1_.idsoc)
Heap Fetches: 3
Buffers: shared hit=139
Planning time: 0.837 ms
Execution time: 2177.841 ms
(30 lignes)
La condition d’index “intersection sur index Gist
” est une bonne piste de recherche
Sort (cost=514434.59..514848.36 rows=165508 width=80) (actual time=7289.040..7292.531 rows=61429 loops=1)
Sort Key: zulu_tango_mike.india_victor
Sort Method: quicksort Memory: 10175kB
-> Append (cost=5.11..500087.90 rows=165508 width=80) (actual time=7161.463..7272.203 rows=61429 loops=1)
-> Bitmap Heap Scan on oscar_foxtrot_seven zulu_tango_mike (cost=5.11..694.62 rows=179 width=80) (actual time=0.025..0.025 rows=0 loops=1)
Recheck Cond: (((india_delta_alpha)::text = 'golf_alpha_golf'::text) AND (seven_papa = 'four_uniform_quebec'::smallint) AND (india_victor >= 'xray_sierra'::timestamp without time zone))
Planning time: 28.760 ms
JIT:
Functions: 560
Options: Deforming true, Optimization true, Expressions true, Inlining true
Timing: Total 7261.174 ms, Optimization 4409.715 ms, Generation 110.757 ms, Inlining 28.595 ms, Emission 2712.107 ms
Execution time: 7408.726 ms
Solution :
Modification du paramètre de configuration Postgres jit_optimize_above_cost
De 500 000 à 1 000 000
Réponse du client :
« Effectivement, après modification de l’option, on retrouve des perfs honorables. Parfait ! »
Github : github.com/dalibo/pev2
Pierre Giraud : @pgira
Christophe Courtois : @krysztophe