Запросы замедлились, а в pg_stat_activity видно, что сеансы чего-то ждут. Представление отвечает на вопрос «чего» только про это мгновение: каждая сессия пишет в свою ячейку общей памяти одно число, класс и номер события, а накопительных счётчиков ожиданий в PostgreSQL нет. Поэтому профиль («на что уходит время») строится выборкой: расширение pg_wait_sampling читает эти ячейки каждые 10 мс и считает попадания. Три нагрузки на одной базе дали три разных профиля: Lock:transactionid с Lock:tuple у конкурирующих UPDATE (матрица и очередь блокировок), IO:DataFileRead при кэше shared_buffers, который меньше данных, и CPU вместе с ожиданием клиента, когда всё лежит в памяти.
Одна база, три нагрузки, три профиля ожиданий
pg_wait_sampling_profile показывает «ничего не ждёт» у чтения из памяти, IO:DataFileRead у чтения с диска и очередь на строке у конкурирующих обновлений.Стенд
Образ на базе postgres:18 с расширением из репозитория PGDG, который в образе уже подключён. Версия пакета и сервера:
cat > Dockerfile <<'DOCKER'
FROM postgres:18
RUN apt-get update && apt-get install -y --no-install-recommends postgresql-18-pg-wait-sampling && rm -rf /var/lib/apt/lists/*
DOCKER
docker build -t dba-wait-events-profiling:local .
docker run -d --name dba-wait-events-profiling --memory 1500m -e POSTGRES_PASSWORD=pg \
dba-wait-events-profiling:local \
-c shared_preload_libraries=pg_wait_sampling,pg_stat_statements \
-c shared_buffers=32MB -c compute_query_id=on -c pg_wait_sampling.profile_queries=true
docker exec -i dba-wait-events-profiling psql -U postgresCREATE EXTENSION pg_wait_sampling;
CREATE EXTENSION pg_stat_statements;
SELECT version(); version
--------------------------------------------------------------------------------------------------------------------
PostgreSQL 18.6 (Debian 18.6-1.pgdg13+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 14.2.0-19) 14.2.0, 64-bit
(1 row)Версия пакета из образа (dpkg -s postgresql-18-pg-wait-sampling): 1.1.11-1.pgdg13+1.
shared_preload_libraries читается при старте: расширению нужны общая память и фоновый процесс-сборщик, поэтому сервер перезапускают. Данные и три скрипта pgbench:
D="docker exec -i dba-wait-events-profiling"
$D pgbench -U postgres -d postgres -i -s 40 -q
$D sh -c 'printf "\\set id random(1, 50000)\nSELECT abalance FROM pgbench_accounts WHERE aid = :id;\n" > /tmp/cpu.sql'
$D sh -c 'printf "\\set id random(1, 4000000)\nSELECT abalance FROM pgbench_accounts WHERE aid = :id;\n" > /tmp/disk.sql'
$D sh -c 'printf "BEGIN;\nUPDATE pgbench_accounts SET abalance = abalance + 1 WHERE aid = 1;\nSELECT pg_sleep(0.005);\nEND;\n" > /tmp/lock.sql'
$D psql -U postgres -At \
-c "SELECT pg_size_pretty(pg_relation_size('pgbench_accounts')), pg_size_pretty(pg_relation_size('pgbench_accounts_pkey'))"512 MB|86 MBshared_buffers в 32 МБ много меньше таблицы в 512 МБ. Контейнер ограничен 1500 МБ, и таблица помещается в кэш ОС: «диск» в опыте 2 — это чтение через кэш ОС, а не с физического носителя.
Как сессия сообщает ожидание
Список событий задан одним файлом, из которого генерируются и перечисления в C, и таблицы документации. Формат — имя в UPPER_SNAKE_CASE и описание через табуляцию; в разделе класса Client (wait_event_names.txt, строки 83–86, тег REL_18_6):
Section: ClassName - WaitEventClient
CLIENT_READ "Waiting to read data from the client."
CLIENT_WRITE "Waiting to write data to the client."CLIENT_READ превращается в видимое имя ClientRead. Классы Lock и LWLock в файле только описаны для документации, у них свой C-код.
Сообщает ожидание сам процесс, одной записью в память (wait_event.h, строки 68–76):
static inline void
pgstat_report_wait_start(uint32 wait_event_info)
{
/*
* Since this is a four-byte field which is always read and written as
* four-bytes, updates are atomic.
*/
*(volatile uint32 *) my_wait_event_info = wait_event_info;
}Ни блокировки, ни системного вызова: четырёхбайтное слово записывается целиком, поэтому его можно читать из другого процесса без захвата. Старший байт — класс, младшие 16 бит — событие; ноль означает «не ждёт». my_wait_event_info указывает на поле wait_event_info структуры PGPROC своего процесса (InitProcess в proc.c, строка 540). Отсюда два следствия: история не хранится нигде, видна только последняя запись; и NULL в pg_stat_activity.wait_event значит «сейчас не ждёт», а не «считает на CPU» — процесс может стоять в очереди планировщика ОС.
Опыт 1: что ждёт сессия прямо сейчас
Восемь клиентов pgbench обновляют одну строку, держа транзакцию открытой 5 мс (pg_sleep в lock.sql):
$D pgbench -U postgres -d postgres -n -c 8 -T 10 -f /tmp/lock.sqlЧерез несколько секунд из другого сеанса (три снимка подряд, показан первый):
SELECT wait_event_type, wait_event, state, count(*)
FROM pg_stat_activity
WHERE backend_type = 'client backend' AND pid <> pg_backend_pid()
GROUP BY 1, 2, 3 ORDER BY 4 DESC; wait_event_type | wait_event | state | count
-----------------+---------------+--------+-------
Lock | transactionid | active | 5
Lock | tuple | active | 2
Timeout | PgSleep | active | 1
(3 rows)Один сеанс держит строку и спит в pg_sleep (Timeout:PgSleep), остальные семеро ждут: пятеро конца его транзакции (Lock:transactionid) и двое блокировки кортежа (Lock:tuple). Описания из pg_wait_events: transactionid — «Waiting for a transaction to finish», tuple — «Waiting to acquire a lock on a tuple». Повторные снимки дали 4 и 3, затем снова 5 и 2: распределение между этими двумя событиями меняется от снимка к снимку, а состав «1 держит, 7 ждут» остался. Одного снимка достаточно, чтобы найти виновника, но не чтобы сказать, где уходит время: для этого нужна выборка.
Опыт 2: профиль через pg_wait_sampling
Сборщик запускается как фоновый процесс и обходит все PGPROC под разделяемой блокировкой ProcArrayLock (collector.c, функция probe_waits, строки 161–170, тег v1.1.11):
/* Iterate PGPROCs under shared lock */
LWLockAcquire(ProcArrayLock, LW_SHARED);
for (i = 0; i < ProcGlobal->allProcCount; i++)
{
HistoryItem item,
*observation;
PGPROC *proc = &ProcGlobal->allProcs[i];
if (!pgws_should_sample_proc(proc, &item.pid, &item.wait_event_info))
continue;Для каждого процесса берётся wait_event_info и, при profile_queries, идентификатор запроса, который расширение хранит в своём массиве pgws_proc_queryids. В профиль попадают и фоновые процессы, и бездействующие сеансы. Настройки (профиль каждые 10 мс, sample_cpu = on; profile_queries=true из команды запуска показан как top):
name | setting
----------------------------------+---------
pg_wait_sampling.history_period | 10
pg_wait_sampling.history_size | 5000
pg_wait_sampling.profile_period | 10
pg_wait_sampling.profile_pid | on
pg_wait_sampling.profile_queries | top
pg_wait_sampling.sample_cpu | on
(6 rows)При sample_cpu = on сеанс без ожидания записывается как строка с NULL вместо типа и события; в запросе ниже она названа CPU. Запрос убирает фоновые процессы по backend_type (их pid постоянны, клиентские сеансы pgbench к моменту запроса уже закрыты) и считает доли:
SELECT coalesce(event_type || ':' || event, 'CPU') AS wait,
sum(count) AS samples,
round(100.0 * sum(count) / sum(sum(count)) OVER (), 1) AS pct
FROM pg_wait_sampling_profile
WHERE pid NOT IN (SELECT pid FROM pg_stat_activity WHERE backend_type <> 'client backend')
GROUP BY event_type, event ORDER BY samples DESC LIMIT 5;Перед каждой нагрузкой в psql сбрасываются профиль и статистика запросов, затем 20 секунд pgbench:
SELECT pg_wait_sampling_reset_profile();
SELECT pg_stat_statements_reset();$D pgbench -U postgres -d postgres -n -c 4 -T 20 -f /tmp/cpu.sqlДля диска -f /tmp/disk.sql, для блокировок -c 8 -f /tmp/lock.sql. cpu.sql касается примерно 6 МБ таблицы и части индекса, они помещаются в shared_buffers; disk.sql ходит по всей таблице.
Три результата подряд. CPU, 4 клиента, 220 674 транзакции в секунду; диск, 4 клиента, 162 716; блокировки, 8 клиентов, 157 транзакций в секунду при средней задержке 50,8 мс и 5 мс самой работы:
wait | samples | pct
-------------------+---------+------
CPU | 5732 | 71.7
Client:ClientRead | 2268 | 28.4
(2 rows)
wait | samples | pct
--------------------+---------+------
CPU | 5007 | 62.6
Client:ClientRead | 1784 | 22.3
IO:DataFileRead | 1210 | 15.1
IO:AioIoCompletion | 1 | 0.0
(4 rows)
wait | samples | pct
--------------------+---------+------
Lock:transactionid | 7545 | 47.1
Lock:tuple | 6390 | 39.9
Timeout:PgSleep | 1584 | 9.9
IO:WalSync | 369 | 2.3
CPU | 95 | 0.6
(5 rows)Что видно:
Client:ClientRead22–28 % во всех трёх:pgbenchна том же хосте, и между запросами сеанс ждёт следующую команду клиента. Это ожидание клиента, а не базы.- Переход от первой нагрузки ко второй добавил
IO:DataFileRead15,1 %, а скорость упала с 220 тыс. до 163 тыс. транзакций в секунду. Чтение шло из кэша ОС, на настоящем диске доля была бы другой (не измерено); механизм двойного кэширования описан в статье проshared_buffers. - В третьей нагрузке 87 % времени сеансов занимают два события
Lock, аCPU— 0,6 %: запросы ждут не вычислений.
Связь с pg_stat_statements идёт по queryid. Профиль по запросам, а не по базе в целом:
SELECT left(s.query, 38) AS query, w.samples, round(s.total_exec_time / 10) AS exec_ms_div_10
FROM (SELECT queryid, sum(count) AS samples FROM pg_wait_sampling_profile
WHERE queryid <> 0 GROUP BY 1) w
JOIN pg_stat_statements s USING (queryid) ORDER BY w.samples DESC LIMIT 2; query | samples | exec_ms_div_10
----------------------------------------+---------+----------------
UPDATE pgbench_accounts SET abalance = | 13990 | 13984
SELECT pg_sleep($1) | 1592 | 1596
(2 rows)Число выборок на запрос совпадает с total_exec_time, делённым на период 10 мс: 13 990 против 13 984 для UPDATE и 1592 против 1596 для pg_sleep. Так выборка проверяется: если числа не сходятся, нагрузка слишком короткая или профиль сбрасывали посередине.
Опыт 3: то же на MySQL 8.4
performance_schema в MySQL ведёт не выборку, а точные счётчики по каждому событию. Для ожиданий включаются инструменты wait/%:
docker run -d --name dba-wait-events-profiling-my --memory 1g -e MYSQL_ROOT_PASSWORD=my mysql:8.4CREATE DATABASE t; USE t;
CREATE TABLE acc (aid INT PRIMARY KEY, bal INT) ENGINE=InnoDB;
INSERT INTO acc VALUES (1,0),(2,0);
DELIMITER //
CREATE PROCEDURE hot(n INT) BEGIN
DECLARE i INT DEFAULT 0;
WHILE i < n DO
START TRANSACTION; UPDATE acc SET bal = bal + 1 WHERE aid = 1; DO SLEEP(0.005); COMMIT;
SET i = i + 1;
END WHILE;
END//
DELIMITER ;
UPDATE performance_schema.setup_instruments SET ENABLED='YES', TIMED='YES' WHERE NAME LIKE 'wait/%';
TRUNCATE performance_schema.events_waits_summary_global_by_event_name;Восемь сеансов параллельно вызывают CALL hot(250) (в конце bal = 2000), затем:
SELECT EVENT_NAME, COUNT_STAR, ROUND(SUM_TIMER_WAIT/1e12, 2) AS total_s
FROM performance_schema.events_waits_summary_global_by_event_name
WHERE COUNT_STAR > 0 AND EVENT_NAME NOT LIKE 'wait/synch/cond/mysqlx/%' ORDER BY SUM_TIMER_WAIT DESC LIMIT 4;
SHOW GLOBAL STATUS LIKE 'Innodb_row_lock_time';
SHOW GLOBAL STATUS LIKE 'Innodb_row_lock_waits';
SELECT COUNT_FETCH, ROUND(SUM_TIMER_FETCH/1e12, 2) AS fetch_s
FROM performance_schema.table_io_waits_summary_by_table WHERE OBJECT_SCHEMA = 't' AND OBJECT_NAME = 'acc';EVENT_NAME COUNT_STAR total_s
wait/io/table/sql/handler 4000 97.14
wait/synch/cond/sql/Item_func_sleep::cond 2000 10.06
wait/io/file/innodb/innodb_log_file 11125 3.75
wait/io/file/sql/binlog 4000 1.87
Variable_name Value
Innodb_row_lock_time 97109
Variable_name Value
Innodb_row_lock_waits 1999
COUNT_FETCH fetch_s
2001 97.12Строка wait/io/table/sql/handler (97,14 с) — это и есть очередь на строке: те же секунды стоят в Innodb_row_lock_time (97 109 мс) и в обращениях fetch к таблице acc (97,12 с при 2001 обращении). Блокирующее чтение внутри UPDATE учтено как ввод-вывод таблицы. Имени «ожидание блокировки строки» в сводке нет, а сводка глобальная: ни queryid, ни дайджеста в ней нет. Счётчики не требуют выборки, но инструменты включаются заранее (накладные расходы не измерялись), а то, что 97 с — именно блокировка, подтверждает только Innodb_row_lock_*.
Что из этого следует
- В PostgreSQL ожидания читают двумя способами:
pg_stat_activityотвечает «кто и чего ждёт сейчас», профиль черезpg_wait_sampling— «на что уходит время». Первое находит виновника блокировки (держатель вpg_sleep), второе показывает долю (87 % уLock). - Класс события подсказывает, куда идти.
Lock:*— к очереди блокировок и к приложению, которое держит транзакцию открытой;IO:DataFileRead— к размеруshared_buffersи плану запроса;Client:ClientRead— к приложению и сети, а не к базе. - Идея профиля активных сессий пришла из Oracle:
V$ACTIVE_SESSION_HISTORYраз в секунду снимает активные сеансы.pg_wait_samplingснимает все процессы каждые 10 мс, поэтому видит и простой (ClientRead). - В MySQL ожидание строки отдельным событием не видно: время лежит в
wait/io/table/sql/handler, а назвать его блокировкой помогаетInnodb_row_lock_time.
Чек-лист
- Подключи
pg_wait_samplingиpg_stat_statementsчерезshared_preload_libraries(нужен перезапуск) и включиcompute_query_id: без них нет ни профиля, ни связи сqueryid. - Начни с
pg_stat_activity:GROUP BY wait_event_type, wait_event, stateпо клиентским сеансам находит держателя блокировки одним снимком. - Перед нагрузкой сбрось профиль
pg_wait_sampling_reset_profile(), исключи фоновые процессы поbackend_typeи сверь: выборки × период должны даватьtotal_exec_timeизpg_stat_statements. - Читай доли по классам:
Lockведёт к транзакциям приложения,IO— к кэшу и планам,Client:ClientRead— к приложению и сети. - Убери стенд:
docker rm -f -v dba-wait-events-profiling dba-wait-events-profiling-my && docker rmi dba-wait-events-profiling:local.