За какво мълчи 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"

Но четенето на плана текстово „на лист“ е много сложно и неясно:

• във възела се извежда сумата по ресурсите на поддеревото
  тоест за да разберете колко време е отнело изпълнението на конкретен възел, или колко точно това четене от таблицата е извлякло данни от диска – трябва по някакъв начин да извадите едно от друго
• времето на възела е необходимо да се умножава по цикли
  Да, изваждането все още не е най-сложната операция, която трябва да се прави „в ума“ — тъй като времето за изпълнение е посочено средно за едно изпълнение на възел, а те могат да бъдат стотици.
• Но всичко това заедно затруднява отговора на основния въпрос — така кой всъщност е. „Най-слабата връзка“?

Когато се опитахме да обясним всичко това на няколко стотин наши разработчици, разбрахме, че отстрани това изглежда по следния начин:

А, значи, ни трябва...

Инструмент

В него се опитахме да съберем всички ключови механики, които помагат по плана и запитването да разберем „кой е виновен и какво да правим“. И също така да споделим част от опита си със общността.
Запознайте се и използвайте — 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

Не особено.

Но по този начин, в съкратен вид, когато ключовите показатели са отделени — вече е много по-разбираемо:

Но ако планът е по-сложен — на помощ идва диаграма на разпределението на времето по възли:

Но за най-сложните варианти на помощ пристига диаграма на изпълнението:

Например, имат достатъчно нетривиални ситуации, когато планът може да има повече от един действителен корен:

Структурни подсказки

Но ако цялата структура на плана и неговите проблемни места вече са разложени и видими — защо да не ги подсветим на разработчика и не обясним с „човешки език“?

Събрали сме вече няколко десетки такива шаблона за препоръки.

Редови профайлер на запитвания

Сега, ако наложим оригиналното запитване на анализирания план, можем да видим колко време е отнело на всеки отделен оператор — примерно така:

… или дори така:

Подмяна на параметрите в запитването

Ако сте „прикачили“ към плана не само запитването, но и неговите параметри от 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