Метод разбора медленного запроса в PostgreSQL: семь шагов и что дал каждый, с 0,7 до 0,2 с

Отчёт «выручка по клиентам одного города» выполняется 0,7 секунды, и непонятно, с чего начать: добавить индекс, поднять work_mem или переписать запрос. Метод снимает выбор: шаги идут от дешёвых и безопасных к рискованным, у каждого есть вопрос и критерий остановки, а выигрыш записывается в миллисекундах. Как читать сам план, описано в статье про EXPLAIN ANALYZE BUFFERS; здесь — порядок действий вокруг него и ссылки на статьи, где разобран каждый механизм.

DBA / 01koddo

Семь шагов разбора и что дал каждый

Стенд

Две таблицы: 8 млн заказов и 500 тыс. клиентов. Сначала в orders загружено 10 000 строк за 2025 год и выполнен ANALYZE, затем догружены остальные 7 990 000 строк 2026 года, как это бывает после ночной загрузки. Автовакуум на таблице выключен, чтобы воспроизвести окно, в котором он ещё не успел. Столбец city определяет country: в каждой из 20 стран ровно две «своих» точки.

docker run -d --name dba-slow-query-triage-method --memory 2g -e POSTGRES_PASSWORD=pg postgres:18 \
  -c shared_preload_libraries=pg_stat_statements -c track_io_timing=on -c max_parallel_workers_per_gather=0
docker exec -it dba-slow-query-triage-method psql -U postgres

CREATE EXTENSION pg_stat_statements;
CREATE TABLE customers AS
SELECT g AS id, 'customer-' || g AS name, g % 5 AS segment FROM generate_series(1, 500000) g;
ALTER TABLE customers ADD PRIMARY KEY (id);

CREATE TABLE orders (id bigint, customer_id int, country int, city int,
  created_at timestamptz, amount numeric(10,2), note text) WITH (autovacuum_enabled = false);

INSERT INTO orders
SELECT g, 1 + abs(hashint8(g)::bigint) % 500000, 1 + g % 20, (1 + g % 20) * 2 + (g / 20) % 2,
       timestamptz '2025-01-01' + (g % 365) * interval '1 day', (g % 1000) / 10.0, repeat('x', 40)
FROM generate_series(1, 10000) g;
ANALYZE orders;
INSERT INTO orders
SELECT g, 1 + abs(hashint8(g)::bigint) % 500000, 1 + g % 20, (1 + g % 20) * 2 + (g / 20) % 2,
       timestamptz '2026-01-01' + (g % 300) * interval '1 day', (g % 1000) / 10.0, repeat('x', 40)
FROM generate_series(10001, 8000000) g;
CREATE UNIQUE INDEX orders_pkey ON orders (id);
ANALYZE customers;

Отчёт, который просят выгрузить: выручка по клиентам страны 4, города 9, с апреля 2026.

SELECT c.segment, c.id, c.name, count(*) AS n, sum(o.amount) AS revenue
FROM orders o JOIN customers c ON c.id = o.customer_id
WHERE o.country = 4 AND o.city = 9 AND o.created_at >= '2026-04-01'
GROUP BY c.segment, c.id, c.name
ORDER BY revenue DESC;

Шаг 1. Найти запрос в pg_stat_statements

Жалоба «всё тормозит» не называет запрос, статистика называет. Сбрось её, дай нагрузку (20 000 точечных чтений через pgbench и три запуска отчёта) и отсортируй по total_exec_time. Как устроены queryid, снимки и ловушка среднего, описано в статье про pg_stat_statements.

docker exec -i dba-slow-query-triage-method sh -c 'cat > /tmp/l.sql && pgbench -U postgres -n -f /tmp/l.sql -c 4 -t 5000 postgres' <<'EOF'
\set id random(1, 500000)
SELECT name FROM customers WHERE id = :id;
EOF

SELECT calls, round(total_exec_time) AS total_ms, round(mean_exec_time::numeric, 1) AS mean_ms,
       rows, shared_blks_hit AS hit, shared_blks_read AS read, temp_blks_written AS temp_w,
       left(regexp_replace(query, '\s+', ' ', 'g'), 40) AS query
FROM pg_stat_statements WHERE query NOT LIKE '%pg_stat_statements%'
ORDER BY total_exec_time DESC LIMIT 3;

В psql перед этим выполнены SELECT pg_stat_statements_reset(); и три запуска отчёта с \o /dev/null.

вывод:

 calls | total_ms | mean_ms |  rows  |   hit   |  read  | temp_w |                  query                   
-------+----------+---------+--------+---------+--------+--------+------------------------------------------
     3 |     2037 |   679.1 | 350715 | 1632465 | 285570 |   4116 | SELECT c.segment, c.id, c.name, count(*)
 20000 |       78 |     0.0 |  20000 |   80000 |      0 |      0 | SELECT name FROM customers WHERE id = $1

Критерий остановки: есть один queryid, чьё среднее или суммарное время заметно выше остальных. Здесь отчёт: 679,1 мс на вызов, около 95 000 блоков вне shared_buffers на вызов (read 285 570 на три вызова) и temp_blks_written — сортировка уходит на диск. Остальные запросы (78 мс на 20 000 вызовов) не трогаются.

Шаг 2. EXPLAIN (ANALYZE, BUFFERS) с реальными параметрами

Перед отчётом ставится EXPLAIN (ANALYZE, BUFFERS), константы остаются теми же, что у приложения: с другими значениями статистика даст другую оценку, а с $1 из prepared statement можно получить generic-план (регрессии планов). Как читать loops, буферы родителя и детей, описано в статье EXPLAIN продвинуто. Оставлены строки, по которым принимается решение:

               ->  Nested Loop  (cost=0.42..245979.36 rows=1 width=29) (actual time=6.206..577.183 rows=133168.00 loops=1)
                     ->  Seq Scan on orders o  (cost=0.00..245970.92 rows=1 width=10) (actual time=6.174..307.303 rows=133168.00 loops=1)
                           Rows Removed by Filter: 7866832
                           Buffers: shared hit=11601 read=95066
                     ->  Index Scan using customers_pkey on customers c  (cost=0.42..8.44 rows=1 width=23) (actual time=0.002..0.002 rows=1.00 loops=133168)
 Execution Time: 711.499 ms

Шесть запусков подряд дали 657–713 мс; к этому диапазону сравнивается каждый шаг. Время уходит в Seq Scan по 8 млн строк (307 мс из 711) и в 133 168 заходов во внутреннюю часть соединения. Критерий остановки: названы узлы, на которых проведено больше всего времени, и известно, сколько раз они выполнялись.

Шаг 3. Оценки против факта

Сравнение идёт снизу вверх: rows оценки против actual rows × loops. Первый узел с расхождением больше порядка — место, откуда начинается ошибка: всё выше него планировщик считал по неверным числам.

В плане выше это Seq Scan on orders: оценка rows=1, факт 133 168. Index Scan по customers оценён верно (1 строка на заход), но заходов вместо одного получилось 133 168: планировщик верил в одну внешнюю строку и выбрал вложенный цикл. Критерий остановки: найден узел с ошибкой в 10 раз и больше. Если оценки совпадают с фактом, шаг 4 сводится к проверке индексов.

Шаг 4. Статистика и индексы

Три проверки по порядку, у каждой своя цифра. Механизм первых двух — в статьях про ANALYZE и гистограммы и расширенную статистику.

Статистика устарела? После загрузки ANALYZE не выполнялся.

SELECT c.reltuples::bigint AS reltuples, s.n_live_tup, s.n_mod_since_analyze,
       (SELECT max(created_at) FROM orders) AS real_max,
       (SELECT (histogram_bounds::text::timestamptz[])[array_length(histogram_bounds::text::timestamptz[], 1)]
        FROM pg_stats WHERE tablename = 'orders' AND attname = 'created_at') AS hist_max
FROM pg_class c JOIN pg_stat_user_tables s ON s.relid = c.oid WHERE c.relname = 'orders';

 reltuples | n_live_tup | n_mod_since_analyze |        real_max        |        hist_max        
-----------+------------+---------------------+------------------------+------------------------
     10000 |    8010000 |             8000000 | 2026-10-27 00:00:00+00 | 2025-12-31 00:00:00+00

reltuples остался от первых 10 000 строк, а гистограмма created_at кончается на 2025-12-31: условие created_at >= '2026-04-01' лежит правее неё, и планировщик получил rows=1. После ANALYZE orders оценка стала 6 571 (факт 133 168), Nested Loop сменился Merge Join, время — 499–530 мс.

Оценка всё ещё занижена в 20 раз: city определяет country, а планировщик перемножает доли. CREATE STATISTICS orders_country_city (dependencies) ON country, city FROM orders и повторный ANALYZE orders подняли оценку до 139 559 (в pg_stats_ext зависимость "4 => 3": 1.0, то есть столбец 4 city определяет столбец 3 country). План остался тем же, время тоже: 498–565 мс. Верная оценка сама ничего не ускорила; она нужна, чтобы следующее решение принималось по верным числам.

Есть ли индекс под фильтр? Нет, остался Seq Scan по 8 млн строк. Индекс по трём условиям отчёта:

CREATE INDEX orders_country_city_created_idx ON orders (country, city, created_at);
VACUUM ANALYZE orders;

                           ->  Bitmap Heap Scan on orders o  (cost=2218.58..200443.49 rows=136639 width=10) (actual time=15.629..239.608 rows=133168.00 loops=1)
                                 Rows Removed by Index Recheck: 2429346
                                 Heap Blocks: exact=46715 lossy=33186
 Execution Time: 491.146 ms

Seq Scan сменился на Bitmap Heap Scan, время — 386–493 мс (четыре запуска из шести уложились в 386–398, два выброса 463 и 493). Выигрыш скромный: строки города лежат в куче вперемешку с остальными, и узел обходит 80 018 блоков (шаг 6). Критерий остановки: оценка совпала с фактом, а для условий фильтра есть индекс, который планировщик выбрал.

Шаг 5. Блокировки и ожидания

Если время клиента больше Planning Time + Execution Time, запрос ждал до начала выполнения: блокировку на таблицу берёт разбор запроса (parserOpenTable в addRangeTableEntry, parse_relation.c, строка 1550), а Planning Time в EXPLAIN отсчитывается позже, от planstart:

	INSTR_TIME_SET_CURRENT(planstart);

	/* plan the query */
	plan = pg_plan_query(query, queryString, cursorOptions, params);

	INSTR_TIME_SET_CURRENT(planduration);
	INSTR_TIME_SUBTRACT(planduration, planstart);

Чтобы проверить, в сессии A открыта «миграция» с ACCESS EXCLUSIVE на 6 секунд, через секунду в сессии B запущен отчёт с \timing on, ещё через три секунды сессия C смотрит pg_stat_activity. Те же данные есть в pg_locks (granted = false у ожидающего), а pg_blocking_pids называет блокирующий PID сразу:

-- сессия A
BEGIN; ALTER TABLE orders ADD COLUMN reviewed boolean; SELECT pg_sleep(6); COMMIT;
-- сессия B: \timing on, \o /dev/null, отчёт
-- сессия C
SELECT pid, state, wait_event_type, wait_event, pg_blocking_pids(pid) AS blocked_by,
       now() - query_start AS waiting, left(query, 30) AS query
FROM pg_stat_activity WHERE backend_type = 'client backend' AND pid <> pg_backend_pid();

 pid | state  | wait_event_type | wait_event | blocked_by |     waiting     |             query              
-----+--------+-----------------+------------+------------+-----------------+--------------------------------
 628 | active | Timeout         | PgSleep    | {}         | 00:00:04.00089  | BEGIN; ALTER TABLE orders ADD 
 632 | active | Lock            | relation   | {628}      | 00:00:03.000629 | SELECT c.segment, c.id, c.name

Time: 5477.972 ms (00:05.478)

Отчёт стоял в очереди с wait_event_type = Lock, wait_event = relation и блокирующим PID 628. Клиент получил ответ за 5 478 мс. pg_stat_statements для этого вызова записал 456 мс, а повторный запуск отчёта без блокировки под EXPLAIN ANALYZE — Planning Time: 0.164 ms, Execution Time: 473.182 ms. Очередь за ALTER TABLE разобрана в статье про блокировки, профиль ожиданий по wait_event — в статье про wait events.

Критерий остановки: Planning + Execution совпадает со временем клиента, а в pg_stat_activity нет сессий с wait_event_type = Lock. Тогда запрос медленен сам по себе. Шаг не меняет Execution Time: он диагностический.

Шаг 6. I/O и память узлов

Для каждого тяжёлого узла: сколько блоков он читает, сколько из них не в shared_buffers, сколько времени ушло на чтение и есть ли temp. В плане после шага 4:

   Buffers: shared hit=7 read=84568, temp read=1062 written=1065
   I/O Timings: shared read=14.772, temp read=1.583 write=4.320
                                 Buffers: shared read=80018
                                 I/O Timings: shared read=3.979

Чтение всех блоков стоит 15 мс из 491: страницы приходят из кэша ОС, диск не узкое место. Сортировка на диске (temp written=1065, около 8 МБ) стоит 4,3 мс записи; подробно спилл разобран в статье про work_mem. Остаются 80 018 блоков кучи ради 133 168 строк: индекс знает, где строки города, но customer_id и amount берутся из кучи. Возврат к шагу 4 по данным шага 6: индекс со столбцами, нужными отчёту.

DROP INDEX orders_country_city_created_idx;
CREATE INDEX orders_report_idx ON orders (country, city, created_at) INCLUDE (customer_id, amount);
VACUUM ANALYZE orders;

                           ->  Index Only Scan using orders_report_idx on orders o  (cost=0.56..6738.56 rows=144089 width=10) (actual time=0.025..8.504 rows=133168.00 loops=1)
                                 Heap Fetches: 0
                                 Buffers: shared hit=847
 Execution Time: 220.711 ms

Шесть запусков: 214–218 мс. Вместо 80 018 блоков кучи узел читает 847 блоков индекса, Heap Fetches: 0 (после VACUUM карта видимости актуальна). Цена: индекс 379 МБ рядом с таблицей 834 МБ и ещё один индекс на каждую вставку в orders; стоимость записи опыт не измерял. Критерий остановки: самый тяжёлый узел читает ровно столько блоков, сколько нужно ради своих строк.

Шаг 7. Конфигурация, только в сессии

Настройки меняют все планы сразу, поэтому проверяются в одной сессии через SET и не попадают в postgresql.conf, пока запрос не доказал пользу. Кандидаты из шага 6: work_mem (сортировки по 5,6 и 2,9 МБ выходят на диск) и random_page_cost (по модели стоимости он решает, дёшев ли индекс). Каждая проверка — SET, шесть запусков, RESET ALL.

С SET work_mem = '64MB' время 296–308 мс против 214–218. План сменился: сортировки и HashAggregate целиком в памяти (Sort Method: quicksort Memory: 9466kB, Batches: 1 Memory Usage: 53265kB), но соединение стало хеш-соединением, где Hash по всем 500 000 строкам customers строится 106 мс. С SET random_page_cost = 1.1 время 256–290 мс: хеш-соединение с Batches: 4. Планировщик считал хеш-план дешевле (cost 36 794 против 62 165 у прежнего), а он оказался медленнее; оценки rows при этом верны (144 089 при факте 133 168), так что расхождение не от статистики.

Критерий остановки: три запуска подряд не дают больше 10 % или дают хуже, и настройка откатывается.

Последнее: переписывание запроса

Переписывание меняет код приложения, поэтому идёт после настройки. Вариант с предварительной агрегацией заказов по customer_id:

SELECT c.segment, c.id, c.name, a.n, a.revenue
FROM (SELECT customer_id, count(*) AS n, sum(amount) AS revenue FROM orders
      WHERE country = 4 AND city = 9 AND created_at >= '2026-04-01' GROUP BY customer_id) a
JOIN customers c ON c.id = a.customer_id ORDER BY a.revenue DESC;

Результат 253–278 мс, хуже исходного: HashAggregate ушёл на диск (Batches: 9, Disk Usage: 3544kB). Запрос остаётся прежним.

Итог: шаг → изменение → время → что подтвердило

Итог: 657–713 → 214–218 мс на 8 млн строк, примерно втрое. Основной выигрыш дали шаги 4 и 6, то есть статистика и индекс; настройки и переписывание не помогли. Машина общая, поэтому диапазоны шире, чем на выделенном сервере; у тебя цифры будут другими.

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

• Метод ставит безопасные проверки раньше рискованных: статистика и индексы меняют один запрос, настройки — все.
• Верная оценка rows не гарантирует выигрыш по времени (CREATE STATISTICS: 0 мс), но без неё остальные решения принимаются по неверным числам.
• Ожидание блокировки не видно ни в EXPLAIN, ни в pg_stat_statements: 5 478 мс у клиента против 456 мс в статистике.

Чек-лист

1. Начни с pg_stat_statements: один queryid по total_exec_time или mean_exec_time.
2. Снимай EXPLAIN (ANALYZE, BUFFERS) на реальных константах, шесть запусков, записывай диапазон и сравнивай с ним каждый шаг.
3. Найди первый снизу узел, где rows отличается от факта больше чем в 10 раз; проверь n_mod_since_analyze, зависимые столбцы и индекс под фильтр. Сравни время клиента с Planning + Execution и посмотри wait_event_type = Lock.
4. Настройки меняй только через SET в сессии и откатывай, если выигрыш меньше 10 %.
5. Убери стенд командой docker rm -f -v dba-slow-query-triage-method: без -v том с данными остаётся на диске.