Koddo
начать бесплатно

Справочник DBA: базы данных изнутри читается по порядку

Статья 10.4 · раздел 10 «Мониторинг и диагностика» · 74 из 109

EXPLAIN продвинуто: actual rows × loops, буферы родителя и детей, WAL, SERIALIZE и цена TIMING

опубликовано
читать
≈ 11 мин
автор
среда и версия
PostgreSQL 18.6 в контейнере postgres:18 (--memory 1500m, shared_buffers = 256MB, max_parallel_workers_per_gather = 0); orders 1 млн строк (82 МБ), docs 4 000 строк (87 МБ с TOAST), big 10 млн строк (346 МБ); опыт выполнен 28 октября 2026
содержание решать задачи SQL на собеседовании

В плане стоит rows=20.00 loops=3, а рядом Buffers: shared hit=44 и Rows Removed by Filter: 980: часть этих чисел усреднена на один запуск узла, часть сложена за все запуски, а буферы родителя уже содержат буферы детей. Базовое чтение дерева, оценок и BUFFERS разобрано в статье про EXPLAIN ANALYZE BUFFERS; здесь продолжение с того места, где она остановилась: какое число умножать, какое вычитать, что показывают WAL, SETTINGS и SERIALIZE и сколько стоит сам замер времени.

DBA / 01

Откуда взялось каждое число в плане

Откуда взялось каждое число в плане Nested Loop отдаёт 60 строк и показывает hit 47. Его дети: Index Only Scan по customers отдаёт 3 строки за один запуск и читает 3 буфера; Index Scan по orders за три запуска отдаёт по 20 строк и читает 44 буфера суммарно. Аннотации: буферы родителя 3 плюс 44 равно 47; строки 20 умножить на 3 равно 60; отброшено фильтром 980 умножить на 3 равно 2 940. Nested Loop rows 60.00 · hit 47 Index Only Scan customers rows 3.00 × loops 1 · hit 3 Index Scan orders_customer_idx rows 20.00 × loops 3 · hit 44 hit 3 + 44 = 47 родитель = сумма детей 20 × 3 = 60 строк родителю 980 × 3 = 2 940 отброшено всего rows и Rows Removed by Filter — среднее на запуск: умножай на loops. Buffers и Index Searches — сумма за все запуски: не умножай.
Один план, три правила: строки и отброшенные строки усреднены на запуск и умножаются на loops, буферы сложены за все запуски, а у родителя к ним добавлены буферы детей.

Стенд

Все опыты идут на одном контейнере. shared_buffers и параллельные воркеры зафиксированы, чтобы числа буферов повторялись; auto_explain подгружается заранее для последнего опыта:

docker run -d --name dba-explain-advanced-reading --memory 1500m -e POSTGRES_PASSWORD=pg \
  postgres:18 -c shared_buffers=256MB -c max_parallel_workers_per_gather=0 \
  -c shared_preload_libraries=auto_explain
docker exec -i dba-explain-advanced-reading psql -U postgres
CREATE TABLE customers AS SELECT g AS id, g % 10 AS region FROM generate_series(1,1000) g;
ALTER TABLE customers ADD PRIMARY KEY (id);
CREATE TABLE orders AS
SELECT g AS id, 1 + (g - 1) / 1000 AS customer_id,
       CASE WHEN g % 50 = 0 THEN 'failed' ELSE 'ok' END AS status,
       (g % 997) AS amount, md5(g::text) AS note
FROM generate_series(1,1000000) g;
ALTER TABLE orders ADD PRIMARY KEY (id);
CREATE INDEX orders_customer_idx ON orders(customer_id);
VACUUM ANALYZE customers, orders;

В orders 1 млн строк, по 1000 на клиента подряд; таблица занимает 82 МБ, или 10 368 страниц.

Опыт 1: Nested Loop и loops больше единицы

EXPLAIN (ANALYZE) SELECT c.id, o.id
FROM customers c JOIN orders o ON o.customer_id = c.id
WHERE c.id <= 3 AND o.status = 'failed';

Вывод, второй запуск (первый прогрел кэш); опущены Index Cond, Heap Fetches и строки Planning:

 Nested Loop  (cost=0.70..210.23 rows=62 width=8) (actual time=0.008..0.169 rows=60.00 loops=1)
   Buffers: shared hit=47
   ->  Index Only Scan using customers_pkey on customers c  (cost=0.28..4.33 rows=3 width=4) (actual time=0.001..0.001 rows=3.00 loops=1)
         Index Searches: 1
         Buffers: shared hit=3
   ->  Index Scan using orders_customer_idx on orders o  (cost=0.42..68.42 rows=21 width=8) (actual time=0.005..0.054 rows=20.00 loops=3)
         Filter: (status = 'failed'::text)
         Rows Removed by Filter: 980
         Index Searches: 3
         Buffers: shared hit=44

Внутренний Index Scan, число за числом:

  • rows=20.00 loops=3 — среднее за запуск. Внешняя сторона отдала трёх клиентов, внутренний узел запускался по разу на каждого, итог 20 × 3 = 60, и ровно rows=60.00 вышло из Nested Loop. Оценка rows=21 тоже на один запуск: сравнивать её надо с 20.00, не с 60. actual time=0.005..0.054 — тоже на запуск: три запуска заняли около 0.054 × 3 = 0.16 мс из 0.169 мс родителя.
  • Rows Removed by Filter: 980 — среднее на запуск: отброшено 980 × 3 = 2 940, а прочитано по 20 + 980 = 1 000 на клиента, что совпадает с данными.
  • Index Searches: 3 — не среднее, а сумма: три запуска, три поиска по индексу.
  • Buffers: shared hit=44 — сумма за три запуска, без деления. У родителя hit=47, и 3 + 44 = 47: собственных страниц Nested Loop не читает.

Деление на loops видно в коде: ExplainNode берёт накопленные за все запуски ntuples и время и делит на nloops (explain.c, строки 1832-1835):

		double		nloops = planstate->instrument->nloops;
		double		startup_ms = 1000.0 * planstate->instrument->startup / nloops;
		double		total_ms = 1000.0 * planstate->instrument->total / nloops;
		double		rows = planstate->instrument->ntuples / nloops;

Rows Removed by Filter делится так же и печатается без дробной части (строки 3983-3984): 980 × 3 может отличаться от настоящего итога на единицы. Буферы не делятся: bufusage узла печатается как есть (строки 2285-2286). Дробные rows появились в PostgreSQL 18: в примечаниях к выпуску есть строка «Modify EXPLAIN to output fractional row counts», поэтому 20.00 вместо 20.

Опыт 2: Seq Scan с фильтром и буферы родителя

EXPLAIN (ANALYZE)
SELECT c.region, count(*), sum(o.amount)
FROM orders o JOIN customers c ON c.id = o.customer_id
WHERE o.status = 'failed' GROUP BY c.region;

В выводе опущены строки Group Key, Batches, Buckets и Planning:

 HashAggregate  (cost=23107.66..23107.76 rows=10 width=20) (actual time=31.836..31.839 rows=10.00 loops=1)
   Buffers: shared hit=3282 read=7093
   ->  Hash Join  (cost=29.50..22952.16 rows=20733 width=8) (actual time=0.133..30.287 rows=20000.00 loops=1)
         Buffers: shared hit=3282 read=7093
         ->  Seq Scan on orders o  (cost=0.00..22868.00 rows=20733 width=8) (actual time=0.007..28.078 rows=20000.00 loops=1)
               Filter: (status = 'failed'::text)
               Rows Removed by Filter: 980000
               Buffers: shared hit=3275 read=7093
         ->  Hash  (cost=17.00..17.00 rows=1000 width=8) (actual time=0.111..0.111 rows=1000.00 loops=1)
               Buffers: shared hit=7
               ->  Seq Scan on customers c  (cost=0.00..17.00 rows=1000 width=8) (actual time=0.005..0.041 rows=1000.00 loops=1)
                     Buffers: shared hit=7

Seq Scan по orders с loops=1: отдано 20 000, отброшено 980 000, прочитано 20 000 + 980 000 = 1 000 000 строк, фильтр пропустил 2 %. Буферы 3275 + 7093 = 10 368 равны числу страниц таблицы: узел прошёл её всю. Деление на hit и read зависит от кэша, сумма не зависит.

Буферы родителя включают детей, поэтому собственную работу узла находят вычитанием. HashAggregate читает 3282 + 7093 = 10 375, ровно столько же у ребёнка Hash Join: собственных 0. У Hash Join те же 10 375 против 10 368 + 7 у детей Seq Scan orders и Hash: снова 0. У Hash 7 и у его ребёнка 7. Если сложить все строки дерева, получится 10 375 + 10 375 + 10 368 + 7 + 7 = 31 132 против реальных 10 375: страницы посчитаны по три раза. Механизм виден в InstrStopNode: при выходе из узла к его счётчику прибавляется разница общих счётчиков между входом и выходом, а в этом интервале исполнялись и дочерние узлы (instrument.c, строки 104-107):

	/* Add delta of buffer usage since entry to node's totals */
	if (instr->need_bufusage)
		BufferUsageAccumDiff(&instr->bufusage,
							 &pgBufferUsage, &instr->bufusage_start);

Время узла устроено так же: actual time родителя включает детей. Как выбирается вид соединения, разобрано в статье про алгоритмы соединения.

Опыт 3: запрос с записью и опция WAL

EXPLAIN ANALYZE выполняет UPDATE по-настоящему, поэтому запуск обёрнут в транзакцию с откатом. Перед ним CHECKPOINT, чтобы первая запись в страницу после контрольной точки несла полный образ (статья про full page writes):

CHECKPOINT;
BEGIN;
EXPLAIN (ANALYZE, WAL, COSTS OFF, SUMMARY OFF)
UPDATE orders SET amount = amount + 1 WHERE customer_id <= 10;
ROLLBACK;
 Update on orders (actual time=33.254..33.255 rows=0.00 loops=1)
   Buffers: shared hit=100838 read=111 dirtied=298 written=90
   WAL: records=40414 fpi=150 bytes=4408495
   ->  Index Scan using orders_customer_idx on orders (actual time=0.005..1.435 rows=10000.00 loops=1)
         Buffers: shared hit=106 read=66
  • Update показывает rows=0.00: без RETURNING узел ничего не отдаёт наверх, обновлённые 10 000 строк видны только в дочернем Index Scan (rows=10000.00).
  • Буферы родителя: 100 838 + 111 = 100 949; ребёнка: 106 + 66 = 172. Разность 100 949 − 172 = 100 777 — собственная работа Update: страницы таблицы и двух индексов с новыми версиями. В отличие от соединений в опытах 1 и 2, здесь у родителя есть собственные буферы.
  • WAL: records=40414 fpi=150 bytes=4408495 — число записей журнала, полных образов страниц (fpi) и байтов, сгенерированных узлом. Эти записи сгенерированы во время выполнения, до ROLLBACK.

Опыт 4: BUFFERS по умолчанию, SETTINGS и SERIALIZE

BUFFERS. В примечаниях к PostgreSQL 18 есть строка «Automatically include BUFFERS output in EXPLAIN ANALYZE». Проверка: BUFFERS не указан, а строки Buffers есть:

EXPLAIN (ANALYZE, COSTS OFF, SUMMARY OFF) SELECT count(*) FROM customers;
 Aggregate (actual time=0.057..0.057 rows=1.00 loops=1)
   Buffers: shared hit=7
   ->  Seq Scan on customers (actual time=0.005..0.030 rows=1000.00 loops=1)
         Buffers: shared hit=7

SETTINGS печатает параметры планирования, отличающиеся от встроенных значений; он нужен, когда план с одного сервера не воспроизводится на другом:

CREATE INDEX orders_amount_idx ON orders(amount);
VACUUM ANALYZE orders;
EXPLAIN (SETTINGS, COSTS OFF) SELECT * FROM orders WHERE amount < 400;
SET random_page_cost = 1.1;
SET work_mem = '64MB';
EXPLAIN (SETTINGS, COSTS OFF) SELECT * FROM orders WHERE amount < 400;
RESET work_mem;
EXPLAIN (SETTINGS, COSTS OFF) SELECT * FROM orders WHERE amount < 400;

Из каждого плана оставлены корневой узел и строка Settings:

 Bitmap Heap Scan on orders
 Settings: max_parallel_workers_per_gather = '0'
 Index Scan using orders_amount_idx on orders
 Settings: max_parallel_workers_per_gather = '0', random_page_cost = '1.1', work_mem = '64MB'
 Index Scan using orders_amount_idx on orders
 Settings: max_parallel_workers_per_gather = '0', random_page_cost = '1.1'

max_parallel_workers_per_gather = '0' попал в вывод из флага запуска контейнера: SETTINGS видит и конфигурацию сервера, не только SET сессии. План сменился с Bitmap Heap Scan на Index Scan; в третьем запуске без work_mem план тот же, значит причина — random_page_cost, а work_mem просто присутствует в списке. Как параметр входит в стоимость, показано в статье про модель стоимости, а как work_mem ограничивает узлы — в статье про сортировки и спилл.

SERIALIZE (с PostgreSQL 17) считает время и объём преобразования результата в формат отправки. Таблица docs: 4 000 строк по 20 000 байт (length и pg_column_size равны, сжатия нет), основная часть 208 кБ, вместе с TOAST 87 МБ (статья про TOAST):

CREATE TABLE docs AS
SELECT g AS id, (SELECT string_agg(md5(random()::text || g::text || i::text), '')
                 FROM generate_series(1, 625) i) AS body
FROM generate_series(1, 4000) g;
VACUUM ANALYZE docs;
EXPLAIN (ANALYZE, COSTS OFF) SELECT * FROM docs;
EXPLAIN (ANALYZE, SERIALIZE, COSTS OFF) SELECT * FROM docs;
 Seq Scan on docs (actual time=0.013..0.200 rows=4000.00 loops=1)
   Buffers: shared hit=26
 Execution Time: 0.332 ms

 Seq Scan on docs (actual time=0.001..0.193 rows=4000.00 loops=1)
   Buffers: shared hit=26
 Serialization: time=18.093 ms  output=78179kB  format=text
   Buffers: shared hit=22001
 Execution Time: 18.525 ms

Без SERIALIZE запрос «стоит» 0,332 мс: значения из TOAST не читались, 26 страниц кучи. С ним добавилось 18,093 мс, 78 179 кБ и 22 001 страница TOAST. Тот же SELECT * FROM docs в psql с выводом в /dev/null занял по \timing 39,6; 30,0; 30,1; 30,0 и 32,2 мс: порядок тот же, что у SERIALIZE, а не у 0,3 мс обычного плана. Если запрос «быстрый в EXPLAIN, медленный в приложении», первым делом пробуй SERIALIZE.

Опыт 5: сколько стоит TIMING

Таблица big: 10 млн строк, 346 МБ. Один и тот же SELECT count(*) FROM big тремя способами, по пять запусков, время клиента из \timing (вывод в /dev/null):

CREATE TABLE big AS SELECT g AS id FROM generate_series(1, 10000000) g;
VACUUM ANALYZE big;

Запросы: SELECT count(*) FROM big;, он же под EXPLAIN (ANALYZE, TIMING on) и под EXPLAIN (ANALYZE, TIMING off).

РежимПять запусков, мсМедиана, мс
без EXPLAIN167,7; 153,7; 153,2; 149,7; 150,1153,2
TIMING off238,8; 237,3; 237,3; 236,8; 237,7237,3
TIMING on475,5; 482,8; 471,8; 475,2; 472,5475,2

Замер замедлил запрос в 475,2 / 153,2 = 3,1 раза: TIMING on добавил 475,2 − 153,2 = 322,0 мс на 10 млн строк, 32 нс на строку. TIMING off убирает большую часть: 237,3 − 153,2 = 84,1 мс, 8 нс на строку (подсчёт строк остаётся, а времени узлов в плане нет). Цена одного обращения к часам в этом контейнере:

$ docker exec dba-explain-advanced-reading pg_test_timing -d 3
Per loop time including overhead: 13.01 ns

Два обращения по 13 нс — 26 нс из 32 нс на строку. Они видны в InstrStopNode: при включённом таймере узел читает часы на каждом вызове (instrument.c, строки 93-99), а Seq Scan вызывается по разу на каждую отданную строку. Узел, который отдаёт мало строк, платит мало; узел с десятками миллионов вызовов платит за каждый. Число 13 нс относится к этому хосту: на другом его надо мерить своим pg_test_timing.

Опыт 6: auto_explain и вложенные запросы

Функция выполняет запрос внутри, снаружи виден только вызов:

CREATE FUNCTION orders_total(cid int) RETURNS bigint LANGUAGE plpgsql AS $$
BEGIN
  RETURN (SELECT sum(amount) FROM orders WHERE customer_id = cid);
END $$;
SET auto_explain.log_min_duration = 0;
SET auto_explain.log_analyze = on;
SET auto_explain.log_buffers = on;
SET auto_explain.log_nested_statements = on;
SELECT orders_total(7);

В логе сервера (docker logs dba-explain-advanced-reading) две записи: сначала запрос внутри функции, затем вызов. С выключенным log_nested_statements в логе была только вторая, один узел Result:

LOG:  duration: 0.113 ms  plan:
	Query Text: (SELECT sum(amount) FROM orders WHERE customer_id = cid)
	Result  (cost=38.37..38.38 rows=1 width=8) (actual time=0.110..0.111 rows=1.00 loops=1)
	  Buffers: shared hit=18
	  InitPlan 1
	    ->  Aggregate  (cost=38.36..38.37 rows=1 width=8) (actual time=0.109..0.110 rows=1.00 loops=1)
CONTEXT:  PL/pgSQL expression "(SELECT sum(amount) FROM orders WHERE customer_id = cid)"
	PL/pgSQL function orders_total(integer) line 3 at RETURN
LOG:  duration: 0.214 ms  plan:
	Query Text: SELECT orders_total(7)
	Result  (cost=0.00..0.26 rows=1 width=8) (actual time=0.212..0.213 rows=1.00 loops=1)
	  Buffers: shared hit=21

Строка CONTEXT называет функцию и номер строки. Вызов hit=21 включает вложенные hit=18, как родитель включает детей. log_analyze на всех запросах дорог по тем же причинам, что TIMING on: в документации auto_explain для этого есть log_timing = off.

Что из этого следует

  • Сначала определи, что в числе усреднено. rows, actual time, Rows Removed by Filter умножай на loops; Buffers и Index Searches не трогай. Оценку планировщика сравнивай со средним, не с итогом.
  • Буферы и время узла читай как разность с детьми. У Hash Join собственных страниц не нашлось, у Update нашлись 100 777; сумму по дереву не бери.
  • Запись видна в WAL, а не в Buffers: для UPDATE и DELETE смотри records, fpi и bytes; откат не освобождает журнал.
  • План с другого сервера просит SETTINGS, запрос из приложения просит SERIALIZE. Замер времени тоже стоит: TIMING on утроил время запроса на 10 млн строк.

Чек-лист

  1. В каждом узле с loops > 1 умножь rows и Rows Removed by Filter на loops и не умножай Buffers.
  2. Чтобы найти узел, который сам читает страницы, вычти буферы детей из буферов родителя.
  3. Для DML запускай EXPLAIN (ANALYZE, WAL) внутри BEGIN ... ROLLBACK и сравнивай records, fpi и bytes.
  4. Сохраняй план вместе с SETTINGS, а для широких значений TOAST добавляй SERIALIZE.
  5. На узлах с миллионами строк сверяй TIMING off, а для функций включай auto_explain.log_nested_statements.
  6. Контейнер опыта убирается командой docker rm -f -v dba-explain-advanced-reading.

Источники

Выжимки статей в Telegram: одна ловушка, код с выводом и ссылка на полный разбор. t.me/koddo_ru