[EXPLAIN] Déchiffrer un plan d’exécution grâce à PEV2 (exemples concrets)

Webinaire - Juin 2021

(Pierre Giraud & Christophe Courtois)

PEV2: kézako ?

« PostgreSQL Explain Visualizer 2 »

Outil pour mieux comprendre et analyser des plans d’exécution.

Librairie JavaScript

utilisable :

  • mode standalone pev2.tar.gz
  • comme composant dans un autre outil
  • ou via le service :

explain.dalibo.com

Exemple 0 : Aperçu rapide

Usage

Soumettre un plan, l’afficher.

https://explain.dalibo.com/plan/BRw

Utilitaires

https://github.com/agneum/plan-exporter

  • soit dans 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
  • soit dans votre terminal
$ psql -f my_explain_file.sql | plan-exporter --target=dalibo --auto-confirm
Welcome to the query plan exporter. Target: dalibo.
[…]
Posting to the visualizer...
The plan has been posted successfully.
URL: https://explain.dalibo.com/plan/EH

Exemple 1

Requête avec un prédicat sur un champ :

SELECT * FROM product_data
WHERE organization_id = '00032877-ec6a4d21-bfb4-864c307a5ecb';
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)

https://explain.dalibo.com/plan/5Kf

Ajout d’un index

CREATE INDEX ON product_data(organization_id);

Nouveau plan

SELECT * FROM product_data
WHERE organization_id = '00032877-ec6a4d21-bfb4-864c307a5ecb';
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)

https://explain.dalibo.com/plan/PZH

Exemple 2

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

https://explain.dalibo.com/plan/V8Wl

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.

Exemple 3

                                                                                                    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)

https://explain.dalibo.com/plan/YV8

  • -> 1 million de heap fetches sur 2 millions de lignes pour un Index Only Scan ! et pas qu’en cache
  • -> des sous-estimations de lignes énormes
  • => VACUUM ANALYZE urgent !

Exemple 4

https://explain.dalibo.com/plan/eQP

Durée 1h37 !

  • 6,34 To lus dans un Seq scan
  • Filtre inefficace -> envie d’index

Solution ?

*_collapse_limit pour chercher de meilleurs plans

Avant :

  • Planning Time: 26.370 ms
  • Execution Time: 5850945.494 ms (~1h 37m)

Après :

  • Planning Time: 189.391 ms
  • Execution Time: 1061.245 ms (~1s)

-> planification x 7, durée totale / 5513 !

Exemple 5

 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)

https://explain.dalibo.com/plan/AnC

La condition d’index “intersection sur index Gist” est une bonne piste de recherche

Exemple 6

 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

https://explain.dalibo.com/plan/6fP

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 ! »

Contacts

Github : github.com/dalibo/pev2

Pierre Giraud : @pgira

Christophe Courtois : @krysztophe