Вначале включим сбор статистики ввода-вывода и выполнения функций.
=> 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.29 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: 9882 latency average = 1.012 ms tps = 988.128832 (including connections establishing) tps = 988.440421 (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 | 19764 idx_tup_fetch | 19764 n_tup_ins | 0 n_tup_upd | 9882 n_tup_del | 0 n_tup_hot_upd | 8273 n_live_tup | 0 n_dead_tup | 3168 n_mod_since_analyze | 9882 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 | 36273 idx_blks_read | 221 idx_blks_hit | 42756 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 | 19764 idx_tup_read | 21503 idx_tup_fetch | 19764
=> 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 | 42756
А также варианты для пользовательских и системных объектов (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 | 9892 xact_rollback | 0 blks_read | 333 blks_hit | 128982 tup_returned | 131774 tup_fetched | 19938 tup_inserted | 9882 tup_updated | 29647 tup_deleted | 0 conflicts | 0 temp_files | 0 temp_bytes | 0 deadlocks | 0 blk_read_time | 3.779 blk_write_time | 0 stats_reset | 2018-03-02 14:27:21.012132+03
Отдельно доступна статистика по процессам фоновой записи и контрольной точки, ввиду ее важности для мониторинга экземпляра:
=> CHECKPOINT;
CHECKPOINT
=> SELECT * FROM pg_stat_bgwriter \gx
-[ RECORD 1 ]---------+------------------------------ checkpoints_timed | 0 checkpoints_req | 1 checkpoint_write_time | 34 checkpoint_sync_time | 19 buffers_checkpoint | 1956 buffers_clean | 0 maxwritten_clean | 0 buffers_backend | 1703 buffers_backend_fsync | 0 buffers_alloc | 394 stats_reset | 2018-03-02 14:27:21.056587+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 | 31872 query | UPDATE t SET n = n + 1; state | idle in transaction wait_event | ClientRead wait_event_type | Client pg_blocking_pids | {} -[ RECORD 2 ]----+----------------------------------------------------------------------------- pid | 31334 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 | 31924 query | UPDATE t SET n = n + 2; state | active wait_event | transactionid wait_event_type | Lock pg_blocking_pids | {31872}
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 | 10507 | 31872 | ExclusiveLock | t transactionid | 10507 | 31924 | 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 | 31334 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 | 31924 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 -------+---------------------+-------------------------------+-------- 23914 | background worker | 2018-03-02 14:27:01.526247+03 | 23912 | autovacuum launcher | 2018-03-02 14:27:01.527299+03 | 31334 | client backend | 2018-03-02 14:27:20.986162+03 | active 31924 | client backend | 2018-03-02 14:27:33.133347+03 | idle 23910 | background writer | 2018-03-02 14:27:01.528208+03 | 23909 | checkpointer | 2018-03-02 14:27:01.528557+03 | 23911 | walwriter | 2018-03-02 14:27:01.527899+03 | (7 rows)
Сравним с тем, что показывает операционная система:
postgres$ ps -o pid,command --ppid `head -n 1 $PGDATA/postmaster.pid`
PID COMMAND 23909 postgres: checkpointer process 23910 postgres: writer process 23911 postgres: wal writer process 23912 postgres: autovacuum launcher process 23913 postgres: stats collector process 23914 postgres: bgworker: logical replication launcher 31334 postgres: postgres admin_monitoring [local] idle 31924 postgres: postgres admin_monitoring [local] idle
Можно заметить, что в pg_stat_activity не попадает процесс stats collector.
Посмотрим самый простой случай. Например, нас интересуют сообщения FATAL:
postgres$ grep FATAL /home/postgres/logfile | tail -n 10
2018-03-02 14:26:31.540 MSK [17840] FATAL: terminating logical replication worker due to administrator command 2018-03-02 14:27:03.405 MSK [25008] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:06.468 MSK [26232] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:07.986 MSK [26840] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:08.912 MSK [27132] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:12.435 MSK [28596] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:14.434 MSK [29439] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:17.037 MSK [30280] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:19.784 MSK [31144] FATAL: lock file "postmaster.pid" already exists 2018-03-02 14:27:33.417 MSK [31872] 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 ------------------ 500291.230051417 (1 row)
И посмотрим журнал:
postgres$ tail -n 1 /home/postgres/logfile
(pid=31334) LOG: duration: 352.617 ms statement: SELECT sum(random()) FROM generate_series(1,1000000);
Конец демонстрации.