🥇Hvad EXPLAIN ikke siger, og hvordan man får det til at tale

Det klassiske spørgsmål, som en udvikler næsten altid stiller sin DBA eller virksomhedsejer – til PostgreSQL-konsulenten – lyder næsten altid ens: «Hvorfor kører forespørgslerne så længe på databasen?»

Et traditionelt sæt årsager:

ineffektiv algoritme
når du besluttede at lave en JOIN af flere CTE'er med par af titusinder af poster
forældet statistik
hvis den faktiske fordeling af data i tabellen allerede adskiller sig meget fra det, der blev samlet med ANALYZE sidst
«flaskehals» af ressourcer
og der ikke er nok dedikerede beregningskræfter fra CPU'en, man får konstant millioner af hukommelsesgigabytes eller disken kan ikke følge med alle database «ønsker»
låsninger fra konkurrerende processer

Og hvis låsninger er ret svære at indfange og analysere, så kræver alt andet bare forespørgselsplanen, som kan opnås med EXPLAIN-sætningen (bedst med det samme EXPLAIN (ANALYZE, BUFFERS) …) eller auto_explain-modulet.

Men som nævnt i den samme dokumentation,

«At forstå planen er en kunst, og for at mestre det kræves en vis erfaring, …»

Men man kan også klare sig uden det, hvis man bruger det rette værktøj!

Hvordan ser en forespørgselsplan normalt ud? Nogenlunde sådan:

Index Scan using pg_class_relname_nsp_index on pg_class (actual time=0.049..0.050 rows=1 loops=1)
  Index Cond: (relname = $1)
  Filter: (oid = $0)
  Buffers: shared hit=4
  InitPlan 1 (returns $0,$1)
    ->  Limit (actual time=0.019..0.020 rows=1 loops=1)
          Buffers: shared hit=1
          ->  Seq Scan on pg_class pg_class_1 (actual time=0.015..0.015 rows=1 loops=1)
                Filter: (relkind = 'r'::"char")
                Rows Removed by Filter: 5
                Buffers: shared hit=1

eller sådan her:

"Append  (cost=868.60..878.95 rows=2 width=233) (actual time=0.024..0.144 rows=2 loops=1)"
"  Buffers: shared hit=3"
"  CTE cl"
"    ->  Seq Scan on pg_class  (cost=0.00..868.60 rows=9972 width=537) (actual time=0.016..0.042 rows=101 loops=1)"
"          Buffers: shared hit=3"
"  ->  Limit  (cost=0.00..0.10 rows=1 width=233) (actual time=0.023..0.024 rows=1 loops=1)"
"        Buffers: shared hit=1"
"        ->  CTE Scan on cl  (cost=0.00..997.20 rows=9972 width=233) (actual time=0.021..0.021 rows=1 loops=1)"
"              Buffers: shared hit=1"
"  ->  Limit  (cost=10.00..10.10 rows=1 width=233) (actual time=0.117..0.118 rows=1 loops=1)"
"        Buffers: shared hit=2"
"        ->  CTE Scan on cl cl_1  (cost=0.00..997.20 rows=9972 width=233) (actual time=0.001..0.104 rows=101 loops=1)"
"              Buffers: shared hit=2"
"Planning Time: 0.634 ms"
"Execution Time: 0.248 ms"

Men at læse planen direkte fra teksten er meget svært og uklar:

i noden vises summen af ressourcerne fra undertræet
Det vil sige, for at forstå, hvor lang tid det tog at udføre den specifikke knude, eller hvor meget denne læsning fra tabellen hentede data fra disken — skal man på en eller anden måde trække det ene fra det andet.
Tiden for knuden er nødvendig. At multiplicere med loops.
Ja, subtraktion er endnu ikke den mest komplekse operation, man skal lave "i hovedet" — for den oplyste udførelsestid er gennemsnitlig for én udførelse af knuden, og der kan være hundreder af dem.
Og alt dette sammen gør det svært at svare på det vigtigste spørgsmål — så hvem er det? "Det svageste link".?

Da vi forsøgte at forklare alt dette til flere hundrede af vores udviklere, indså vi, at det fra siden ser cirka sådan her ud:

Så, vi har brug for…

Værktøj

I det har vi forsøgt at samle alle nøgleværktøjer, der hjælper med at forstå "hvem der er skyld i hvad, og hvad der skal gøres". Og at dele en del af vores erfaring med samfundet.
Mødt og brugt — explain.tensor.ru

Overskuelighed i planer

Er det let at forstå planen, når den ser sådan ud?

Seq Scan on pg_class (aktuel tid=0.009..1.304 rækker=6609 loops=1)
  Buffers: shared hit=263
Planlægningstid: 0.108 ms
Udførelsestid: 1.800 ms

Ikke rigtig.

Men sådan her, i forkortet form,, når nøgletal er adskilt — er det allerede meget klarere:

Men hvis planen er mere kompleks — vil cirkeldiagram over tidsfordelingen for knuderne hjælpe:

Og for de mest komplekse varianter kommer udførelsesdiagrammet:

For eksempel er der tilfælde, hvor planen kan have mere end én reel rod:

Strukturelle hints

Men hvis hele strukturen af planen og dens svage punkter allerede er opdelt og synlige — hvorfor ikke fremhæve dem for udvikleren og forklare "på menneskesprog"?

Vi har allerede samlet et par dusin sådanne anbefalingsskabeloner.

Linje-for-linje profilerer af forespørgsler

Nu, hvis man lægger den analyserede plan oven på den oprindelige forespørgsel, kan man se, hvor meget tid der gik på hver enkelt operator — omtrent sådan her:

… eller endda sådan her:

Parameterindsætning i forespørgslen

Hvis du har "hæftet" forespørgslen til planen, men også dens parametre fra DETAIL-strengen i loggen, kan du kopiere den yderligere i en af varianterne:

med indsat værdier i forespørgslen
for direkte udførelse på din egen database og videre profilering.
```
SELECT 'const', 'param'::text;
```
med indsat værdier via PREPARE/EXECUTE.
til at simulere planlæggerens arbejde, når den parameteriske del kan ignoreres — for eksempel ved arbejde med sektionerede tabeller
```
DEALLOCATE ALL;
PREPARE q(text) AS SELECT 'const', $1::text;
EXECUTE q('param'::text);
```