🥇Cosa tace EXPLAIN e come farlo parlare

Una domanda classica che i programmatori pongono al loro DBA o ai consulenti di business per PostgreSQL è quasi sempre la stessa: «Perché le query impiegano così tanto tempo a eseguire?»

Le ragioni tradizionali sono:

algoritmo inefficiente
quando hai deciso di fare un JOIN di diverse CTE su decine di migliaia di record
statistiche obsolete
se la distribuzione effettiva dei dati nella tabella è già molto diversa rispetto a quella raccolta dall'ANALYZE l'ultima volta
strozzature delle risorse
e non ci sono più sufficienti potenze computazionali della CPU, i gigabyte di memoria vengono utilizzati continuamente o il disco non riesce a tenere il passo con tutte le «richieste» del database
blocco da processi concorrenti

E se le serrature sono abbastanza complesse da catturare e analizzare, per tutto il resto abbiamo bisogno di un piano di query, che possiamo ottenere tramite l'operatore EXPLAIN (meglio, ovviamente, utilizzare subito EXPLAIN (ANALYZE, BUFFERS) …) o il modulo auto_explain.

Ma, come si dice nella stessa documentazione,

«Capire il piano è un'arte e per padroneggiarlo è necessaria una certa esperienza, …»

Ma possiamo cavarcela anche senza, se utilizziamo uno strumento adatto!

Come appare di solito un piano di query? Qualcosa del genere:

Index Scan using pg_class_relname_nsp_index on pg_class (tempo reale=0.049..0.050 righe=1 cicli=1)
  Condizione indice: (relname = $1)
  Filtro: (oid = $0)
  Buffer: hit condiviso=4
  InitPlan 1 (restituisce $0,$1)
    ->  Limit (tempo reale=0.019..0.020 righe=1 cicli=1)
          Buffer: hit condiviso=1
          ->  Seq Scan on pg_class pg_class_1 (tempo reale=0.015..0.015 righe=1 cicli=1)
                Filtro: (relkind = 'r'::"char")
                Righe rimosse dal filtro: 5
                Buffer: hit condiviso=1

o qualcosa del genere:

"Append  (costo=868.60..878.95 righe=2 larghezza=233) (tempo reale=0.024..0.144 righe=2 cicli=1)"
"  Buffer: hit condiviso=3"
"  CTE cl"
"    ->  Seq Scan on pg_class  (costo=0.00..868.60 righe=9972 larghezza=537) (tempo reale=0.016..0.042 righe=101 cicli=1)"
"          Buffer: hit condiviso=3"
"  ->  Limit  (costo=0.00..0.10 righe=1 larghezza=233) (tempo reale=0.023..0.024 righe=1 cicli=1)"
"        Buffer: hit condiviso=1"
"        ->  CTE Scan on cl  (costo=0.00..997.20 righe=9972 larghezza=233) (tempo reale=0.021..0.021 righe=1 cicli=1)"
"              Buffer: hit condiviso=1"
"  ->  Limit  (costo=10.00..10.10 righe=1 larghezza=233) (tempo reale=0.117..0.118 righe=1 cicli=1)"
"        Buffer: hit condiviso=2"
"        ->  CTE Scan on cl cl_1  (costo=0.00..997.20 righe=9972 larghezza=233) (tempo reale=0.001..0.104 righe=101 cicli=1)"
"              Buffer: hit condiviso=2"
"Tempo di pianificazione: 0.634 ms"
"Tempo di esecuzione: 0.248 ms"

Ma leggere il piano in forma testuale «a voce alta» è molto complicato e poco chiaro:

nel nodo viene visualizzato il totale delle risorse del sottoalbero
cioè, per capire quanto tempo è stato speso per l'esecuzione di un nodo specifico, o quanto precisamente questa lettura dalla tabella ha recuperato dati dal disco, è necessario sottrarre uno dall'altro
il tempo del nodo è necessario da moltiplicare per loops
sì, la sottrazione non è ancora l'operazione più complicata da fare 'nella mente' — poiché il tempo di esecuzione è indicato come una media per una singola esecuzione di un nodo, e potrebbero essercene centinaia
e tutto questo insieme rende difficile rispondere alla domanda principale — quindi chi è il 'collo di bottiglia'?

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

Ah, quindi, abbiamo bisogno di...

Strumento

In esso abbiamo cercato di raccogliere tutte le meccaniche chiave che aiutano a capire, in base al piano e alla richiesta, 'chi è colpevole e cosa fare'. Bene, e parte della nostra esperienza da condividere con la comunità.
Benvenuti e usate — explain.tensor.ru

Chiarezza dei piani

È facile capire un piano quando appare in questo modo?

Seq Scan on pg_class (tempo reale=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 molto.

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

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

E per le opzioni più complicate, c'è diagramma di esecuzione:

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

Suggerimenti strutturali

E se tutta la struttura del piano e i suoi punti critici sono già visibili, perché non evidenziarli per lo sviluppatore e non spiegarli in modo semplice?

Abbiamo già raccolto un certo numero di questi modelli di raccomandazioni.

Profiler di query riga per riga

Ora, se sovrapponiamo il piano analizzato alla query originale, possiamo vedere quanto tempo è stato impiegato per ogni singolo operatore — in questo modo:

… o anche in questo modo:

Sostituzione dei parametri nella query

Se hai "agganciato" al piano non solo la query, ma anche i suoi parametri dalla stringa DETAIL del log, puoi copiarlo anche in uno dei modi seguenti:

con la sostituzione dei valori nella query
per l'esecuzione diretta sul tuo database e un'ulteriore profilazione
```
SELECT 'const', 'param'::text;
```
con la sostituzione dei valori tramite PREPARE/EXECUTE
per simulare il funzionamento dello scheduler, quando la parte parametrica 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);
```