Continuation of the article "«.
The article will discuss and demonstrate through specific queries and examples — what useful information can be obtained using the pg_stat_activity view history.
Warning.
Given the novelty of the topic and the ongoing testing period, the article may contain errors. Critique and feedback are always welcomed and expected.
Input data
pg_stat_statements view history
pg_stat_history
CREATE TABLE pg_stat_history (
id SERIAL,
snapshot_timestamp timestamp without time zone,
database_id integer,
dbid oid,
userid oid,
queryid bigint,
query text,
calls bigint,
total_time double precision,
min_time double precision,
max_time double precision,
mean_time double precision,
stddev_time double precision,
rows bigint,
shared_blks_hit bigint,
shared_blks_read bigint,
shared_blks_dirtied bigint,
shared_blks_written bigint,
local_blks_hit bigint,
local_blks_read bigint,
local_blks_dirtied bigint,
local_blks_written bigint,
temp_blks_read bigint,
temp_blks_written bigint,
blk_read_time double precision,
blk_write_time double precision,
baseline_id integer );The table is filled every hour using dblink to the target database. The most interesting and useful column in the table, of course, queryid.
pg_stat_activity view history
archive_pg_stat_activity
CREATE TABLE archive_pg_stat_activity
(
timepoint timestamp without time zone,
datid oid,
datname name,
pid integer,
usesysid oid,
usename name,
application_name text,
client_addr inet,
client_hostname text,
client_port integer,
backend_start timestamp without time zone,
xact_start timestamp without time zone,
query_start timestamp without time zone,
state_change timestamp without time zone,
wait_event_type text,
wait_event text,
state text,
backend_xid xid,
backend_xmin xid,
query text,
backend_type text,
queryid bigint
);The table represents a partitioned hourly table history_pg_stat_activity (More details here — and here —
Output data
CLUSTER CPU TIME (SYSTEM + CLIENTS )
Query
WITH
t AS
(
SELECT
date_trunc('second', timepoint)
FROM activity_hist.archive_pg_stat_activity aa
WHERE timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND
( aa.wait_event_type IS NULL ) AND
aa.state = 'active'
)
SELECT count(*)
INTO cpu_total
FROM t ;Example
CLUSTER CPU TIME (SYSTEM + CLIENTS ) : 28:37:46CLUSTER WAITINGS TIME
Query
WITH
t AS
(
SELECT
date_trunc('second', timepoint)
FROM activity_hist.archive_pg_stat_activity aa
WHERE timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND
( aa.wait_event_type IS NOT NULL ) AND
aa.state = 'active'
)
SELECT count(*)
INTO cpu_total
FROM t ;Example
CLUSTER WAITINGS TIME : 30:12:49Total pg_stat_statements values
Query
--TOTAL pg_stat
SELECT
SUM(calls) AS calls, SUM(total_time) AS total_time, SUM(rows) AS rows ,
SUM(shared_blks_hit) AS shared_blks_hit, SUM(shared_blks_read) AS shared_blks_read ,
SUM(shared_blks_dirtied) AS shared_blks_dirtied, SUM(shared_blks_written) AS shared_blks_written ,
SUM(local_blks_hit) AS local_blks_hit , SUM(local_blks_read) AS local_blks_read ,
SUM(local_blks_dirtied) AS local_blks_dirtied , SUM(local_blks_written) AS local_blks_written,
SUM(temp_blks_read) AS temp_blks_read, SUM(temp_blks_written) AS temp_blks_written ,
SUM(blk_read_time) AS blk_read_time , SUM(blk_write_time) AS blk_write_time
INTO
pg_total_stat_history_rec
FROM
pg_stat_history
WHERE
snapshot_timestamp BETWEEN pg_stat_history_begin AND pg_stat_history_end AND
queryid IS NULL;SQL DBTIME — total query execution time
Query
dbtime_total = interval '1 millisecond' * pg_total_stat_history_rec.total_time ;Example
SQL DBTIME : 136:49:36SQL CPU TIME — CPU time spent executing queries
Query
WITH
t AS
(
SELECT
date_trunc('second', timepoint)
FROM activity_hist.archive_pg_stat_activity aa
WHERE timepoint BETWEEN pg_stat_history_begin + (current_hour_diff * interval '1 hour') AND pg_stat_history_end + (current_hour_diff * interval '1 hour') AND
( aa.wait_event_type IS NULL ) AND
backend_type = 'client backend' AND
aa.state = 'active'
)
SELECT count(*)
INTO cpu_total
FROM t ;Example
SQL CPU TIME : 27:40:15SQL WAITINGS TIME — total waiting time for queries
Query
WITH
t AS
(
SELECT
date_trunc('second', timepoint)
FROM activity_hist.archive_pg_stat_activity aa
WHERE timepoint BETWEEN pg_stat_history_begin + (current_hour_diff * interval '1 hour') AND pg_stat_history_end + (current_hour_diff * interval '1 hour') AND
( aa.wait_event_type IS NOT NULL ) AND
aa.state = 'active' AND
backend_type = 'client backend'
)
SELECT count(*)
INTO waiting_total
FROM t ;Example
SQL WAITINGS TIME : 30:04:09The following queries are trivial, and implementation details are omitted for brevity:
Example
| SQL IOTIME : 19:44:50
| SQL READ TIME : 19:44:32
| SQL WRITE TIME : 00:00:17
|
| SQL CALLS : 12188248
-------------------------------------------------------------
| SQL SHARED BLOCKS READS : 7997039120
| SQL SHARED BLOCKS HITS : 8868286092
| SQL SHARED BLOCKS HITS/READS % : 110.89
| SQL SHARED BLOCKS DIRTIED : 419945
| SQL SHARED BLOCKS WRITTEN : 19857
|
| SQL TEMPORARY BLOCKS READS : 7836169
| SQL TEMPORARY BLOCKS WRITTEN : 10683938
Now, to the most interesting section
WAITINGS STATISTICS
TOP 10 WAITINGS BY TOTAL WAIT TIME FOR CLIENTS PROCESSES
Query
SELECT
wait_event_type, wait_event ,
get_system_waiting_duration( wait_event_type , wait_event , pg_stat_history_begin + (current_hour_diff * interval '1 hour') , pg_stat_history_end + (current_hour_diff * interval '1 hour') ) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin + (current_hour_diff * interval '1 hour') AND pg_stat_history_end + (current_hour_diff * interval '1 hour') AND backend_type != 'client backend' AND wait_event_type IS NOT NULL
GROUP BY
wait_event_type, wait_event
ORDER BY 3 DESC
LIMIT 10Example
+------------------------------------------------------------------------------------ | TOP 10 WAIT TIMES BY TOTAL WAIT TIME FOR SYSTEM PROCESSES +-----+------------------------------+--------------------+-------------------- | #| wait_event_type| wait_event| duration +-----+------------------------------+--------------------+-------------------- | 1| Activity| LogicalLauncherMain| 10:43:28 | 2| Activity| AutoVacuumMain| 10:42:49 | 3| Activity| WalWriterMain| 10:28:53 | 4| Activity| CheckpointerMain| 10:23:50 | 5| Activity| BgWriterMain| 09:11:59 | 6| Activity| BgWriterHibernate| 01:37:46 | 7| IO| BufFileWrite| 00:02:35 | 8| LWLock| buffer_mapping| 00:01:54 | 9| IO| DataFileRead| 00:01:23 | 10| IO| WALWrite| 00:00:59 +-----+------------------------------+--------------------+--------------------
TOP 10 WAITINGS BY TOTAL WAIT TIME FOR CLIENTS PROCESSES
Query
SELECT
wait_event_type , wait_event ,
get_clients_waiting_duration( wait_event_type , wait_event , pg_stat_history_begin+(current_hour_diff * interval '1 hour') , pg_stat_history_end+(current_hour_diff * interval '1 hour') ) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND backend_type = 'client backend' AND wait_event_type IS NOT NULL
GROUP BY wait_event_type, wait_event
ORDER BY 3 DESC
LIMIT 10Example
+-----+------------------------------+--------------------+--------------------+---------- | #| wait_event_type| wait_event| duration| % dbtime +-----+------------------------------+--------------------+--------------------+---------- | 1| Lock| transactionid| 08:16:47| 6.05 | 2| IO| DataFileRead| 06:13:41| 4.55 | 3| Timeout| PgSleep| 02:53:21| 2.11 | 4| LWLock| buffer_mapping| 00:40:42| 0.5 | 5| LWLock| buffer_io| 00:17:17| 0.21 | 6| IO| BufFileWrite| 00:01:34| 0.02 | 7| Lock| tuple| 00:01:32| 0.02 | 8| Client| ClientRead| 00:01:19| 0.02 | 9| IO| BufFileRead| 00:00:37| 0.01 | 10| LWLock| buffer_content| 00:00:08| 0 +-----+------------------------------+--------------------+--------------------+----------
WAIT TYPES BY TOTAL WAIT TIME FOR SYSTEM PROCESSES
Query
SELECT
wait_event_type ,
get_system_waiting_type_duration( wait_event_type , pg_stat_history_begin+(current_hour_diff * interval '1 hour') , pg_stat_history_end+(current_hour_diff * interval '1 hour') ) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND backend_type != 'client backend' AND wait_event_type IS NOT NULL
GROUP BY wait_event_type
ORDER BY 2 DESCExample
+-----+------------------------------+-------------------- | #| wait_event_type| duration +-----+------------------------------+-------------------- | 1| Activity| 53:08:45 | 2| IO| 00:06:24 | 3| LWLock| 00:03:02 +-----+------------------------------+--------------------
WAITING TYPES BY TOTAL WAIT TIME, FOR CLIENT PROCESSES
Query
SELECT
wait_event_type ,
get_clients_waiting_type_duration( wait_event_type , pg_stat_history_begin+(current_hour_diff * interval '1 hour') , pg_stat_history_end+(current_hour_diff * interval '1 hour') ) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND backend_type = 'client backend' AND wait_event_type IS NOT NULL
GROUP BY wait_event_type
ORDER BY 2 DESCExample
+-----+------------------------------+--------------------+-------------------- | #| wait_event_type| duration| % dbtime +-----+------------------------------+--------------------+-------------------- | 1| Lock| 08:18:19| 6.07 | 2| IO| 06:16:01| 4.58 | 3| Timeout| 02:53:21| 2.11 | 4| LWLock| 00:58:12| 0.71 | 5| Client| 00:01:19| 0.02 | 6| IPC| 00:00:04| 0 +-----+------------------------------+--------------------+--------------------
Waiting durations for system processes and individual queries.
WAITING FOR SYSTEM PROCESSES
Query
SELECT
backend_type , datname , wait_event_type , wait_event , get_backend_type_waiting_duration( backend_type , wait_event_type , wait_event , pg_stat_history_begin+(current_hour_diff * interval '1 hour') , pg_stat_history_end+(current_hour_diff * interval '1 hour') ) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin+(current_hour_diff * interval '1 hour') AND pg_stat_history_end+(current_hour_diff * interval '1 hour') AND backend_type != 'client backend' AND wait_event_type IS NOT NULL
GROUP BY backend_type , datname , wait_event_type , wait_event
ORDER BY 5 DESCExample
+-----+-----------------------------+----------+--------------------+----------------------+-------------------- | #| backend_type| dbname| wait_event_type| wait_event| duration +-----+-----------------------------+----------+--------------------+----------------------+-------------------- | 1| logical replication launcher| | Activity| LogicalLauncherMain| 10:43:28 | 2| autovacuum launcher| | Activity| AutoVacuumMain| 10:42:49 | 3| walwriter| | Activity| WalWriterMain| 10:28:53 | 4| checkpointer| | Activity| CheckpointerMain| 10:23:50 | 5| background writer| | Activity| BgWriterMain| 09:11:59 | 6| background writer| | Activity| BgWriterHibernate| 01:37:46 | 7| parallel worker| tdb1| IO| BufFileWrite| 00:02:35 | 8| parallel worker| tdb1| LWLock| buffer_mapping| 00:01:41 | 9| parallel worker| tdb1| IO| DataFileRead| 00:01:22 | 10| parallel worker| tdb1| IO| BufFileRead| 00:00:59 | 11| walwriter| | IO| WALWrite| 00:00:57 | 12| parallel worker| tdb1| LWLock| buffer_io| 00:00:47 | 13| autovacuum worker| tdb1| LWLock| buffer_mapping| 00:00:13 | 14| background writer| | IO| DataFileWrite| 00:00:12 | 15| checkpointer| | IO| DataFileWrite| 00:00:11 | 16| walwriter| | LWLock| WALWriteLock| 00:00:09 | 17| checkpointer| | LWLock| WALWriteLock| 00:00:06 | 18| background writer| | LWLock| WALWriteLock| 00:00:06 | 19| walwriter| | IO| WALInitWrite| 00:00:02 | 20| autovacuum worker| tdb1| LWLock| WALWriteLock| 00:00:02 | 21| walwriter| | IO| WALInitSync| 00:00:02 | 22| autovacuum worker| tdb1| IO| DataFileRead| 00:00:01 | 23| checkpointer| | IO| ControlFileSyncUpdate| 00:00:01 | 24| background writer| | IO| WALWrite| 00:00:01 | 25| background writer| | IO| DataFileFlush| 00:00:01 | 26| checkpointer| | IO| SLRUFlushSync| 00:00:01 | 27| autovacuum worker| tdb1| IO| WALWrite| 00:00:01 | 28| checkpointer| | IO| DataFileSync| 00:00:01 +-----+-----------------------------+----------+--------------------+----------------------+--------------------
WAITINGS FOR SQL — waits for individual requests by queryid
Query
SELECT
queryid, datname, wait_event_type, wait_event, get_query_waiting_duration(queryid, wait_event_type, wait_event, pg_stat_history_begin + (current_hour_diff * interval '1 hour'), pg_stat_history_end + (current_hour_diff * interval '1 hour')) as duration
FROM
activity_hist.archive_pg_stat_activity aa
WHERE
timepoint BETWEEN pg_stat_history_begin + (current_hour_diff * interval '1 hour') AND pg_stat_history_end + (current_hour_diff * interval '1 hour') AND backend_type = 'client backend' AND wait_event_type IS NOT NULL AND queryid IS NOT NULL
GROUP BY queryid, datname, wait_event_type, wait_event
ORDER BY 1, 5 DESC Example
+-----+-------------------------+----------+--------------------+--------------------+--------------------+-------------------- | #| queryid| dbname| wait_event_type| wait_event| waitings| total | | | | | | duration| duration +-----+-------------------------+----------+--------------------+--------------------+--------------------+-------------------- | 1| -8247416849404883188| tdb1| Client| ClientRead| 00:00:02| | 2| -6572922443698419129| tdb1| Client| ClientRead| 00:00:05| | 3| -6572922443698419129| tdb1| IO| DataFileRead| 00:00:01| | 4| -5917408132400665328| tdb1| Client| ClientRead| 00:00:04| | 5| -4091009262735781873| tdb1| Client| ClientRead| 00:00:03| | 6| -1473395109729441239| tdb1| Client| ClientRead| 00:00:01| | 7| 28942442626229688| tdb1| IO| BufFileWrite| 00:01:34| 00:46:06 | 8| 28942442626229688| tdb1| LWLock| buffer_mapping| 00:01:05| 00:46:06 | 9| 28942442626229688| tdb1| IO| DataFileRead| 00:00:44| 00:46:06 | 10| 28942442626229688| tdb1| IO| BufFileRead| 00:00:37| 00:46:06 | 11| 28942442626229688| tdb1| LWLock| buffer_io| 00:00:35| 00:46:06 | 12| 28942442626229688| tdb1| Client| ClientRead| 00:00:05| 00:46:06 | 13| 28942442626229688| tdb1| IPC| MessageQueueReceive| 00:00:03| 00:46:06 | 14| 28942442626229688| tdb1| IPC| BgWorkerShutdown| 00:00:01| 00:46:06 | 15| 389015618226997618| tdb1| Lock| transactionid| 03:55:09| 04:14:15 | 16| 389015618226997618| tdb1| IO| DataFileRead| 03:23:09| 04:14:15 | 17| 389015618226997618| tdb1| LWLock| buffer_mapping| 00:12:09| 04:14:15 | 18| 389015618226997618| tdb1| LWLock| buffer_io| 00:10:18| 04:14:15 | 19| 389015618226997618| tdb1| Lock| tuple| 00:00:35| 04:14:15 | 20| 389015618226997618| tdb1| LWLock| WALWriteLock| 00:00:02| 04:14:15 | 21| 389015618226997618| tdb1| IO| DataFileWrite| 00:00:01| 04:14:15 | 22| 389015618226997618| tdb1| LWLock| SyncScanLock| 00:00:01| 04:14:15 | 23| 389015618226997618| tdb1| Client| ClientRead| 00:00:01| 04:14:15 | 24| 734234407411547467| tdb1| Client| ClientRead| 00:00:11| | 25| 734234407411547467| tdb1| LWLock| buffer_mapping| 00:00:05| | 26| 734234407411547467| tdb1| IO| DataFileRead| 00:00:02| | 27| 1237430309438971376| tdb1| LWLock| buffer_mapping| 00:02:18| 02:45:40 | 28| 1237430309438971376| tdb1| IO| DataFileRead| 00:00:27| 02:45:40 | 29| 1237430309438971376| tdb1| Client| ClientRead| 00:00:02| 02:45:40 | 30| 2404820632950544954| tdb1| Client| ClientRead| 00:00:01| | 31| 2515308626622579467| tdb1| Client| ClientRead| 00:00:02| | 32| 4710212362688288619| tdb1| LWLock| buffer_mapping| 00:03:08| 02:18:21 | 33| 4710212362688288619| tdb1| IO| DataFileRead| 00:00:22| 02:18:21 | 34| 4710212362688288619| tdb1| Client| ClientRead| 00:00:06| 02:18:21 | 35| 4710212362688288619| tdb1| LWLock| buffer_io| 00:00:02| 02:18:21 | 36| 9150846928388977274| tdb1| IO| DataFileRead| 00:01:19| | 37| 9150846928388977274| tdb1| LWLock| buffer_mapping| 00:00:34| | 38| 9150846928388977274| tdb1| Client| ClientRead| 00:00:10| | 39| 9150846928388977274| tdb1| LWLock| buffer_io| 00:00:01| +-----+-------------------------+----------+--------------------+--------------------+--------------------+--------------------
CLIENT SQL STATISTICS — TOP Queries
The queries for retrieval are again trivial and are not provided to save space.
Examples
+------------------------------------------------------------------------------------ | CLIENT SQL ordered by Elapsed Time +--------------------+----------+----------+----------+----------+----------+-------------------- | elapsed time| calls| % dbtime| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+-------------------- | 04:14:15| 19| 3.1| 10.83| 11.52| tdb1| 389015618226997618 | 02:45:40| 746| 2.02| 4.23| 0.08| tdb1| 1237430309438971376 | 02:18:21| 749| 1.69| 3.39| 0.1| tdb1| 4710212362688288619 | 00:46:06| 375| 0.56| 0.94| 0.41| tdb1| 28942442626229688 +--------------------+----------+----------+----------+----------+----------+-------------------- | CLIENT SQL ordered by CPU Time +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | cpu time| calls| % dbtime|total_time| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | 02:59:49| 19| 3.1| 04:14:15| 10.83| 11.52| tdb1| 389015618226997618 | 01:10:12| 746| 2.02| 02:45:40| 4.23| 0.08| tdb1| 1237430309438971376 | 00:56:15| 749| 1.69| 02:18:21| 3.39| 0.1| tdb1| 4710212362688288619 | 00:15:35| 375| 0.56| 00:46:06| 0.94| 0.41| tdb1| 28942442626229688 +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | CLIENT SQL ordered by User I/O Wait Time +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | io_wait time| calls| % dbtime|total_time| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | 03:23:10| 19| 3.1| 04:14:15| 10.83| 11.52| tdb1| 389015618226997618 | 00:02:54| 375| 0.56| 00:46:06| 0.94| 0.41| tdb1| 28942442626229688 | 00:00:27| 746| 2.02| 02:45:40| 4.23| 0.08| tdb1| 1237430309438971376 | 00:00:22| 749| 1.69| 02:18:21| 3.39| 0.1| tdb1| 4710212362688288619 +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | CLIENT SQL ordered by Shared Buffers Reads +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | buffers reads| calls| % dbtime|total_time| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | 1056388566| 19| 3.1| 04:14:15| 10.83| 11.52| tdb1| 389015618226997618 | 11709251| 375| 0.56| 00:46:06| 0.94| 0.41| tdb1| 28942442626229688 | 3439004| 746| 2.02| 02:45:40| 4.23| 0.08| tdb1| 1237430309438971376 | 3373330| 749| 1.69| 02:18:21| 3.39| 0.1| tdb1| 4710212362688288619 +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | CLIENT SQL ordered by Disk Reads Time +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | read time| calls| % dbtime|total_time| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | 02:16:30| 19| 3.1| 04:14:15| 10.83| 11.52| tdb1| 389015618226997618 | 00:04:50| 375| 0.56| 00:46:06| 0.94| 0.41| tdb1| 28942442626229688 | 00:01:10| 749| 1.69| 02:18:21| 3.39| 0.1| tdb1| 4710212362688288619 | 00:00:57| 746| 2.02| 02:45:40| 4.23| 0.08| tdb1| 1237430309438971376 +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | CLIENT SQL ordered by Executions +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | calls| rows| % dbtime|total_time| % CPU| % IO| dbname| queryid +--------------------+----------+----------+----------+----------+----------+----------+-------------------- | 749| 749| 1.69| 02:18:21| 3.39| 0.1| tdb1| 4710212362688288619 | 746| 746| 2.02| 02:45:40| 4.23| 0.08| tdb1| 1237430309438971376 | 375| 0| 0.56| 00:46:06| 0.94| 0.41| tdb1| 28942442626229688 | 19| 19| 3.1| 04:14:15| 10.83| 11.52| tdb1| 389015618226997618 +--------------------+----------+----------+----------+----------+----------+----------+--------------------
Summary
By using the provided queries and resulting reports, one can gain a more comprehensive view for analyzing and addressing performance degradation issues for individual queries and the entire cluster.
Development
The development plans are as follows:
- Supplement the reporting with a history of locks. Queries are being tested and will be provided shortly.
- Utilize the TimescaleDB extension for storing the history of pg_stat_activity and pg_locks.
- Prepare a batch solution on GitHub for mass deployment on production databases.
To be continued…
Source: habr.com
