Настройка

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

=> 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 - штатной утилитой для запуска эталонных тестов.

Сначала утилита создает набор таблиц и заполняет их данными.

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.12 s, remaining 0.00 s)
vacuum...
set primary keys...
done.

Затем сбросим все накопленные ранее статистики.

=> 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: 9455
latency average = 1.058 ms
tps = 945.440112 (including connections establishing)
tps = 945.707311 (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            | 18910
idx_tup_fetch       | 18910
n_tup_ins           | 0
n_tup_upd           | 9455
n_tup_del           | 0
n_tup_hot_upd       | 7848
n_live_tup          | 0
n_dead_tup          | 3169
n_mod_since_analyze | 9455
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   | 34979
idx_blks_read   | 221
idx_blks_hit    | 41025
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      | 18910
idx_tup_read  | 20642
idx_tup_fetch | 18910

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

А также варианты для пользовательских и системных объектов (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    | 9469
xact_rollback  | 0
blks_read      | 346
blks_hit       | 123826
tup_returned   | 126223
tup_fetched    | 19091
tup_inserted   | 9455
tup_updated    | 28366
tup_deleted    | 0
conflicts      | 0
temp_files     | 0
temp_bytes     | 0
deadlocks      | 0
blk_read_time  | 4.343
blk_write_time | 0
stats_reset    | 2018-02-25 22:51:55.531241+03


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

=> CHECKPOINT;
CHECKPOINT
=> SELECT * FROM pg_stat_bgwriter \gx
-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 0
checkpoints_req       | 1
checkpoint_write_time | 34
checkpoint_sync_time  | 18
buffers_checkpoint    | 1954
buffers_clean         | 0
maxwritten_clean      | 0
buffers_backend       | 1701
buffers_backend_fsync | 0
buffers_alloc         | 386
stats_reset           | 2018-02-25 22:51:55.576603+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              | 12673
query            | UPDATE t SET n = n + 1;
state            | idle in transaction
wait_event       | ClientRead
wait_event_type  | Client
pg_blocking_pids | {}
-[ RECORD 2 ]----+-----------------------------------------------------------------------------
pid              | 12051
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              | 12725
query            | UPDATE t SET n = n + 2;
state            | active
wait_event       | transactionid
wait_event_type  | Lock
pg_blocking_pids | {12673}


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 |         10080 | 12725 | ShareLock     | f
 transactionid |         10080 | 12673 | 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             | 12051
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             | 12725
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  
-------+---------------------+-------------------------------+--------
  4717 | background worker   | 2018-02-25 22:51:36.843101+03 | 
  4715 | autovacuum launcher | 2018-02-25 22:51:36.843686+03 | 
 12051 | client backend      | 2018-02-25 22:51:54.978301+03 | active
 12725 | client backend      | 2018-02-25 22:52:06.656478+03 | idle
  4713 | background writer   | 2018-02-25 22:51:36.844799+03 | 
  4712 | checkpointer        | 2018-02-25 22:51:36.845174+03 | 
  4714 | walwriter           | 2018-02-25 22:51:36.844419+03 | 
(7 rows)


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

postgres$ ps -o pid,command --ppid `head -n 1 $PGDATA/postmaster.pid`
  PID COMMAND
 4712 postgres: checkpointer process   
 4713 postgres: writer process   
 4714 postgres: wal writer process   
 4715 postgres: autovacuum launcher process   
 4716 postgres: stats collector process   
 4717 postgres: bgworker: logical replication launcher   
12051 postgres: postgres admin_monitoring [local] idle
12725 postgres: postgres admin_monitoring [local] idle

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


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

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

postgres$ grep FATAL /home/postgres/logfile | tail -n 10
2018-02-25 22:51:08.574 MSK [30896] FATAL:  terminating logical replication worker due to administrator command
2018-02-25 22:51:38.763 MSK [5816] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:41.733 MSK [7040] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:43.096 MSK [7644] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:44.007 MSK [7936] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:47.294 MSK [9400] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:49.137 MSK [10243] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:51.650 MSK [11084] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:51:54.369 MSK [11948] FATAL:  lock file "postmaster.pid" already exists
2018-02-25 22:52:06.941 MSK [12673] 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        
------------------
 500125.155604011
(1 row)


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

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

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