← назад к разделу

Готовый отчёт нагрузки — удобная вещь, но однажды выясняется, что поставить его некуда: база чужая, доступ только на чтение, разбираться надо сейчас. Хорошая новость в том, что все числа отчёта PostgreSQL считает сам и отдаёт обычными запросами — инструмент лишь красиво их складывает.

Эта статья — про то, откуда каждый раздел берётся. Читать её полезно и без всякой аварии: когда понимаешь, из какой колонки выросло число в отчёте, перестаёшь верить ему на слово.

Как читать сам отчёт и ставить по нему диагноз — в соседней статье. Все запросы ниже выполнены на PostgreSQL 16; где версии расходятся, я говорю об этом отдельно.

Почему нельзя просто спросить «что было с двух до четырёх»

Первое, обо что спотыкаются все, — статистика в PostgreSQL накопительная.

Это значит, что pg_stat_statements не хранит историю: он держит одну строку на запрос, и в ней сумма за всё время с момента запуска сервера или последнего сброса. Запрос, который вчера отработал двести раз, а сегодня двадцать тысяч, выглядит в ней как одна строка с общим итогом. Спросить «а сколько было между двумя и четырьмя» напрямую невозможно — этой информации там просто нет.

Поэтому все инструменты делают одно и то же: периодически сохраняют состояние счётчиков и потом вычитают одно из другого. Снимок плюс снимок — и разница между ними и есть отчёт за период.

Минимальное хранилище снимков — таблица и процедура, которая складывает в неё текущее состояние:

CREATE TABLE snap_statements (
    snap_id           int         NOT NULL,
    taken_at          timestamptz NOT NULL DEFAULT now(),
    queryid           bigint,
    query             text,
    calls             bigint,
    total_exec_time   double precision,
    rows              bigint,
    shared_blks_hit   bigint,
    shared_blks_read  bigint,
    temp_blks_written bigint,
    wal_bytes         numeric
);
CREATE SEQUENCE snap_seq;

CREATE PROCEDURE take_snapshot() LANGUAGE sql AS $$
    INSERT INTO snap_statements (snap_id, queryid, query, calls, total_exec_time, rows,
                                 shared_blks_hit, shared_blks_read, temp_blks_written, wal_bytes)
    SELECT currval('snap_seq'), queryid, left(query, 200), calls, total_exec_time, rows,
           shared_blks_hit, shared_blks_read, temp_blks_written, wal_bytes
      FROM pg_stat_statements
     WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database());
$$;

Дальше это вызывается по расписанию — из cron, pg_cron или чего угодно, что умеет ходить в базу: SELECT nextval('snap_seq'); CALL take_snapshot();. Шаг в пять минут — обычный выбор: реже нельзя, потому что короткий всплеск усреднится и пропадёт; чаще уже незачем.

Отчёт за интервал — это разница двух снимков по каждому запросу:

WITH b AS (SELECT * FROM snap_statements WHERE snap_id = :begin_id),
     e AS (SELECT * FROM snap_statements WHERE snap_id = :end_id)
SELECT round((e.total_exec_time - coalesce(b.total_exec_time, 0))::numeric, 1) AS total_ms,
       round((100 * (e.total_exec_time - coalesce(b.total_exec_time, 0))
              / nullif(sum(e.total_exec_time - coalesce(b.total_exec_time, 0)) OVER (), 0))::numeric, 1) AS pct,
       e.calls - coalesce(b.calls, 0) AS calls,
       round(((e.total_exec_time - coalesce(b.total_exec_time, 0))
              / nullif(e.calls - coalesce(b.calls, 0), 0))::numeric, 2) AS mean_ms,
       e.shared_blks_read - coalesce(b.shared_blks_read, 0) AS blks_read,
       pg_size_pretty(e.wal_bytes - coalesce(b.wal_bytes, 0)) AS wal,
       left(regexp_replace(e.query, '\s+', ' ', 'g'), 60) AS query
  FROM e LEFT JOIN b USING (queryid)
 WHERE e.total_exec_time - coalesce(b.total_exec_time, 0) > 0
 ORDER BY total_ms DESC
 LIMIT 20;

Здесь легко получить отчёт, который врёт, и не заметить этого.

Первое — как соединяются снимки. Запрос мог появиться уже внутри интервала: скажем, вышел новый релиз, и в нём новая выборка. В раннем снимке такой строки нет вообще, и при обычном JOIN она молча выпадет из отчёта — а это ровно тот случай, когда виновник и есть новичок. Поэтому соединение внешнее, а недостающие значения подменяются нулями через coalesce.

Второе — типы. Времена в pg_stat_statements хранятся как double precision, а функции round(double precision, integer) в PostgreSQL нет: запрос упадёт с сообщением про несуществующую функцию. Спасает приведение ::numeric — и это, пожалуй, самая частая ошибка при написании таких отчётов вручную.

Третье — сброс счётчиков. Если между снимками кто-то вызвал pg_stat_statements_reset(), поздний снимок окажется меньше раннего, и разница уйдёт в минус. Отрицательные числа в таком отчёте означают не аномалию нагрузки, а сброс статистики.

Дальше идут разделы отчёта. Запросы показаны в простом виде — по текущему состоянию счётчиков; чтобы получить «за период», каждый оборачивается той же разницей снимков.

Сколько всего работы сделала база

Прежде чем искать виноватых, стоит понять масштаб: период вообще был необычным или нагрузка была штатной, а плохо стало по другой причине. Это разные расследования, и путать их дорого.

Общую картину по базе даёт pg_stat_database:

SELECT datname,
       xact_commit, xact_rollback,
       tup_returned, tup_fetched, tup_inserted, tup_updated, tup_deleted,
       blks_read, blks_hit,
       round(100.0 * blks_hit / nullif(blks_hit + blks_read, 0), 2) AS hit_pct,
       temp_files, pg_size_pretty(temp_bytes) AS temp,
       deadlocks,
       round(blk_read_time::numeric, 1)  AS read_ms,
       round(blk_write_time::numeric, 1) AS write_ms
  FROM pg_stat_database
 WHERE datname = current_database();

Что тут важно понять про колонки.

xact_commit и xact_rollback — завершённые и откатившиеся транзакции. Небольшая доля откатов нормальна, заметная означает либо ошибки в приложении, либо срабатывающие таймауты; и то и другое стоит искать по журналам.

hit_pct — доля страниц, которые нашлись в буферном кэше и не потребовали чтения с диска. Низкое значение на нагруженной базе — сигнал, что рабочий набор перестал помещаться в память. Но и высокое ничего не гарантирует: прочитать миллион лишних страниц из кэша тоже дорого, просто дешевле, чем с диска.

Пара tup_returned и tup_fetched как раз про это. Первое — сколько строк база просмотрела, второе — сколько из них реально пригодилось. Когда первое в сотни раз больше второго, база честно перебирает таблицы там, где должна была прийти по индексу.

temp_files и temp_bytes — сортировки и соединения, которым не хватило work_mem и которые ушли на диск. А blk_read_time заполняется только при включённом track_io_timing: без него все времена ввода-вывода будут нулями, и половина отчёта окажется пустой. Накладные расходы на современном оборудовании небольшие, включать стоит.

Объём журнала считается отдельно — эта вьюха появилась в 14-й версии:

SELECT wal_records, wal_fpi, pg_size_pretty(wal_bytes) AS wal,
       wal_buffers_full, wal_write, wal_sync,
       round(wal_write_time::numeric, 1) AS write_ms,
       round(wal_sync_time::numeric, 1)  AS sync_ms
  FROM pg_stat_wal;

Отдельного внимания заслуживает wal_fpi — полностраничные образы. При первом изменении страницы после чекпоинта PostgreSQL пишет в журнал не разницу, а страницу целиком. Чем чаще чекпоинты, тем больше таких страниц, и запись растёт при той же нагрузке. Если объём журнала вырос, а приложение работает как раньше, смотреть надо сюда и на чекпоинты.

На чём стоит время: ожидания

Дальше вопрос «во что упирается». Сессия в каждый момент либо считает на процессоре, либо чего-то ждёт — диска, блокировки, соседа. Текущее состояние всех сессий видно в pg_stat_activity:

SELECT coalesce(wait_event_type, 'CPU') AS wait_type,
       coalesce(wait_event, 'on CPU')   AS wait_event,
       count(*) AS sessions
  FROM pg_stat_activity
 WHERE state = 'active'
   AND backend_type = 'client backend'
   AND pid <> pg_backend_pid()
 GROUP BY 1, 2
 ORDER BY sessions DESC;

Тут есть тонкость, которая сбивает с толку при первом знакомстве. Если сессия активна, а wait_event_type пустой — это не значит «ничего не ждёт и всё хорошо». Это значит, что она прямо сейчас работает на процессоре. Поэтому в запросе пустое значение подменяется на CPU: в отчётах эта строка обычно и называется «on CPU».

Проблема одного такого запроса в том, что он показывает мгновение. Чтобы говорить о долях времени за период, срезы нужно копить — и это следующий раздел.

Активные сессии за период: свой ASH

Идея, на которой построен весь раздел ASH в любом отчёте, простая: если раз в секунду записывать, кто чем занят, то доля сэмплов приблизительно равна доле времени. Двадцать сэмплов из ста с ожиданием блокировки — значит, примерно пятую часть периода система стояла на блокировках.

Хранилище и сборщик выглядят так:

CREATE TABLE ash (
    sample_at       timestamptz NOT NULL,
    pid             int,
    datname         text,
    usename         text,
    state           text,
    wait_event_type text,
    wait_event      text,
    query_id        bigint,
    xact_start      timestamptz,
    query           text
);

CREATE PROCEDURE take_ash_sample() LANGUAGE sql AS $$
    WITH s AS (SELECT clock_timestamp() AS ts)
    INSERT INTO ash
    SELECT s.ts, a.pid, a.datname, a.usename, a.state, a.wait_event_type, a.wait_event,
           a.query_id, a.xact_start, left(a.query, 100)
      FROM s, pg_stat_activity a
     WHERE a.backend_type = 'client backend'
       AND a.state = 'active'
       AND a.pid <> pg_backend_pid();
$$;

В этом коротком коде спрятаны две ошибки, каждая из которых ломает подсчёт молча — сборщик работает, таблица наполняется, а числа получаются неправильные.

Первая — время. Кажется естественным написать now(), но now() возвращает время начала транзакции и внутри неё не меняется. Сборщик, крутящийся циклом в одной транзакции, проставит всем сэмплам одинаковую метку, и период схлопнется в одно мгновение. Нужен clock_timestamp(), который берёт время по-настоящему сейчас.

Вторая тоньше. clock_timestamp() вычисляется для каждой строки отдельно — значит, две сессии, попавшие в один сэмпл, получат разные метки времени. После этого попытка посчитать «сколько всего было сэмплов» через count(DISTINCT sample_at) даст завышенное число: во столько раз, сколько сессий было активно. Поэтому время берётся один раз в отдельном подзапросе и приклеивается ко всем строкам сэмпла — за это отвечает WITH s AS (SELECT clock_timestamp()).

Когда сборщик работает, по накопленной таблице считается всё, ради чего он затевался:

-- Профиль ожиданий за период
SELECT coalesce(wait_event_type, 'CPU') AS wait_type,
       coalesce(wait_event, 'on CPU')   AS wait_event,
       count(*) AS samples,
       round(100.0 * count(*) / sum(count(*)) OVER (), 1) AS pct
  FROM ash
 WHERE sample_at BETWEEN :from AND :to
 GROUP BY 1, 2
 ORDER BY samples DESC;

-- Кто именно занимал время
SELECT pid, count(*) AS samples,
       round(100.0 * count(*) / (SELECT count(DISTINCT sample_at)
                                   FROM ash WHERE sample_at BETWEEN :from AND :to), 1) AS pct_of_time,
       coalesce(max(wait_event_type), 'CPU') AS wait_type,
       max(query_id) AS query_id,
       left(max(query), 60) AS query
  FROM ash
 WHERE sample_at BETWEEN :from AND :to
 GROUP BY pid
 ORDER BY samples DESC
 LIMIT 10;

Колонка query_id появилась в pg_stat_activity в 14-й версии и заполняется, когда включён compute_query_id — при значении auto он включается сам, если загружен pg_stat_statements. Именно она связывает два мира: по ней видно не просто «сессия стояла на блокировке», а какой конкретно запрос там стоял и сколько он суммарно стоит по данным топов.

Кто кого держит: блокировки

Когда в ожиданиях преобладает Lock, нужен следующий вопрос — кто держит. PostgreSQL отвечает на него функцией pg_blocking_pids(), которая для процесса возвращает список тех, кого он ждёт:

SELECT a.pid, a.state, a.wait_event_type, a.wait_event,
       now() - a.xact_start AS xact_age,
       pg_blocking_pids(a.pid) AS blocked_by,
       left(regexp_replace(a.query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_activity a
 WHERE a.backend_type = 'client backend'
   AND cardinality(pg_blocking_pids(a.pid)) > 0;

Дальше по этим номерам смотрят держателя — и почти всегда обнаруживают, что он не делает ничего тяжёлого. Типичная картина: сессия открыла транзакцию, обновила строку и ушла в idle in transaction, потому что приложение в этот момент ходило во внешний сервис. Виноват не запрос, а незакрытая транзакция; как это разбирать — в статье про блокировки.

Найти такие транзакции можно и заранее, не дожидаясь жалоб:

SELECT pid, state, wait_event_type, wait_event,
       now() - xact_start   AS xact_age,
       now() - state_change AS in_state,
       left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_activity
 WHERE backend_type = 'client backend'
   AND xact_start IS NOT NULL
   AND now() - xact_start > interval '1 minute'
 ORDER BY xact_start;

Долгая транзакция вредна не только тем, что кого-то блокирует. Пока она открыта, автовакуум не имеет права убрать мёртвые строки, которые она теоретически ещё может увидеть, — и таблица распухает у всех.

Обслуживание: вакуум и мёртвые строки

Раздел про обслуживание отвечает на вопрос, справляется ли база с уборкой за собой:

SELECT relname,
       n_live_tup, n_dead_tup,
       round(100.0 * n_dead_tup / nullif(n_live_tup + n_dead_tup, 0), 1) AS dead_pct,
       last_autovacuum, autovacuum_count, last_autoanalyze
  FROM pg_stat_user_tables
 ORDER BY n_dead_tup DESC
 LIMIT 10;

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

Что происходит с уборкой прямо сейчас, видно отдельно:

SELECT p.pid, p.datname, c.relname, p.phase,
       p.heap_blks_total, p.heap_blks_scanned, p.heap_blks_vacuumed,
       round(100.0 * p.heap_blks_scanned / nullif(p.heap_blks_total, 0), 1) AS scanned_pct
  FROM pg_stat_progress_vacuum p
  LEFT JOIN pg_class c ON c.oid = p.relid;

Такие же вьюхи прогресса есть для перестроения индекса и для CLUSTER — pg_stat_progress_create_index и pg_stat_progress_cluster. Полезны они тем, что превращают «оно висит уже час» в «просмотрено 60% страниц, осталось примерно столько же».

И последнее в этом разделе — таблицы, которые читаются целиком:

SELECT relname, seq_scan, seq_tup_read, idx_scan,
       pg_size_pretty(pg_relation_size(relid)) AS size,
       n_tup_ins, n_tup_upd, n_tup_del
  FROM pg_stat_user_tables
 ORDER BY seq_tup_read DESC
 LIMIT 10;

Большое seq_tup_read на большой таблице при почти нулевом idx_scan — самый частый источник лишнего чтения. Маленькую таблицу база и должна читать целиком, это дешевле индекса, поэтому размер здесь смотрится обязательно.

Топы SQL: четыре вопроса к одной таблице

pg_stat_statements — одна таблица, но отвечает она на разные вопросы в зависимости от того, как её отсортировать. Поэтому в отчётах не один топ, а несколько, и каждый ведёт к своему диагнозу.

Куда ушло время базы. Главный топ, с него начинают:

SELECT round(total_exec_time::numeric, 1) AS total_ms,
       round((100 * total_exec_time / nullif(sum(total_exec_time) OVER (), 0))::numeric, 1) AS pct,
       calls,
       round(mean_exec_time::numeric, 2) AS mean_ms,
       rows,
       shared_blks_hit, shared_blks_read, temp_blks_written,
       pg_size_pretty(wal_bytes::numeric) AS wal,
       left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_statements
 WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
 ORDER BY total_exec_time DESC
 LIMIT 10;

Колонка pct здесь важнее абсолютных миллисекунд: она сразу говорит, стоит ли вообще заниматься этой строкой. Запрос на 3% общего времени можно ускорить вдвое и не заметить разницы.

Не выполняется ли что-то в цикле. Тот же набор, отсортированный по числу вызовов:

SELECT calls,
       round(mean_exec_time::numeric, 3) AS mean_ms,
       round(total_exec_time::numeric, 1) AS total_ms,
       rows / nullif(calls, 0) AS rows_per_call,
       left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_statements
 ORDER BY calls DESC
 LIMIT 10;

Колонка rows_per_call добавлена не для красоты. Когда она равна единице, а вызовов сотни тысяч, картина почти однозначна: приложение в цикле достаёт записи по одной. Это не лечится индексом — запрос и так быстрый, их просто слишком много. Лечится пакетной выборкой на стороне сервиса.

Что читается с диска. Здесь ищут нехватку памяти и пропущенные индексы:

SELECT shared_blks_read, shared_blks_hit,
       round(100.0 * shared_blks_hit / nullif(shared_blks_hit + shared_blks_read, 0), 1) AS hit_pct,
       round(blk_read_time::numeric, 1) AS read_ms,
       left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_statements
 WHERE shared_blks_read > 0
 ORDER BY shared_blks_read DESC
 LIMIT 10;

Чему не хватило памяти на сортировку. Временные файлы — прямая подсказка про work_mem:

SELECT temp_blks_written,
       pg_size_pretty(temp_blks_written * 8192.0) AS temp,
       calls,
       left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS query
  FROM pg_stat_statements
 WHERE temp_blks_written > 0
 ORDER BY temp_blks_written DESC
 LIMIT 10;

Про версии здесь стоит помнить одно: имена колонок менялись. До 13-й версии время было одно и называлось total_time, без разделения на планирование и выполнение. В 17-й переименовали времена ввода-вывода: blk_read_time стал shared_blk_read_time, и рядом появились отдельные счётчики для локальных и временных блоков. Если готовый запрос падает на неизвестной колонке — почти наверняка дело в этом.

Состояние сервера: чекпоинты, архивация, возраст

Последний раздел отчёта — про сервер целиком, а не про отдельные запросы.

-- PostgreSQL 16 и раньше
SELECT checkpoints_timed, checkpoints_req,
       round(checkpoint_write_time::numeric / 1000, 1) AS ckpt_write_s,
       round(checkpoint_sync_time::numeric / 1000, 1)  AS ckpt_sync_s,
       buffers_checkpoint, buffers_clean, maxwritten_clean,
       buffers_backend, buffers_backend_fsync, buffers_alloc
  FROM pg_stat_bgwriter;

Главное здесь — соотношение двух первых колонок. Чекпоинт бывает плановый, по расписанию, и запрошенный — когда журнал вырос до max_wal_size и ждать больше нельзя. В здоровой системе плановых большинство. Перевес запрошенных означает, что база пишет чекпоинты чаще, чем задумано, а за этим тянется рост полностраничных образов, о которых говорилось выше.

В 17-й версии эту вьюху разделили: счётчики чекпоинтов уехали в pg_stat_checkpointer — там они называются num_timed и num_requested, — а в pg_stat_bgwriter остались только buffers_clean, maxwritten_clean и buffers_alloc.

Начиная с 16-й версии есть куда более подробный разрез ввода-вывода — по типам процессов:

SELECT backend_type, object, context,
       reads, round(read_time::numeric, 1) AS read_ms,
       writes, round(write_time::numeric, 1) AS write_ms,
       extends, hits, evictions
  FROM pg_stat_io
 WHERE reads > 0 OR writes > 0
 ORDER BY reads + writes DESC;

Он отвечает на вопрос, который раньше приходилось угадывать: кто именно нагружает диск — клиентские сессии, автовакуум или фоновая запись, и в каком режиме это происходит.

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

SELECT archived_count, last_archived_wal, last_archived_time,
       failed_count, last_failed_wal, last_failed_time
  FROM pg_stat_archiver;

Растущий failed_count означает, что журналы не уезжают. Последствий два, и оба неприятные: восстановление на точку во времени уже невозможно, а место под журналы рано или поздно закончится.

Возраст базы — то, о чём вспоминают поздно:

SELECT datname,
       age(datfrozenxid) AS xid_age,
       round(100.0 * age(datfrozenxid) / 2000000000, 1) AS pct_to_wraparound
  FROM pg_database
 ORDER BY xid_age DESC;

Номера транзакций в PostgreSQL конечны, и чтобы они не переполнились, старые строки периодически «замораживаются» вакуумом. Если этого не происходит, база приближается к пределу и в какой-то момент останавливает запись, уходя в аварийную уборку. Смотреть на этот процент стоит регулярно, а не когда он уже перевалил за восемьдесят.

И напоследок — настройки, особенно те, которые кто-то менял:

SELECT name, setting, unit, source, pending_restart
  FROM pg_settings
 WHERE source NOT IN ('default', 'override')
 ORDER BY name;

Колонка pending_restart со значением true означает, что параметр в файле изменили, а сервер не перезапустили: в конфигурации написано одно, работает другое. Удивительная доля долгих расследований заканчивается именно этой строкой.

Стоит ли собирать это самому

Запросы выше хороши тем, что работают везде, куда пустили psql, и не требуют ничего, кроме pg_stat_statements. Знать их полезно: это тот минимум, с которым можно разобраться в чужой базе, где никаких инструментов нет.

Но собирать из них собственный отчёт стоит только тогда, когда готовый поставить нельзя. У pg_profile и pgpro_pwr уже сделаны хранилище снимков, ротация, HTML и сравнение периодов — а самодельный сборщик придётся отлаживать ровно в тот момент, когда он нужнее всего.

Коротко

  • Статистика накопительная: «за период» получается только разницей двух снимков, отдельным запросом это не спросить.
  • В разностном запросе обязательны внешнее соединение (новый запрос отсутствует в раннем снимке) и ::numeric перед round; отрицательная разница означает сброс статистики, а не аномалию.
  • Пустой wait_event_type у активной сессии — это работа на процессоре, а не отсутствие ожиданий.
  • Сборщик ASH пишет clock_timestamp(), и метка времени берётся одна на сэмпл, иначе доли времени считаются неверно.
  • Топов SQL несколько, потому что это четыре разных диагноза: суммарное время, число вызовов, чтение с диска, временные файлы.
  • Запрошенных чекпоинтов больше плановых — база упирается в max_wal_size; растущий failed_count у архиватора — сломанное восстановление на точку во времени.
  • Версии: pg_stat_wal с 14-й, pg_stat_io с 16-й, в 17-й чекпоинты уехали в pg_stat_checkpointer, а времена ввода-вывода в pg_stat_statements переименованы в shared_blk_*.

Что почитать дальше

  • Отчёт нагрузки PostgreSQL — как читать готовый отчёт и ставить диагноз.
  • Мониторинг PostgreSQL — что держать на дашборде в реальном времени.
  • EXPLAIN и планы запросов — следующий шаг после того, как виновник найден.
  • VACUUM и распухание — почему растут мёртвые строки и чем это кончается.