🥇Cosa tace EXPLAIN e come farlo parlare

La domanda classica che un sviluppatore pone al suo DBA o al proprietario dell'azienda — al consulente PostgreSQL — suona quasi sempre la stessa: «Perché le query impiegano così tanto tempo ad essere eseguite?»

L'insieme tradizionale di motivazioni:

algoritmo inefficiente
quando hai deciso di fare un JOIN di diverse CTE su un paio di decine di migliaia di record
statistiche non aggiornate
se la distribuzione effettiva dei dati nella tabella è già molto diversa rispetto a quella raccolta dall'ANALYZE l'ultima volta
colli di bottiglia nelle risorse
e non ci sono più potenze computazionali dedicate CPU, gigabyte di memoria vengono costantemente utilizzati o il disco non riesce a soddisfare tutte le «richieste» del DB
di blocco da processi concorrenti

E se i blocchi sono abbastanza complessi da catturare e analizzare, per tutto il resto ci basta il piano di esecuzione della query, che può essere ottenuto utilizzando l'operatore EXPLAIN (è meglio, ovviamente, usare subito EXPLAIN (ANALYZE, BUFFERS) …) oppure il modulo auto_explain.

Ma, come detto nella stessa documentazione,

«Capire il piano è un'arte e per dominarla occorre una certa esperienza, ...»

Ma si può fare anche senza, se si utilizza lo strumento giusto!

Come appare normalmente un piano di esecuzione? Più o meno in questo modo:

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

oppure così:

"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"

Ma leggere il piano come testo «da un foglio» è molto difficile e poco chiaro:

nel nodo viene mostrato il totale delle risorse del sottodrago
cioè per capire quanto tempo è stato impiegato per l'esecuzione di un nodo specifico, o quanto precisamente questa lettura dalla tabella abbia caricato dati dal disco — è necessario in qualche modo sottrarre uno dall'altro
il tempo del nodo è necessario moltiplicare per loops
sì, la sottrazione non è ancora l'operazione più complessa da fare "nella mente" — poiché il tempo di esecuzione è indicato come medio per un'esecuzione del nodo, e potrebbero esserci centinaia di essi
e tutto questo insieme rende difficile rispondere alla domanda principale — dunque chi è "il punto più debole"?

Quando abbiamo cercato di spiegare tutto questo a diverse centinaia dei nostri sviluppatori, ci siamo resi conto che esternamente appare più o meno così:

Quindi, abbiamo bisogno di...

Strumento

In esso abbiamo cercato di raccogliere tutte le meccaniche chiave che aiutano, secondo il piano e la richiesta, a capire "chi è il colpevole e cosa fare". Bene, e una parte della nostra esperienza da condividere con la comunità.
Incontrate e usate — explain.tensor.ru

Chiarezza dei piani

È facile comprendere un piano quando appare in questo modo?

Seq Scan on pg_class (tempo effettivo=0.009..1.304 righe=6609 cicli=1)
  Buffers: hit condivisi=263
Tempo di pianificazione: 0.108 ms
Tempo di esecuzione: 1.800 ms

Non proprio.

Ma in questo modo, in forma ridotta, quando gli indicatori chiave sono separati — è già molto più chiaro:

Ma se il piano è più complesso — ci aiuterà il grafico a torta della distribuzione del tempo per i nodi:

Bene, per i casi più complessi ci viene in soccorso il diagramma di esecuzione:

Ad esempio, ci sono situazioni abbastanza non banali in cui un piano può avere più di una radice effettiva:

Suggerimenti strutturali

Bene, se l'intera struttura del piano e i suoi punti critici sono già scomposti e visibili — perché non evidenziarli per lo sviluppatore e spiegare "in termini semplici"?

Abbiamo già raccolto una ventina di tali modelli di raccomandazione.

Profiler di query riga per riga

Ora, se sovrapponiamo il piano analizzato alla query originale, possiamo vedere quanto tempo è stato speso su ciascun singolo operatore — più o meno in questo modo:

… o anche così:

Sostituzione dei parametri nella query

Se hai "collegato" al piano non solo la query, ma anche i suoi parametri dalla riga DETAIL del log, puoi copiarla ulteriormente in una delle seguenti varianti:

con sostituzione dei valori nella query
per l'esecuzione diretta sul tuo database e ulteriori profili
```
SELECT 'const', 'param'::text;
```
con sostituzione dei valori tramite PREPARE/EXECUTE
per emulare il lavoro del pianificatore, quando la parte parametric di può essere ignorata — ad esempio, quando si lavora su tabelle partizionate
```
DEALLOCATE ALL;
PREPARE q(text) AS SELECT 'const', $1::text;
EXECUTE q('param'::text);
```