Вначале включим сбор статистики ввода-вывода и выполнения функций.
=> ALTER SYSTEM SET track_io_timing=on;
ALTER SYSTEM
=> ALTER SYSTEM SET track_functions='all';
ALTER SYSTEM
=> SELECT pg_reload_conf();
pg_reload_conf ---------------- t (1 row)
Смотреть на активности сервера имеет смысл, когда какие-то активности на самом деле есть. Чтобы сымитировать нагрузку, воспользуемся pgbench - штатной утилитой для запуска эталонных тестов.
Сначала утилита создает набор таблиц и заполняет их данными.
=> CREATE DATABASE admin_monitoring;
CREATE DATABASE
postgres$ pgbench -i admin_monitoring
NOTICE: table "pgbench_history" does not exist, skipping NOTICE: table "pgbench_tellers" does not exist, skipping NOTICE: table "pgbench_accounts" does not exist, skipping NOTICE: table "pgbench_branches" does not exist, skipping creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done.
Затем сбросим все накопленные ранее статистики.
=> \c admin_monitoring
You are now connected to database "admin_monitoring" as user "postgres".
=> SELECT pg_stat_reset();
pg_stat_reset --------------- (1 row)
=> SELECT pg_stat_reset_shared('bgwriter');
pg_stat_reset_shared ---------------------- (1 row)
Теперь запускаем тест TPC-B на несколько секунд.
postgres$ pgbench -T 10 admin_monitoring
starting vacuum...end. transaction type: <builtin: TPC-B (sort of)> scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 9304 latency average = 1.075 ms tps = 930.308591 (including connections establishing) tps = 930.517389 (excluding connections establishing)
=> VACUUM pgbench_accounts;
VACUUM
Теперь мы можем посмотреть статистику обращения к таблицам в терминах строк:
=> SELECT * FROM pg_stat_all_tables WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-------+----------------- relid | 16519 schemaname | public relname | pgbench_accounts seq_scan | 0 seq_tup_read | 0 idx_scan | 18608 idx_tup_fetch | 18608 n_tup_ins | 0 n_tup_upd | 9304 n_tup_del | 0 n_tup_hot_upd | 7694 n_live_tup | 0 n_dead_tup | 3171 n_mod_since_analyze | 9304 last_vacuum | last_autovacuum | last_analyze | last_autoanalyze | vacuum_count | 0 autovacuum_count | 0 analyze_count | 0 autoanalyze_count | 0
И в терминах страниц:
=> SELECT * FROM pg_statio_all_tables WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]---+----------------- relid | 16519 schemaname | public relname | pgbench_accounts heap_blks_read | 25 heap_blks_hit | 34524 idx_blks_read | 221 idx_blks_hit | 40405 toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit |
Существуют аналогичные представления для индексов:
=> SELECT * FROM pg_stat_all_indexes WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-+---------------------- relid | 16519 indexrelid | 16530 schemaname | public relname | pgbench_accounts indexrelname | pgbench_accounts_pkey idx_scan | 18608 idx_tup_read | 20329 idx_tup_fetch | 18608
=> SELECT * FROM pg_statio_all_indexes WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-+---------------------- relid | 16519 indexrelid | 16530 schemaname | public relname | pgbench_accounts indexrelname | pgbench_accounts_pkey idx_blks_read | 221 idx_blks_hit | 40405
А также варианты для пользовательских и системных объектов (all, user, sys), для статистики текущей транзакции (pg_stat_xact*) и др.
Можно посмотреть глобальную статистику по всей базе данных:
=> SELECT * FROM pg_stat_database WHERE datname='admin_monitoring' \gx
-[ RECORD 1 ]--+----------------------------- datid | 16512 datname | admin_monitoring numbackends | 1 xact_commit | 9314 xact_rollback | 0 blks_read | 330 blks_hit | 121986 tup_returned | 124242 tup_fetched | 18782 tup_inserted | 9304 tup_updated | 27913 tup_deleted | 0 conflicts | 0 temp_files | 0 temp_bytes | 0 deadlocks | 0 blk_read_time | 4.578 blk_write_time | 0 stats_reset | 2019-03-31 15:25:42.27966+03
Здесь есть информация о количестве произошедших взаимоблокировок, зафиксированных и отмененных транзакций, использовании временных файлов.
Отдельно доступна статистика по процессам фоновой записи и контрольной точки, ввиду ее важности для мониторинга экземпляра:
=> CHECKPOINT;
CHECKPOINT
=> SELECT * FROM pg_stat_bgwriter \gx
-[ RECORD 1 ]---------+------------------------------ checkpoints_timed | 0 checkpoints_req | 1 checkpoint_write_time | 35 checkpoint_sync_time | 23 buffers_checkpoint | 1953 buffers_clean | 0 maxwritten_clean | 0 buffers_backend | 1700 buffers_backend_fsync | 0 buffers_alloc | 391 stats_reset | 2019-03-31 15:25:42.329588+03
Воспроизведем сценарий, в котором один процесс блокирует выполнение другого, и попробуем разобраться в ситуации с помощью системных представлений.
Создадим таблицу с одной строкой:
=> CREATE TABLE t(n integer);
CREATE TABLE
=> INSERT INTO t VALUES(42);
INSERT 0 1
Запустим два сеанса, один из которых изменяет таблицу и ничего не делает:
postgres$ psql -d admin_monitoring
=> BEGIN;
BEGIN
=> UPDATE t SET n = n + 1;
UPDATE 1
А второй пытается изменить ту же строку и блокируется:
postgres$ psql -d admin_monitoring
=> UPDATE t SET n = n + 2;
Посмотрим информацию об обслуживающих процессах:
=> SELECT pid, query, state, wait_event, wait_event_type, pg_blocking_pids(pid) FROM pg_stat_activity WHERE backend_type = 'client backend' \gx
-[ RECORD 1 ]----+-----------------------------------------------------------------------------
pid | 30562
query | UPDATE t SET n = n + 1;
state | idle in transaction
wait_event | ClientRead
wait_event_type | Client
pg_blocking_pids | {}
-[ RECORD 2 ]----+-----------------------------------------------------------------------------
pid | 30022
query | SELECT pid, query, state, wait_event, wait_event_type, pg_blocking_pids(pid)+
| FROM pg_stat_activity +
| WHERE backend_type = 'client backend'
state | active
wait_event |
wait_event_type |
pg_blocking_pids | {}
-[ RECORD 3 ]----+-----------------------------------------------------------------------------
pid | 30614
query | UPDATE t SET n = n + 2;
state | active
wait_event | transactionid
wait_event_type | Lock
pg_blocking_pids | {30562}
Cостояние idle in transaction означает, что сеанс начал транзакцию, но в настоящее время ничего не делает, а транзакция осталась незавершенной. Это может стать проблемой, если ситуация возникает систематически, например, из-за некорректной реализации приложения или из-за ошибок в драйвере - поскольку открытый сеанс расходует оперативную память.
Начиная с версии 9.6 в арсенале администратора появился параметр:
А мы покажем, как завершить блокирующий сеанс вручную. Сначала запомним номер заблокированного процесса:
=> SELECT pid as blocked_pid FROM pg_stat_activity WHERE backend_type = 'client backend' AND cardinality(pg_blocking_pids(pid)) > 0 \gset
В PostgreSQL версий ниже 9.6 нет функции pg_blocking_pids, но блокирующий процесс можно вычислить, используя запросы к таблице блокировок. Запрос покажет две строки: одна транзакция получила блокировку (granted), другая - нет и ожидает.
=> SELECT locktype, transactionid, pid, mode, granted FROM pg_locks WHERE transactionid IN ( SELECT transactionid FROM pg_locks WHERE pid = :blocked_pid AND NOT granted );
locktype | transactionid | pid | mode | granted ---------------+---------------+-------+---------------+--------- transactionid | 9929 | 30562 | ExclusiveLock | t transactionid | 9929 | 30614 | ShareLock | f (2 rows)
В общем случае нужно аккуратно учитывать тип блокировки.
Выполнение запроса можно прервать функцией pg_cancel_backend. В нашем случае транзакция простаивает, так что просто прерываем сеанс, вызвав pg_terminate_backend:
=> SELECT pg_terminate_backend(b.pid) FROM unnest(pg_blocking_pids(:blocked_pid)) AS b(pid);
pg_terminate_backend ---------------------- t (1 row)
Функция unnest нужна, поскольку pg_blocking_pids возвращает массив идентификаторов процессов, блокирующих искомый серверный процесс. В нашем примере блокирующий процесс один, но в общем случае их может быть несколько.
Проверим состояние серверных процессов.
=> SELECT pid, query, state, wait_event, wait_event_type FROM pg_stat_activity WHERE backend_type = 'client backend' \gx
-[ RECORD 1 ]---+------------------------------------------------------
pid | 30022
query | SELECT pid, query, state, wait_event, wait_event_type+
| FROM pg_stat_activity +
| WHERE backend_type = 'client backend'
state | active
wait_event |
wait_event_type |
-[ RECORD 2 ]---+------------------------------------------------------
pid | 30614
query | UPDATE t SET n = n + 2;
state | idle
wait_event | ClientRead
wait_event_type | Client
Осталось только два, причем заблокированный успешно завершил транзакцию.
Начиная с версии 10 представление pg_stat_activity показывает информацию не только про обслуживающие процессы, но и про служебные фоновые процессы экземпляра:
=> SELECT pid, backend_type, backend_start, state FROM pg_stat_activity;
pid | backend_type | backend_start | state -------+---------------------+-------------------------------+-------- 22616 | background worker | 2019-03-31 15:25:22.337945+03 | 22614 | autovacuum launcher | 2019-03-31 15:25:22.339051+03 | 30022 | client backend | 2019-03-31 15:25:42.252197+03 | active 30614 | client backend | 2019-03-31 15:25:54.465374+03 | idle 22612 | background writer | 2019-03-31 15:25:22.340118+03 | 22611 | checkpointer | 2019-03-31 15:25:22.340522+03 | 22613 | walwriter | 2019-03-31 15:25:22.339701+03 | (7 rows)
Сравним с тем, что показывает операционная система:
postgres$ ps -o pid,command --ppid `head -n 1 $PGDATA/postmaster.pid`
PID COMMAND 22611 postgres: checkpointer process 22612 postgres: writer process 22613 postgres: wal writer process 22614 postgres: autovacuum launcher process 22615 postgres: stats collector process 22616 postgres: bgworker: logical replication launcher 30022 postgres: postgres admin_monitoring [local] idle 30614 postgres: postgres admin_monitoring [local] idle
Можно заметить, что в pg_stat_activity не попадает процесс stats collector.
Посмотрим самый простой случай. Например, нас интересуют сообщения FATAL:
postgres$ grep FATAL /home/postgres/logfile | tail -n 10
2019-03-31 15:24:53.802 MSK [16551] FATAL: terminating logical replication worker due to administrator command 2019-03-31 15:25:24.354 MSK [23709] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:27.582 MSK [24944] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:29.020 MSK [25547] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:29.953 MSK [25838] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:33.326 MSK [27301] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:35.305 MSK [28143] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:38.027 MSK [28969] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:41.015 MSK [29832] FATAL: lock file "postmaster.pid" already exists 2019-03-31 15:25:54.769 MSK [30562] FATAL: terminating connection due to administrator command
Сообщение "terminating connection" вызвано тем, что мы завершали блокирующий процесс.
Обычное применение журнала - анализ наиболее продолжительных запросов. Добавим к строкам журнала номер процесса и включим вывод команд и времени их выполнения:
=> ALTER SYSTEM SET log_min_duration_statement=0;
ALTER SYSTEM
=> ALTER SYSTEM SET log_line_prefix='(pid=%p) ';
ALTER SYSTEM
=> SELECT pg_reload_conf();
pg_reload_conf ---------------- t (1 row)
Теперь выполним какую-нибудь команду:
=> SELECT sum(random()) FROM generate_series(1,1000000);
sum
------------------
500182.961182054
(1 row)
И посмотрим журнал:
postgres$ tail -n 1 /home/postgres/logfile
(pid=30022) LOG: duration: 364.589 ms statement: SELECT sum(random()) FROM generate_series(1,1000000);
Конец демонстрации.