🥇Про що мовчить EXPLAIN і як його розговорити

Класичне питання, з яким розробник приходить до свого DBA або власник бізнесу - до консультанта з PostgreSQL, майже завжди звучить однаково: "Чому запити виконуються на базі так довго?"

Традиційний набір причин:

неефективний алгоритм
коли ви вирішили зробити JOIN кількох CTE по парі десятків тисяч записів
неактуальна статистика
якщо фактичний розподіл даних у таблиці вже сильно відрізняється від зібраної ANALYZE в останній раз
«затік» за ресурсами
і вже не вистачає виділених обчислювальних потужностей CPU, постійно прокачуються гігабайти пам'яті або диск не встигає за всіма «хотелками» БД
блокування від конкуруючих процесів

І якщо блокування досить складні в затриманні та аналізі, то для решти нам достатньо плану запиту, який можна отримати за допомогою оператора EXPLAIN (краще, звичайно, відразу EXPLAIN (ANALYZE, BUFFERS) …) Або модуля auto_explain.

Але, як сказано у тій самій документації,

"Розуміння плану - це мистецтво, і щоб опанувати його, потрібен певний досвід, ..."

Але можна обійтися і без нього, якщо скористатися відповідним інструментом!

Як зазвичай виглядає план запиту? Якось ось так:

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

або ось так:

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

Але читати план текстом «з аркуша» дуже складно і ненаглядно:

у вузлі виводиться сума за ресурсами піддерева
тобто щоб зрозуміти, скільки часу пішло на виконання конкретного вузла, або скільки саме ось це читання з таблиці підняло даних з диска - потрібно якось віднімати одне з іншого
час вузла необхідний множити на loops
так, віднімання ще не найскладніша операція, яку треба робити «в умі» — адже час виконання вказується усереднений для одного виконання вузла, а їх можуть бути сотні
ну, і все це разом заважає відповісти на головне питання — то хто ж «найслабша ланка»?

Коли ми спробували пояснити все це кільком сотням наших розробників, то зрозуміли, що з боку це виглядає приблизно так:

Отже, нам потрібен…

Інструмент

У ньому ми постаралися зібрати всі ключові механіки, які допомагають за планом та запитом зрозуміти, «хто винен і що робити». Ну, і частиною свого досвіду поділитися із спільнотою.
Зустрічайте та користуйтеся explain.tensor.ru

Наочність планів

Чи легко зрозуміти план, коли він так виглядає?

Seq Scan on pg_class (actual time=0.009..1.304 rows=6609 loops=1)
  Buffers: shared hit=263
Planning Time: 0.108 ms
Execution Time: 1.800 ms

Не дуже.

Але так, у скороченому виглядіколи ключові показники відокремлені — вже набагато зрозуміліше:

Але якщо план складніший — на допомогу прийде piechart розподілу часу по вузлах:

Ну, а для найскладніших варіантів на допомогу поспішає діаграма виконання:

Наприклад, бувають досить нетривіальні ситуації, коли план може мати більше одного фактичного кореня:

Структурні підказки

Ну, а якщо вся структура плану та його хворі місця вже розкладено і видно — чому б не підсвітити їх розробнику і не пояснити «російською мовою»?

Таких шаблонів рекомендацій ми зібрали вже кілька десятків.

Порядковий профайлер запиту

Тепер, якщо на аналізований план накласти вихідний запит, можна побачити, скільки часу пішло на кожен окремий оператор — приблизно ось так:

… або навіть так:

Підстановка параметрів на запит

Якщо ви «причепили» до плану не лише запит, а й його параметри з DETAIL-рядка лога, то зможете скопіювати його додатково в одному з варіантів:

з підстановкою значень на запит
для безпосереднього виконання на своїй базі та подальшого профілювання
```
SELECT 'const', 'param'::text;
```
із підстановкою значень через PREPARE/EXECUTE
для емуляції роботи планувальника, коли параметричну частину можна проігнорувати — наприклад, під час роботи на секційованих таблицях
```
DEALLOCATE ALL;
PREPARE q(text) AS SELECT 'const', $1::text;
EXECUTE q('param'::text);
```

Архів планів

Вставляйте, аналізуйте, поділіться з колегами! Плани залишаться в архіві, і ви зможете повернутися до них пізніше: explain.tensor.ru/archive

Але якщо не бажаєте, щоб ваш план побачили інші, не забудьте поставити галочку «не публікувати в архіві».

У наступних статтях я розповім про ті складнощі та рішення, які виникають при аналізі плану.

Джерело: habr.com

Про що мовчить EXPLAIN і як його розговорити