🥇O czym milczy EXPLAIN, i jak go przekonać do mówienia

Klasyczne pytanie, które programista zadaje swojemu DBA lub właścicielowi firmy – konsultantowi PostgreSQL – prawie zawsze brzmi tak samo: „Dlaczego zapytania tak długo się wykonują?”

Tradycyjny zestaw powodów:

nieefektywny algorytm
kiedy zdecydowałeś się połączyć kilka CTE z parą dziesiątek tysięcy rekordów
nieaktualna statystyka
jeśli rzeczywisty rozkład danych w tabeli już znacznie różni się od tego, co zostało zebrane podczas ostatniej ANALYZE
„wąskie gardło” pod względem zasobów
i już brakuje przydzielonej mocy obliczeniowej CPU, stale zwiększa się zużycie pamięci lub dysk nie nadąża za wszystkimi „chceniówkami” bazy danych
blokowania od konkurujących procesów

A jeśli blokady są wystarczająco skomplikowane do uchwycenia i analizy, to w przypadku wszystkiego innego wystarczy nam plan zapytania, który można uzyskać za pomocą operatora EXPLAIN (lepiej, oczywiście, od razu EXPLAIN (ANALYZE, BUFFERS) …) lub modułu auto_explain.

Jednak, jak powiedziano w tej samej dokumentacji,

„Zrozumienie planu to sztuka, a żeby ją opanować, potrzebne jest pewne doświadczenie, …”

Ale można się obejść bez niego, jeśli skorzystasz z odpowiedniego narzędzia!

Jak zazwyczaj wygląda plan zapytania? Tak właśnie:

Scan indeksowy za pomocą pg_class_relname_nsp_index na pg_class (aktualny czas=0.049..0.050 wierszy=1 pętli=1)
  Warunek indeksu: (relname = $1)
  Filtr: (oid = $0)
  Bufory: trafienie w pamięci=4
  Inicjalny plan 1 (zwraca $0,$1)
    ->  Limit (aktualny czas=0.019..0.020 wierszy=1 pętli=1)
          Bufory: trafienie w pamięci=1
          ->  Sekwencyjne skanowanie na pg_class pg_class_1 (aktualny czas=0.015..0.015 wierszy=1 pętli=1)
                Filtr: (relkind = 'r'::"char")
                Wiersze usunięte przez filtr: 5
                Bufory: trafienie w pamięci=1

lub tak:

"Append  (koszt=868.60..878.95 wierszy=2 szerokość=233) (aktualny czas=0.024..0.144 wierszy=2 pętli=1)"
"  Bufory: trafienie w pamięci=3"
"  CTE cl"
"    ->  Sekwencyjne skanowanie na pg_class  (koszt=0.00..868.60 wierszy=9972 szerokość=537) (aktualny czas=0.016..0.042 wierszy=101 pętli=1)"
"          Bufory: trafienie w pamięci=3"
"  ->  Limit  (koszt=0.00..0.10 wierszy=1 szerokość=233) (aktualny czas=0.023..0.024 wierszy=1 pętli=1)"
"        Bufory: trafienie w pamięci=1"
"        ->  CTE Scan na cl  (koszt=0.00..997.20 wierszy=9972 szerokość=233) (aktualny czas=0.021..0.021 wierszy=1 pętli=1)"
"              Bufory: trafienie w pamięci=1"
"  ->  Limit  (koszt=10.00..10.10 wierszy=1 szerokość=233) (aktualny czas=0.117..0.118 wierszy=1 pętli=1)"
"        Bufory: trafienie w pamięci=2"
"        ->  CTE Scan na cl cl_1  (koszt=0.00..997.20 wierszy=9972 szerokość=233) (aktualny czas=0.001..0.104 wierszy=101 pętli=1)"
"              Bufory: trafienie w pamięci=2"
"Czas planowania: 0.634 ms"
"Czas wykonania: 0.248 ms"

Lecz czytanie planu w formie tekstowej „z kartki” – jest bardzo trudne i nieczytelne:

w węźle wyświetla się suma zasobów poddrzewka
to znaczy, aby zrozumieć, ile czasu zajęło wykonanie konkretnego węzła, lub ile dokładnie odczyt z tabeli pobrał danych z dysku – trzeba jakoś odjąć jedno od drugiego
czas węzła jest niezbędny mnożymy przez loops
tak, odejmowanie to jeszcze nie najtrudniejsza operacja, którą trzeba wykonać 'w myślach' — ponieważ czas wykonania podawany jest jako średni dla jednego wykonania węzła, a ich może być setki
a więc wszystko to razem utrudnia odpowiedź na główne pytanie — więc kto jest „najsłabsze ogniwo”?

Kiedy próbowaliśmy wyjaśnić to kilkuset naszym programistom, zrozumieliśmy, że z zewnątrz wygląda to mniej więcej tak:

A więc potrzebujemy...

Narzędzie

Stworzyliśmy w nim wszystkie kluczowe mechaniki, które pomagają w planie i zapytaniu zrozumieć, 'kto zawinił i co robić'. No, i podzielić się częścią swojego doświadczenia ze społecznością.
Poznajcie i korzystajcie — explain.tensor.pl

Przejrzystość planów

Czy łatwo zrozumieć plan, gdy wygląda tak?

Seq Scan on pg_class (czas rzeczywisty=0.009..1.304 wierszy=6609 pętle=1)
  Buffery: trafienia współdzielone=263
Czas planowania: 0.108 ms
Czas wykonania: 1.800 ms

Niezbyt.

Ale tak, w skróconej formie, gdy kluczowe wskaźniki są oddzielone — już znacznie bardziej zrozumiałe:

Ale jeśli plan jest bardziej skomplikowany — na pomoc przychodzi wykres kołowy przedstawiający rozkład czasu węzłów:

A dla najbardziej skomplikowanych przypadków na pomoc przychodzi wykres wykonania:

Na przykład zdarzają się dość nietrywialne sytuacje, gdy plan może mieć więcej niż jeden rzeczywisty korzeń:

Wskazówki strukturalne

A jeśli cała struktura planu i jego słabsze miejsca są już rozłożone i widoczne — czemu nie podświetlić ich programiście i nie wyjaśnić 'naturalnym językiem'?

Zebraliśmy już wiele takich szablonów rekomendacji.

Profilowanie zapytania w wierszach

Teraz, jeśli na analizowany plan nałożymy oryginalne zapytanie, można zobaczyć, ile czasu zajęło każde pojedyncze polecenie — mniej więcej tak:

… lub nawet tak:

Podstawienie parametrów w zapytaniu

Jeśli 'przyczepiłeś' do planu nie tylko zapytanie, ale i jego parametry z wiersza DETAIL w logu, możesz skopiować je dodatkowo w jednym z wariantów:

z podstawieniem wartości w zapytaniu
do bezpośredniego wykonania na swojej bazie i dalszego profilowania
```
SELECT 'const', 'param'::text;
```
z podstawieniem wartości przez PREPARE/EXECUTE
do emulacji pracy planisty, gdy część parametryczna może być zignorowana — na przykład przy pracy na sekcjonowanych tabelach
```
DEALLOCATE ALL;
PREPARE q(text) AS SELECT 'const', $1::text;
EXECUTE q('param'::text);
```