Настройка

Вначале включим сбор статистики ввода-вывода и выполнения функций.

=> 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: 9551
latency average = 1.047 ms
tps = 955.089049 (including connections establishing)
tps = 955.373543 (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            | 19102
idx_tup_fetch       | 19102
n_tup_ins           | 0
n_tup_upd           | 9551
n_tup_del           | 0
n_tup_hot_upd       | 7946
n_live_tup          | 0
n_dead_tup          | 3162
n_mod_since_analyze | 9551
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   | 35252
idx_blks_read   | 221
idx_blks_hit    | 41382
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      | 19102
idx_tup_read  | 20826
idx_tup_fetch | 19102

=> 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  | 41382

А также варианты для пользовательских и системных объектов (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    | 9561
xact_rollback  | 0
blks_read      | 331
blks_hit       | 124928
tup_returned   | 127456
tup_fetched    | 19276
tup_inserted   | 9551
tup_updated    | 28654
tup_deleted    | 0
conflicts      | 0
temp_files     | 0
temp_bytes     | 0
deadlocks      | 0
blk_read_time  | 3.967
blk_write_time | 0
stats_reset    | 2018-12-24 17:29:50.481458+03


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

=> CHECKPOINT;
CHECKPOINT
=> SELECT * FROM pg_stat_bgwriter \gx
-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 0
checkpoints_req       | 1
checkpoint_write_time | 38
checkpoint_sync_time  | 19
buffers_checkpoint    | 1954
buffers_clean         | 0
maxwritten_clean      | 0
buffers_backend       | 1701
buffers_backend_fsync | 0
buffers_alloc         | 392
stats_reset           | 2018-12-24 17:29:50.529577+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              | 27646
query            | UPDATE t SET n = n + 1;
state            | idle in transaction
wait_event       | ClientRead
wait_event_type  | Client
pg_blocking_pids | {}
-[ RECORD 2 ]----+-----------------------------------------------------------------------------
pid              | 27110
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              | 27698
query            | UPDATE t SET n = n + 2;
state            | active
wait_event       | transactionid
wait_event_type  | Lock
pg_blocking_pids | {27646}


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 |         10176 | 27698 | ShareLock     | f
 transactionid |         10176 | 27646 | ExclusiveLock | t
(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             | 27110
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             | 27698
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  
-------+---------------------+-------------------------------+--------
 19621 | background worker   | 2018-12-24 17:29:31.384358+03 | 
 19619 | autovacuum launcher | 2018-12-24 17:29:31.385311+03 | 
 27110 | client backend      | 2018-12-24 17:29:50.454655+03 | active
 27698 | client backend      | 2018-12-24 17:30:02.625863+03 | idle
 19617 | background writer   | 2018-12-24 17:29:31.386193+03 | 
 19616 | checkpointer        | 2018-12-24 17:29:31.38663+03  | 
 19618 | walwriter           | 2018-12-24 17:29:31.385882+03 | 
(7 rows)


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

postgres$ ps -o pid,command --ppid `head -n 1 $PGDATA/postmaster.pid`
  PID COMMAND
19616 postgres: checkpointer process   
19617 postgres: writer process   
19618 postgres: wal writer process   
19619 postgres: autovacuum launcher process   
19620 postgres: stats collector process   
19621 postgres: bgworker: logical replication launcher   
27110 postgres: postgres admin_monitoring [local] idle
27698 postgres: postgres admin_monitoring [local] idle

Можно заметить, что в pg_stat_activity не попадает процесс stats collector.


Анализ журнала

Посмотрим самый простой случай. Например, нас интересуют сообщения FATAL:

postgres$ grep FATAL /home/postgres/logfile | tail -n 10
2018-12-24 17:29:02.839 MSK [13550] FATAL:  terminating logical replication worker due to administrator command
2018-12-24 17:29:33.473 MSK [20715] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:36.533 MSK [21941] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:37.925 MSK [22545] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:38.825 MSK [22837] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:42.102 MSK [24301] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:43.967 MSK [25215] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:46.535 MSK [26056] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:29:49.329 MSK [26920] FATAL:  lock file "postmaster.pid" already exists
2018-12-24 17:30:02.914 MSK [27646] 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        
------------------
 499931.013367713
(1 row)


И посмотрим журнал:

postgres$ tail -n 1 /home/postgres/logfile
(pid=27110) LOG:  duration: 356.114 ms  statement: SELECT sum(random()) FROM generate_series(1,1000000);

Конец демонстрации.