Backend / Databases / SQL / 31_pg_stat_statements.md

pg_stat_statements

Updated 4 interview angles 7 min read source
On this page9
  1. Setup
  2. How it identifies a query
  3. The counters, and what each ranking finds
  4. What it cannot see
  5. Counters are cumulative
  6. Where it breaks in production
  7. The trade not taken
  8. Related
  9. Interview angle

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

sql
-- 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:

text
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 = 3

Entries 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) and IN (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 = $1 appeared twice: 4,648 calls from pgbench and 2,000 from psycopg. The parameter types differed, so the query trees, and the queryids, differed. Group by query text when adding up a statement’s total cost across clients.

The counters, and what each ranking finds

sql
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;
text
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      0

The 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

python
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

text
5 x SELECT pg_sleep(1), 'killed_marker'   with statement_timeout = 200ms
entries in pg_stat_statements: 0

Counters 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.

sql
CREATE TABLE pgss_snap AS
SELECT now() AS at, queryid, calls, total_exec_time FROM pg_stat_statements;
-- ... later: delta per queryid between two snapshots

Monitoring 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.

Interview angle 4

  • “Database CPU is pinned. Which query do you fix first?” - the top of pg_stat_statements by total_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 calls count, rows / calls of 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_timeout every few minutes. Will pg_stat_statements show it?” - no: counters are added when a statement finishes, and five cancelled statements left no entry. Look in the error log or pg_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).