pg_stat_statements
Article.
EXPLAIN answers “why is this query slow?”. It cannot answer the question
that comes first: which queries cost the database the most? That is
pg_stat_statements, an extension that keeps running totals for every
distinct statement the server executes. It is the first thing to look at when
the database CPU is pinned, and the first thing to install on any server.
Database CPU is at 100%. Which query do you fix first? The answer is rarely the slowest one. Outputs below are from PostgreSQL 18.4 in Docker, under a pgbench load plus a Python client (psycopg 3).
Setup
-- postgresql.conf, then restart
shared_preload_libraries = 'pg_stat_statements'
track_io_timing = on -- read and write times, not only counts
-- once per database
CREATE EXTENSION pg_stat_statements;It must be loaded at server start because it hooks into the executor of
every backend. Managed services (RDS, Cloud SQL, Azure) preload it already;
only CREATE EXTENSION is needed. Defaults worth knowing: 5,000 entries
(pg_stat_statements.max), top-level statements only (track = top), and
planning time not tracked (track_planning = off, because it adds
contention on busy servers).
How it identifies a query
After parsing, PostgreSQL computes a 64-bit queryid from the query’s
structure (compute_query_id = auto turns this on when the extension is
loaded). Constants are replaced by $1, $2, ... in the stored text, so
queries that differ only in literals share one entry:
SELECT * FROM pgbench_branches WHERE bid = 1 -- three statements,
SELECT * FROM pgbench_branches WHERE bid = 2 -- one entry:
SELECT * FROM pgbench_branches WHERE bid = 3
-> SELECT * FROM pgbench_branches WHERE bid = $1 calls = 3Entries are keyed by user, database, queryid and whether the statement was
top-level. When 5,000 are in use, the least-used are evicted, and
pg_stat_statements_info.dealloc counts the evictions; a growing number
means the table is too small or something generates endless distinct
queries.
Two surprises in the grouping
- IN lists. PostgreSQL 18 squashes lists of constants:
aid IN (1,2),IN (1..5)andIN (1..20)became one entry,aid IN ($1 /*, ... */), with 3 calls. A one-element list stayed separate. Before 18, every list length was its own entry, a common cause of churn. - The same text, two entries.
SELECT abalance FROM pgbench_accounts WHERE aid = $1appeared twice: 4,648 calls from pgbench and 2,000 from psycopg. The parameter types differed, so the query trees, and the queryids, differed. Group byquerytext when adding up a statement’s total cost across clients.
The counters, and what each ranking finds
SELECT left(query, 60) AS query, calls,
round(total_exec_time::numeric, 1) AS total_ms,
round(mean_exec_time::numeric, 3) AS mean_ms,
rows,
shared_blks_hit + shared_blks_read AS blks,
temp_blks_written AS temp
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 8;query calls total_ms mean_ms temp
UPDATE pgbench_branches SET bbalance = ... 4648 4631.1 0.996 0
UPDATE pgbench_tellers SET tbalance = ... 4648 761.0 0.164 0
SELECT aid FROM pgbench_accounts ORDER BY ... 1 516.5 516.530 53737
UPDATE pgbench_accounts SET abalance = ... 4648 311.2 0.067 0
SELECT abalance FROM pgbench_accounts ... 4648 45.2 0.010 0The top line is the answer to the opening question. One millisecond per call looks harmless, but 4,648 calls made it six times the next statement: in pgbench, every transaction updates one of only ten branch rows, so they wait on each other’s row locks. The 516 ms sort, the obvious “slow query”, ran once.
Six rankings
| Order by | Finds |
|---|---|
total_exec_time |
where the server’s time goes: fix these first |
mean_exec_time |
slow individual calls: user-facing latency |
stddev_exec_time |
unstable plans or lock waits |
calls, with rows / calls |
chatty access, the N+1 |
shared_blks_read |
I/O: working set larger than cache |
temp_blks_written |
sorts and hashes spilling past work_mem |
The 516 ms sort wrote 53,737 temp blocks (about 420 MB) with
work_mem = 64kB: that row finds the spill without reading a single plan.
Since 13 there are WAL columns (wal_bytes), since 15 JIT timings, and in 18
parallel_workers_to_launch and parallel_workers_launched, which expose
queries that planned parallel workers and did not get them.
What it cannot see
The N+1 is cheap here and expensive in the app
for aid in aids: # 2,000 queries
cur.execute("SELECT abalance FROM pgbench_accounts WHERE aid = %s", (aid,))
# vs one query
cur.execute("SELECT aid, abalance FROM pgbench_accounts WHERE aid = ANY(%s)", (aids,))| Measured | N+1 loop | One query |
|---|---|---|
database time (total_exec_time) |
21 ms | 0.8 ms |
| time seen by the client | 1,116 ms | 6.4 ms |
The database spent 21 ms; the request spent a second, in 2,000 network round
trips. In pg_stat_statements the N+1 does not rank by time at all. Its
fingerprint is a huge calls count, rows / calls of 1, and a tiny mean
on a lookup by key. Find those, then find the loop in the ORM
(N+1 query problem).
Statements that never finish
5 x SELECT pg_sleep(1), 'killed_marker' with statement_timeout = 200ms
entries in pg_stat_statements: 0Counters are added when the executor finishes. A statement cancelled by
statement_timeout, killed, or failing with an error is never recorded, so
the worst query in the system, the one that always times out, can be
invisible here. Find it in the server log (log_min_error_statement,
log_min_duration_statement) or in pg_stat_activity while it runs.
Parameters and single executions
Constants are gone, so it cannot tell you which customer id was slow, and a
statement that is slow only for one skewed value is averaged away. Use
auto_explain and the slow-query log for that
(Reading a query plan).
Counters are cumulative
Every number is a total since the last pg_stat_statements_reset()
(pg_stat_statements_info.stats_reset says when). “Which query got slower
after the deploy?” cannot be read from one snapshot: take two and subtract.
CREATE TABLE pgss_snap AS
SELECT now() AS at, queryid, calls, total_exec_time FROM pg_stat_statements;
-- ... later: delta per queryid between two snapshotsMonitoring tools do this continuously: pganalyze, PoWA, the postgres
exporter for Prometheus, and the managed equivalents (RDS Performance
Insights, Cloud SQL Query Insights). Since 14, pg_stat_activity.query_id
and %Q in log_line_prefix carry the same queryid, which ties a log line
or an auto_explain plan back to its row here.
Where it breaks in production
Reading the top of the list wrongly
Ranking by mean_exec_time shows the nightly report first and sends the team
to optimise a query that runs once a day. CPU is consumed by
total_exec_time; a 1 ms query called millions of times usually matters
more.
Entries churning
dealloc climbs by thousands an hour, and the statements of interest keep
disappearing before anyone looks. Causes: queries built with varying
structure (dynamic column lists, before 18 every IN-list length), temporary
tables (each has a new OID, so a new queryid), or a search_path per
tenant. Raise pg_stat_statements.max, and fix the query generation.
A database that “looks fine”
Every entry is cheap, the total is low, and users still see timeouts. The
statements that time out are not in the view at all. Check the error log for
canceling statement due to statement timeout before concluding the database
is healthy.
Statements inside functions
With the default track = top, a PL/pgSQL function shows up as one
SELECT my_function($1) entry, and the queries inside it are invisible. Set
pg_stat_statements.track = all to see them as separate rows.
The trade not taken
The alternative is logging: log_min_duration_statement = 200ms plus
pgBadger to aggregate the log. It sees what pg_stat_statements cannot,
real parameters, individual slow executions and failed statements, but it
misses the 1 ms query called a million times, and logging everything costs
I/O. log_min_duration_sample (13) samples instead.
Client-side OpenTelemetry database spans see a third thing, the time in the pool and on the network that the N+1 loop above lost. In practice all three: the extension for where the server’s time goes, the log for the outliers, and traces for what the user felt.
Related
Interview angle 4
- “Database CPU is pinned. Which query do you fix first?” - the top of
pg_stat_statementsbytotal_exec_time. Here a 1 ms update called 4,648 times cost 4.6 s, six times the next one, while the 516 ms query ran once.- Follow-up: “Why total and not mean?” - total is what the server actually spent; mean finds slow calls, which matter for latency, not load.
- Follow-up: “What does an ORM N+1 look like here?” - a key lookup with a
huge
callscount,rows / callsof 1, and a tiny mean. Its database time was 21 ms; the client spent 1.1 s on round trips.
- “A query is killed by
statement_timeoutevery few minutes. Willpg_stat_statementsshow it?” - no: counters are added when a statement finishes, and five cancelled statements left no entry. Look in the error log orpg_stat_activity. - “How does it group queries?” - by a hash of the parsed query tree with
constants removed, so literals collapse into
$1. Since 18 IN lists of any length collapse too; different parameter types still split one text into several entries. - “What changed after the deploy?” - the counters are cumulative since the last reset; compare two snapshots, or use a tool that does (pganalyze, PoWA, Performance Insights).