First of all let's turn on statistics collection for I/O operations.
α=> ALTER SYSTEM SET track_io_timing=on;
ALTER SYSTEM
α=> SELECT pg_reload_conf();
pg_reload_conf ---------------- t (1 row)
There is no point in looking at the statistics when there is no activity, so let's emulate some workload using the pgbench utility. This is the standard PostgreSQL benchmarking utility.
First the utility creates a set of tables and fills them with particular amount of data.
α=> CREATE DATABASE admin_monitoring;
CREATE DATABASE
student$ pgbench -i admin_monitoring
dropping old tables... NOTICE: table "pgbench_accounts" does not exist, skipping NOTICE: table "pgbench_branches" does not exist, skipping NOTICE: table "pgbench_history" does not exist, skipping NOTICE: table "pgbench_tellers" does not exist, skipping creating tables... generating data... 100000 of 100000 tuples (100%) done (elapsed 0.15 s, remaining 0.00 s) vacuuming... creating primary keys... done.
Then we reset previously collected statistics to get zero counts.
α=> \c admin_monitoring
You are now connected to database "admin_monitoring" as user "student".
α=> SELECT pg_stat_reset();
pg_stat_reset --------------- (1 row)
α=> SELECT pg_stat_reset_shared('bgwriter');
pg_stat_reset_shared ---------------------- (1 row)
And then we start a benchmark (kind of TPC-B) for 10 seconds.
student$ 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: 8514 latency average = 1.175 ms tps = 851.333411 (including connections establishing) tps = 851.571912 (excluding connections establishing)
Now we can see the collected statistics, for example for tables in terms of accessed rows and access types:
α=> SELECT * FROM pg_stat_all_tables WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-------+----------------- relid | 17587 schemaname | public relname | pgbench_accounts seq_scan | 0 seq_tup_read | 0 idx_scan | 17028 idx_tup_fetch | 17028 n_tup_ins | 0 n_tup_upd | 8514 n_tup_del | 0 n_tup_hot_upd | 6914 n_live_tup | 0 n_dead_tup | 3131 n_mod_since_analyze | 8514 last_vacuum | last_autovacuum | last_analyze | last_autoanalyze | vacuum_count | 0 autovacuum_count | 0 analyze_count | 0 autoanalyze_count | 0
Or in terms of accessed pages:
α=> SELECT * FROM pg_statio_all_tables WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]---+----------------- relid | 17587 schemaname | public relname | pgbench_accounts heap_blks_read | 25 heap_blks_hit | 32102 idx_blks_read | 221 idx_blks_hit | 37212 toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit |
There are similar views for indexes:
α=> SELECT * FROM pg_stat_all_indexes WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-+---------------------- relid | 17587 indexrelid | 17601 schemaname | public relname | pgbench_accounts indexrelname | pgbench_accounts_pkey idx_scan | 17028 idx_tup_read | 18727 idx_tup_fetch | 17028
α=> SELECT * FROM pg_statio_all_indexes WHERE relid='pgbench_accounts'::regclass \gx
-[ RECORD 1 ]-+---------------------- relid | 17587 indexrelid | 17601 schemaname | public relname | pgbench_accounts indexrelname | pgbench_accounts_pkey idx_blks_read | 221 idx_blks_hit | 37212
Also there are views for user and system objects (all, user, sys), views for the current transaction statistics (pg_stat_xact*) and so on.
We can see database-level statistics:
α=> SELECT * FROM pg_stat_database WHERE datname='admin_monitoring' \gx
-[ RECORD 1 ]--+------------------------------ datid | 17580 datname | admin_monitoring numbackends | 1 xact_commit | 8524 xact_rollback | 0 blks_read | 326 blks_hit | 112432 tup_returned | 113956 tup_fetched | 17204 tup_inserted | 8514 tup_updated | 25543 tup_deleted | 0 conflicts | 0 temp_files | 0 temp_bytes | 0 deadlocks | 0 blk_read_time | 4.457 blk_write_time | 0 stats_reset | 2019-02-27 15:37:58.340606+03
And another view shows statistics for background writer and checkpointer processes statistics, and these numbers are very important for server monitoring:
α=> CHECKPOINT;
CHECKPOINT
α=> SELECT * FROM pg_stat_bgwriter \gx
-[ RECORD 1 ]---------+------------------------------ checkpoints_timed | 0 checkpoints_req | 1 checkpoint_write_time | 39 checkpoint_sync_time | 24 buffers_checkpoint | 1963 buffers_clean | 0 maxwritten_clean | 0 buffers_backend | 1713 buffers_backend_fsync | 0 buffers_alloc | 379 stats_reset | 2019-02-27 15:37:58.398756+03
Let's create a situation of one process locks another, and try to understand what's going on using system views.
First we'll create a single-row table:
α=> CREATE TABLE t(n integer);
CREATE TABLE
α=> INSERT INTO t VALUES(42);
INSERT 0 1
We'll start two sessions, one of which updates the row and just holds on:
student$ psql -d admin_monitoring
α=> BEGIN;
BEGIN
α=> UPDATE t SET n = n + 1;
UPDATE 1
While the other session tries to update the same row and hangs:
student$ psql -d admin_monitoring
α=> UPDATE t SET n = n + 2;
Activity statistics for backends:
α=> 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 | 14679
query | UPDATE t SET n = n + 1;
state | idle in transaction
wait_event | ClientRead
wait_event_type | Client
pg_blocking_pids | {}
-[ RECORD 2 ]----+-----------------------------------------------------------------------------
pid | 14140
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 | 14736
query | UPDATE t SET n = n + 2;
state | active
wait_event | transactionid
wait_event_type | Lock
pg_blocking_pids | {14679}
"Idle in transaction" state indicates that the session has started a transaction but currently there's no activity in it, and the transaction is not yet completed. This can be a problem if such state occurs regularly (for example due to errors in application implementation or in DBMS driver) because open transactions prevent vacuum from cleaning dead rows and hence lead to bloated tables and indexes.
Starting from version 9.6 there is the configuration parameter:
We'll show how to terminate the blocking session manually. First of all let's remember the blocked session:
α=> SELECT pid as blocked_pid FROM pg_stat_activity WHERE backend_type = 'client backend' AND cardinality(pg_blocking_pids(pid)) > 0 \gset
The is no pg_blocking_pids function in versions below 9.6; still we can determine the blocked session by querying the pg_locks table. We'll see a pair of rows: one for the transaction that acquired the lock (granted), and another for the blocked transaction.
α=> 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 | 45217 | 14736 | ShareLock | f transactionid | 45217 | 14679 | ExclusiveLock | t (2 rows)
In general the lock type must also be taken into account.
Running query can be interrupted by the pg_cancel_backend function. In this case the blocking session is idle, so we'll just terminate it by the pg_terminate_backend function:
α=> SELECT pg_terminate_backend(b.pid) FROM unnest(pg_blocking_pids(:blocked_pid)) AS b(pid);
pg_terminate_backend ---------------------- t (1 row)
The unnest function is required because pg_blocking_pids returns an array of process identifiers of blocking sessions. In this case we have just one blocking session, but in general there can be several of them.
Let's check the current state of backends.
α=> SELECT pid, query, state, wait_event, wait_event_type FROM pg_stat_activity WHERE backend_type = 'client backend' \gx
-[ RECORD 1 ]---+------------------------------------------------------
pid | 14140
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 | 14736
query | UPDATE t SET n = n + 2;
state | idle
wait_event | ClientRead
wait_event_type | Client
Only two of them left, and previously blocked session successfully completed its transaction.
Starting from version 10, the pg_stat_activity view shows information not only on backends, but also on internal background processes:
α=> SELECT pid, backend_type, backend_start, state FROM pg_stat_activity;
pid | backend_type | backend_start | state -------+------------------------------+-------------------------------+-------- 9265 | logical replication launcher | 2019-02-27 15:19:58.507853+03 | 9263 | autovacuum launcher | 2019-02-27 15:19:58.508463+03 | 14140 | client backend | 2019-02-27 15:37:58.30704+03 | active 14736 | client backend | 2019-02-27 15:38:10.686775+03 | idle 9261 | background writer | 2019-02-27 15:19:58.509774+03 | 9260 | checkpointer | 2019-02-27 15:19:58.511631+03 | 9262 | walwriter | 2019-02-27 15:19:58.509127+03 | (7 rows)
Let's compare with the information from the operating system:
postgres$ ps -o pid,command --ppid `head -n 1 /var/lib/postgresql/11/alpha/postmaster.pid`
PID COMMAND 9260 postgres: 11/alpha: checkpointer 9261 postgres: 11/alpha: background writer 9262 postgres: 11/alpha: walwriter 9263 postgres: 11/alpha: autovacuum launcher 9264 postgres: 11/alpha: stats collector 9265 postgres: 11/alpha: logical replication launcher 14140 postgres: 11/alpha: student admin_monitoring [local] idle 14736 postgres: 11/alpha: student admin_monitoring [local] idle
Note that pg_stat_activity doesn't show information on stats collector process.
We'll demonstrate just the simplest case. For example we can be interested in FATAL messages:
student$ grep FATAL /var/log/postgresql/postgresql-11-alpha.log | tail -n 10
2019-02-27 15:19:49.979 MSK [8365] student@replica_overview FATAL: terminating connection due to administrator command 2019-02-27 15:19:57.672 MSK [9020] FATAL: terminating logical replication worker due to administrator command 2019-02-27 15:38:11.953 MSK [14679] student@admin_monitoring FATAL: terminating connection due to administrator command
"Terminating connection" message is caused by out interruption of the blocking session.
Message log is commonly used for analysis of long lasting queries. To simplify analysis we can add process id to the messages and turn on logging of statements duration:
α=> 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)
Now let's perform a statement:
α=> SELECT sum(random()) FROM generate_series(1,1000000);
sum
------------------
500089.547127814
(1 row)
Here is what we've got in the log:
student$ tail -n 1 /var/log/postgresql/postgresql-11-alpha.log
(pid=14140) LOG: duration: 409.413 ms statement: SELECT sum(random()) FROM generate_series(1,1000000);
The end of demonstration.