Сервер «тормозит», а top и логи не говорят, какой запрос приложения виноват. pg_stat_statements ведёт накопительные счётчики по каждому типу запроса: вызовы, время, блоки, WAL, временные файлы. Три вещи делают их пригодными для разбора. Запросы с разными константами склеиваются в одну строку, и её ключ queryid виден и в плане, и в списке активных сессий. Счётчики растут с момента сброса, поэтому смотреть надо разность двух снимков, а не итог. И среднее время скрывает редкие выбросы, видные только в max_exec_time и stddev_exec_time. Расширение уже встречалось при поиске регрессий планов; читать сам план помогает EXPLAIN ANALYZE BUFFERS. Здесь все три механизма проверены на нагрузке pgbench с одним испорченным запросом.
Два снимка, разность и пять топов
SELECT без индекса стоит на первом месте только по чтению блоков и по временным файлам. Максимум за окно получают отдельным сбросом, а не вычитанием.Стенд
Контейнер запускается с библиотекой в shared_preload_libraries; без перезапуска сервера её не подключить. compute_query_id = on включает расчёт queryid в ядре, track_io_timing = on добавляет время чтения блоков:
C=dba-pg-stat-statements-workload-analysis
docker run -d --name $C --memory 1500m -e POSTGRES_PASSWORD=pg postgres:18 \
-c shared_preload_libraries=pg_stat_statements -c compute_query_id=on -c track_io_timing=on
docker exec $C psql -U postgres -c "CREATE EXTENSION pg_stat_statements"
docker exec $C pgbench -U postgres -i -s 20 -q postgresSELECT version() вернул PostgreSQL 18.6 (Debian 18.6-1.pgdg13+2), расширение — версия 1.12. В pgbench_accounts 2 000 000 строк, вся база 307 МБ при shared_buffers = 128MB и work_mem = 4MB.
Опыт 1: константы уходят, queryid остаётся
Три запроса отличаются только значением aid:
SELECT pg_stat_statements_reset();
SELECT abalance FROM pgbench_accounts WHERE aid = 17;
SELECT abalance FROM pgbench_accounts WHERE aid = 250000;
SELECT abalance FROM pgbench_accounts WHERE aid = 1999999;
SELECT queryid, query, calls, rows FROM pg_stat_statements WHERE query LIKE '%pgbench_accounts WHERE aid%' AND query NOT LIKE '%pg_stat%';вывод (в psql включён \x on):
-[ RECORD 1 ]-------------------------------------------------
queryid | 5409612748292285639
query | SELECT abalance FROM pgbench_accounts WHERE aid = $1
calls | 3
rows | 3Одна строка, три вызова. Тот же идентификатор печатает EXPLAIN (VERBOSE):
EXPLAIN (VERBOSE, COSTS OFF) SELECT abalance FROM pgbench_accounts WHERE aid = 17;вывод:
QUERY PLAN
-------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on public.pgbench_accounts
Output: abalance
Index Cond: (pgbench_accounts.aid = 17)
Query Identifier: 5409612748292285639
(4 rows)У работающей сессии идентификатор лежит в pg_stat_activity.query_id. В одной сессии выполняется SELECT pg_sleep(4), abalance FROM pgbench_accounts WHERE aid = 42, из другой читается query_id (вывод: -551396630635601600), после завершения по нему ищется строка статистики:
SELECT queryid, query, calls, round(total_exec_time::numeric) AS total_ms FROM pg_stat_statements WHERE queryid = -551396630635601600;вывод:
queryid | query | calls | total_ms
---------------------+--------------------------------------------------------------------+-------+----------
-551396630635601600 | SELECT pg_sleep($1), abalance FROM pgbench_accounts WHERE aid = $2 | 1 | 4003Идентификатор считается не по тексту, а по дереву разбора. В структуре Const значение отмечено атрибутом query_jumble_ignore, а комментарий над ней в REL_18_6 говорит: «Only the constant type OID is relevant for the query jumbling». Вместо значения хеш получает тип, а положение константы в тексте запоминает RecordConstLocation (queryjumblefuncs.c, строки 387–398):
/*
* Record the location of some kind of constant within a query string.
* These are not only bare constants but also expressions that ultimately
* constitute a constant, such as those inside casts and simple function
* calls; if extern_param, then it corresponds to a PARAM_EXTERN Param.
*
* If length is -1, it indicates a single such constant element. If
* it's a positive integer, it indicates the length of a squashable
* list of them.
*/
static void
RecordConstLocation(JumbleState *jstate, bool extern_param, int location, int len)Положения нужны затем, чтобы вместо каждой константы в тексте подставить $n. Это делает pgss_store (pg_stat_statements.c, строки 1348–1355), и только при создании записи (блок if (!entry), строка 1334):
if (jstate)
{
LWLockRelease(pgss->lock);
norm_query = generate_normalized_query(jstate, query,
query_location,
&query_len);
LWLockAcquire(pgss->lock, LW_SHARED);
}Отсюда следует, что query — текст первого вызова с подставленными $n. Список констант в IN в PostgreSQL 18 тоже сворачивается: после сброса ... WHERE aid IN (1, 2, 3) и ... IN (1, 2, 3, 4, 5, 6, 7) дали одну строку с calls = 2 и текстом SELECT count(*) FROM pgbench_accounts WHERE aid IN ($1 /*, ... */).
Опыт 2: таблица снимков и разность
Счётчики копятся с момента stats_since, а не за последнюю минуту. Чтобы увидеть, что происходило в окне, нужны два среза. Таблица и функция, которые их пишут, — это всё, что нужно:
CREATE TABLE pgss_snap AS
SELECT 0 AS snap_id, now() AS ts, s.* FROM pg_stat_statements s WITH NO DATA;
CREATE INDEX ON pgss_snap (snap_id, queryid);
CREATE SEQUENCE pgss_snap_seq;
CREATE FUNCTION pgss_take_snapshot() RETURNS int LANGUAGE sql AS $$
WITH id AS (SELECT nextval('pgss_snap_seq')::int AS n)
INSERT INTO pgss_snap SELECT id.n, now(), s.* FROM id, pg_stat_statements s
RETURNING snap_id
$$;Разность двух снимков — представление, в которое подставлены номера 2 и 6:
CREATE VIEW pgss_delta AS
SELECT b.queryid, b.query, b.calls - COALESCE(a.calls, 0) AS calls,
b.total_exec_time - COALESCE(a.total_exec_time, 0) AS total_ms,
b.shared_blks_read - COALESCE(a.shared_blks_read, 0) AS blks_read,
b.shared_blks_hit - COALESCE(a.shared_blks_hit, 0) AS blks_hit,
b.shared_blks_dirtied - COALESCE(a.shared_blks_dirtied, 0) AS blks_dirtied,
b.wal_bytes - COALESCE(a.wal_bytes, 0) AS wal_bytes,
b.temp_blks_written - COALESCE(a.temp_blks_written, 0) AS temp_written
FROM pgss_snap b
LEFT JOIN pgss_snap a ON a.queryid = b.queryid AND a.snap_id = 2
WHERE b.snap_id = 6;LEFT JOIN с COALESCE нужен для запросов, которых не было в первом снимке. Разностью можно получить только аддитивные счётчики. Среднее восстанавливается как Δ total_exec_time / Δ calls, а min, max и stddev вычитанием не получить.
Нормальную нагрузку даёт tpcb-like, а испорченный запрос лежит в собственном скрипте bad.pgb:
\set bid random(1, 20)
SELECT * FROM pgbench_accounts WHERE bid = :bid ORDER BY filler;По bid индекса нет, а 100 000 строк одного bid с сортировкой по filler не помещаются в work_mem. Запуск на 62 секунды, снимки каждые 15 секунд (скрипты сначала копируются docker cp в /tmp контейнера):
docker exec -d $C bash -c "printf 'SELECT pgss_take_snapshot();\n\\\\watch i=15 c=5\n' | psql -U postgres -q"
docker exec -d $C pgbench -U postgres -n -f /tmp/bad.pgb -c 1 -R 1 -T 62 postgres
docker exec $C pgbench -U postgres -n -b tpcb-like -c 4 -j 2 -T 62 postgrespgbench показал 100 620 транзакций и 1622,9 tps. Снимки 1 и 2 сделаны одновременно (первый запуск запроса и первая итерация \watch), поэтому окно считается от снимка 2 до снимка 6: с 00:52:21 до 00:53:21, ровно 60 секунд. Пять топов:
SELECT left(query,50) q, calls, round(total_ms) total_ms FROM pgss_delta WHERE calls>0 ORDER BY total_ms DESC LIMIT 5;
SELECT left(query,50) q, calls FROM pgss_delta WHERE calls>0 ORDER BY calls DESC LIMIT 5;
SELECT left(query,50) q, blks_read, blks_hit FROM pgss_delta ORDER BY blks_read DESC LIMIT 5;
SELECT left(query,50) q, pg_size_pretty(wal_bytes) wal FROM pgss_delta ORDER BY wal_bytes DESC LIMIT 5;
SELECT left(query,50) q, temp_written, pg_size_pretty(temp_written*8192) temp FROM pgss_delta ORDER BY temp_written DESC LIMIT 5;вывод (по одному на метрику, Δ за окно):
=== по времени
UPDATE pgbench_branches SET bbalance = bbalance + | 97617 | 16913
SELECT pg_sleep($1) | 24 | 7205
SELECT * FROM pgbench_accounts WHERE bid = $1 ORDE | 60 | 3446
=== по вызовам
BEGIN | 97642
=== по чтению блоков (read | hit)
SELECT * FROM pgbench_accounts WHERE bid = $1 ORDE | 1307995 | 685132
UPDATE pgbench_accounts SET abalance = abalance + | 91721 | 687119
=== по WAL
UPDATE pgbench_accounts SET abalance = abalance + | 14 MB
UPDATE pgbench_branches SET bbalance = bbalance + | 7663 kB
=== по temp (блоков | размер)
SELECT * FROM pgbench_accounts WHERE bid = $1 ORDE | 77892 | 609 MB(у каждого топа оставлены первые строки). Что видно:
- По времени испорченный
SELECTтолько третий, 3446 мс против 16 913 мс уUPDATE pgbench_branches. Вторая строка,pg_sleep, — не запрос приложения, а сон скрипта-блокировщика из опыта 3 внутри транзакции. - По вызовам лидирует служебный
BEGIN(97 642): этот топ отвечает на другой вопрос, чем время, — что приложение гоняет чаще всего. - По чтению блоков испорченный запрос первый с большим отрывом: 1 307 995 блоков за 60 вызовов, около 21 800 блоков на вызов, а hit у него всего 685 132 из 1 993 127. Это
shared_blks_read, то есть блоки не изshared_buffers; из диска они пришли или из кэша файловой системы, счётчик не различает. Различаетshared_blk_read_timeприtrack_io_timing. - По WAL первой идёт нормальная запись:
UPDATE pgbench_accountsоставил 14 МБ за 97 618 вызовов. - По
tempтолько он: 77 892 блока, 609 МБ за окно, около 10 МБ на вызов. План подтверждает причину:
EXPLAIN (ANALYZE, BUFFERS, VERBOSE, COSTS OFF, TIMING OFF, SUMMARY OFF) SELECT * FROM pgbench_accounts WHERE bid = 7 ORDER BY filler;вывод (отфильтрован grep -E 'Sort Method|Query Identifier|Seq Scan|Buffers', повторы рабочих процессов убраны):
Buffers: shared hit=12552 read=20838 dirtied=11, temp read=1313 written=1316
Sort Method: external merge Disk: 3208kB
-> Parallel Seq Scan on public.pgbench_accounts (actual rows=33333.33 loops=3)
Query Identifier: 2631783761524797523Query Identifier: 2631783761524797523 — queryid, под которым этот запрос стоял в pg_stat_statements до сброса. Что значат external merge и Disk, объясняет спилл сортировки.
Опыт 3: ловушка среднего
pg_stat_statements хранит mean_exec_time, max_exec_time и stddev_exec_time. Среднее — единственное, что смотрят в обзорах, и именно оно гасит редкий выброс. Чтобы проверить, скрипт hot.pgb обновляет случайную из тысячи строк:
\set aid random(1, 1000)
UPDATE pgbench_accounts SET abalance = abalance - 1 WHERE aid = :aid;Параллельно скрипт locker.pgb раз в две секунды открывает транзакцию, правит такую же строку и держит её 0,3 секунды (pg_sleep(0.3), потом COMMIT). Запись, которая попала на эту строку, ждёт блокировку, остальные нет. За 62 секунды hot.pgb вызвал запрос 18 638 раз, блокировщик 24. Сортировка по среднему:
SELECT left(query,40) q, calls, round(mean_exec_time::numeric,3) mean, round(max_exec_time::numeric,1) max,
round(stddev_exec_time::numeric,2) sd, round((max_exec_time/mean_exec_time)::numeric) max_per_mean
FROM pg_stat_statements WHERE query ~ 'abalance - |abalance \+ |bbalance|tbalance' ORDER BY mean_exec_time;вывод:
q | calls | mean | max | sd | max_per_mean
------------------------------------------+--------+-------+-------+------+--------------
UPDATE pgbench_tellers SET tbalance = tb | 100620 | 0.023 | 13.1 | 0.17 | 573
UPDATE pgbench_accounts SET abalance = a | 100620 | 0.029 | 1.3 | 0.02 | 45
UPDATE pgbench_accounts SET abalance = a | 18638 | 0.031 | 182.5 | 1.49 | 5802
UPDATE pgbench_branches SET bbalance = b | 100620 | 0.175 | 79.6 | 0.98 | 455Третья строка — запрос из hot.pgb. Его среднее 0,031 мс неотличимо от соседнего UPDATE pgbench_accounts (0,029 мс), но максимум 182,5 мс: в 5802 раза больше среднего против 45 у соседа. У branches среднее выше (0,175 мс), там 20 строк на четырёх клиентов tpcb-like, и это постоянная очередь, а не редкий выброс. Ранжировать нужно и по max_exec_time / mean_exec_time, и по stddev_exec_time, а не по одному среднему.
Максимум в pg_stat_statements — не окно, а значение с minmax_stats_since. Для окна сбрасывают только его: pg_stat_statements_reset(0, 0, 0, true) обнуляет min и max, не трогая вызовы и время. После этого hot.pgb отработал ещё 20 секунд без блокировщика:
q | calls | mean | max | sd | max_per_mean
------------------------------------------+--------+-------+-----+------+--------------
UPDATE pgbench_accounts SET abalance = a | 24585 | 0.028 | 0.1 | 1.30 | 2max стал 0,1 мс, а stddev_exec_time остался 1,30: minmax_only его не трогает, и выброс из первого прогона в нём остался (mean и calls тоже накопительные). Поэтому сброс min/max делают в начале каждого окна вместе с новым снимком, а stddev годится для первого взгляда.
Что из этого следует
- Строка статистики — тип запроса, а не вызов: константы там не хранятся. Конкретный медленный вызов ищут в логе (
log_min_duration_statement) и сопоставляют поqueryid. - Накопительные итоги стареют: снимай статистику в таблицу по расписанию и читай разность, полный сброс стирает историю.
- Пять топов отвечают на разные вопросы. Испорченный запрос опыта третий по времени и первый по чтению блоков и по
temp, по одному времени его не найти. - Среднее прячет хвост: нужны
max_exec_time,stddev_exec_timeи сбросminmax_onlyв начале окна. pg_stat_kcache(расширение сообщества, отдельное от contrib) по README добавляет к каждомуqueryidпроцессорное время и реальные чтения файловой системы. В этом опыте он не запускался, цифр по нему нет.
Чек-лист
shared_preload_libraries = 'pg_stat_statements'иcompute_query_id = on(в опыте такжеtrack_io_timing = on).- Таблица снимков и разность: снимай раз в минуту-пять, храни недели,
pg_stat_statements_reset(0, 0, 0, true)— в начале окна. - Смотри все пять топов, а не один: время, вызовы,
shared_blks_read,wal_bytes,temp_blks_written; для хвоста добавьmax_exec_time / mean_exec_time. - Следи за ёмкостью:
pg_stat_statements.maxпо умолчанию 5000 записей, счётчик вытесненийdeallocлежит вpg_stat_statements_info(в опыте 0). - Контейнер с данными опыта убери вместе с томом:
docker rm -f -v dba-pg-stat-statements-workload-analysis.