Triage pg_stat_statements Slow Queries with auto_explain Plans

What the two-stage triage loop is and who should use it

pg_stat_statements is an extension that aggregates execution statistics per normalized statement. It replaces literal constants with placeholders, so thousands of calls that differ only by parameter values collapse into one entry with cumulative call counts, total and mean execution time, rows returned, and buffer activity. It tells you which query shapes cost the system the most in aggregate, but it stores no plans.

auto_explain is a module that writes a statement's execution plan to the server log when the statement runs longer than a configured threshold. The plan is the one the executor actually used, with the real parameter values, table statistics, cache state, and concurrent load at that moment. Optionally, it can include actual row counts and timings.

You need both because each covers the other's blind spot. Ranking alone tells you what is expensive but not why. A plan you reproduce later by running EXPLAIN ANALYZE by hand can differ from the plan production used. Your chosen parameter values may favor a different index, a generic plan may have been in play, or the data and statistics may have changed since. auto_explain gives you the plan from the slow execution itself.

The loop:

rank -> capture -> diagnose -> fix -> re-measure -> (back to rank)

This approach is for backend and platform engineers who own database performance and can read server logs and change server configuration. Run it when:

• Latency or CPU climbs without an obvious cause.
• You are doing a capacity review.
• A release has gone out, so you can catch regressions introduced by new query shapes.

Copy +----------------------+          +---------------------------+
 | pg_stat_statements   |          | auto_explain              |
 | normalized stats:    |          | plans over threshold,     |
 | calls, total/mean    |          | as executed, written to   |
 | time, rows, buffers  |          | the server log            |
 +----------+-----------+          +-------------+-------------+
            |                                    |
            v                                    v
 +----------------------+          +---------------------------+
 | 1. RANK              |          | 2. CAPTURE                |
 | top query shapes by  |--------->| real plan for those       |
 | cumulative cost      |          | shapes from slow runs     |
 +----------------------+          +-------------+-------------+
            ^                                    |
            |                                    v
 +----------+-----------+          +---------------------------+
 | 5. RE-MEASURE        |          | 3. DIAGNOSE               |
 | compare stats after  |          | why slow: scan type,      |
 | the change; repeat   |          | row estimates, buffers    |
 +----------------------+          +-------------+-------------+
            ^                                    |
            |          +--------------------+    |
            +----------| 4. FIX             |<---+
                       | index, query,      |
                       | stats, config      |
                       +--------------------+

The two-stage triage loop: pg_stat_statements ranks query shapes by cumulative cost, auto_explain captures the plans those queries actually used, and each fix is re-measured before the next pass.

How to enable pg_stat_statements and auto_explain

Load both libraries at startup

Add both modules to shared_preload_libraries in postgresql.conf, for example 'pg_stat_statements,auto_explain'. Keep any entries already in the list. pg_stat_statements allocates shared memory for its statistics table when the server starts, so this setting only takes effect after a full restart. A reload is not enough. On a busy primary, schedule the restart in a maintenance window, or roll it through replicas first and fail over.

After the restart, run CREATE EXTENSION pg_stat_statements; in the database you will query from. Statistics are collected cluster-wide. The extension creates the pg_stat_statements view and its helper functions in that one database, which is why you need to run it there. auto_explain has no extension object. It runs as a hook and writes plans to the server log.

Start auto_explain conservatively

• auto_explain.log_min_duration = '1s': logs only the statements worth reading. 0 logs everything and floods the log.
• auto_explain.log_analyze = on: records actual row counts, so you can compare them with the planner's estimates. Instrumentation applies to every sampled statement, not only the slow ones, because auto_explain cannot know in advance which statements will cross the threshold.
• auto_explain.log_timing = off: per-node timing is the most expensive part of that instrumentation. Row counts still appear without it.
• auto_explain.log_buffers = on: shows shared-buffer hits and reads, which separates I/O-bound plans from CPU-bound ones.
• auto_explain.sample_rate = 0.1: explains roughly one in ten statements per session. This limits overhead while still catching recurring slow queries.

For targeted testing, run LOAD 'auto_explain'; in a single session and set the parameters there. This normally requires superuser privileges.

Managed PostgreSQL services may block some of these settings or expose them only through their own parameter configuration. Check which ones you can change before you plan the rollout.

Copy# postgresql.conf: changes to shared_preload_libraries need a full restart, not a reload.
# Append to any libraries already listed instead of replacing them.
shared_preload_libraries = 'pg_stat_statements,auto_explain'

# auto_explain: conservative starting values
auto_explain.log_min_duration = '1s'   # log only plans for statements slower than 1s
auto_explain.log_analyze = on          # actual row counts; instruments every sampled statement
auto_explain.log_timing = off          # skip per-node timing, the costliest part of ANALYZE
auto_explain.log_buffers = on          # shared-buffer hits/reads per node (needs log_analyze)
auto_explain.sample_rate = 0.1         # explain about 1 in 10 statements per session

# After restarting, in the database you will query from (psql):
#   CREATE EXTENSION pg_stat_statements;
#   SHOW shared_preload_libraries;      -- confirm both modules loaded
#
# Targeted test in a single session, with no restart (LOAD normally needs superuser):
#   LOAD 'auto_explain';
#   SET auto_explain.log_min_duration = 0;   -- explain every statement in this session
#   SET auto_explain.log_analyze = on;
#   SET auto_explain.log_buffers = on;
#   SELECT count(*) FROM orders WHERE customer_id = 42;  -- plan goes to the server log

A postgresql.conf fragment that preloads pg_stat_statements and auto_explain with conservative auto_explain settings, followed by the post-restart CREATE EXTENSION step and a per-session LOAD for targeted testing.

How pg_stat_statements normalizes and ranks queries

When a statement runs, pg_stat_statements replaces literal constants with placeholders such as $1 and groups the result by queryid (together with user and database). WHERE id = 42 and WHERE id = 97 collapse into one row, so ten thousand cheap lookups show up as a single entry with a large calls count instead of being scattered across the output.

Rank by total_exec_time first: SELECT queryid, calls, total_exec_time, mean_exec_time, rows, shared_blks_hit, shared_blks_read, temp_blks_written, query FROM pg_stat_statements ORDER BY total_exec_time DESC LIMIT 20. This finds where the server spends most of its time, and that is often a fast query called constantly. Then sort the same query by mean_exec_time to find individually slow statements, which are the ones users notice. Divide rows by calls to spot queries that return far more data than the caller needs.

A block counted as read missed shared buffers but may still have come from the OS page cache. Treat high read counts as a signal to check, not proof of disk I/O.

The counters accumulate from the last reset, so lifetime totals mix old workloads with current ones. You have two ways to measure a defined window. You can call pg_stat_statements_reset() and measure from that point, but the reset clears the statistics for everyone using the view. The alternative is to copy the view into a table with a timestamp before and after the window and compare the two snapshots by queryid.

Copy-- Baseline snapshot: no reset, so other users of the view keep their stats.
-- Grouping by (userid, dbid, queryid) merges top-level and nested rows.
CREATE TABLE pgss_before AS
SELECT userid, dbid, queryid,
       sum(calls) AS calls, sum(total_exec_time) AS total_ms, sum(rows) AS rows,
       sum(shared_blks_hit) AS hit, sum(shared_blks_read) AS read,
       sum(temp_blks_written) AS temp_written
FROM pg_stat_statements
GROUP BY userid, dbid, queryid;

-- ...let the workload run for the window you want to measure, then diff.
-- If an entry was evicted and re-created in between, its delta is negative; skip it.
WITH after AS (
  SELECT userid, dbid, queryid, max(query) AS query,
         sum(calls) AS calls, sum(total_exec_time) AS total_ms, sum(rows) AS rows,
         sum(shared_blks_hit) AS hit, sum(shared_blks_read) AS read,
         sum(temp_blks_written) AS temp_written
  FROM pg_stat_statements
  GROUP BY userid, dbid, queryid
), d AS (
  SELECT a.queryid, a.query,
         a.calls - coalesce(b.calls, 0)               AS calls,
         a.total_ms - coalesce(b.total_ms, 0)         AS total_ms,
         a.rows - coalesce(b.rows, 0)                 AS rows,
         a.hit - coalesce(b.hit, 0)                   AS hit,
         a.read - coalesce(b.read, 0)                 AS read,
         a.temp_written - coalesce(b.temp_written, 0) AS temp_written
  FROM after a LEFT JOIN pgss_before b USING (userid, dbid, queryid)
)
SELECT queryid, calls, round(total_ms::numeric, 1) AS total_ms,
       round((total_ms / calls)::numeric, 2)        AS mean_ms,      -- swap ORDER BY to this for slow-per-call
       round(rows::numeric / calls, 1)              AS rows_per_call, -- large values: over-fetching
       round(100.0 * hit / nullif(hit + read, 0), 1) AS hit_pct,      -- low: working set not in shared buffers
       temp_written,                                                  -- > 0: sorts/hashes spilling past work_mem
       left(query, 80) AS query
FROM d
WHERE calls > 0 AND total_ms >= 0
ORDER BY total_ms DESC
LIMIT 20;

Measures a defined window without calling pg_stat_statements_reset() by snapshotting the counters into a table, then diffing a second read against it and deriving mean time, rows per call, buffer hit percentage and temp blocks written for each queryid.

Reading captured plans and verifying fixes with EXPLAIN ANALYZE

Once a query fingerprint stands out, find its auto_explain entry in the server log. Each entry records the statement's duration followed by the plan. If auto_explain.log_analyze is on, every node shows estimated and actual row counts side by side. Read the plan from the innermost nodes outward, because that is where rows originate. Look for four patterns:

• Estimate gaps. Expecting 50 rows and getting 500,000 usually points to stale or insufficient statistics. The planner picks join methods and scan types from those estimates, so one bad estimate low in the tree can produce a poor plan above it.
• Sequential scans on large tables with a high "Rows Removed by Filter" count. These suggest a missing or unusable index.
• Nested loops with a high loops= value. Actual rows and time are reported per loop, so multiply by the loop count to get the real cost.
• Sorts that report an external merge to disk. The sort exceeded work_mem and spilled to temporary files.

To test a fix, reproduce the plan with EXPLAIN (ANALYZE, BUFFERS) on a non-production copy. The buffer counts show whether time went to cache hits or disk reads. For UPDATE or DELETE, wrap the statement in BEGIN ... ROLLBACK.

Keep in mind that EXPLAIN ANALYZE actually executes the statement. Rolling back still means it took row locks, fired triggers, and wrote WAL and dead tuples.

A staging plan can also differ from production. Data volume, statistics, configuration such as work_mem, and cache state all change the planner's choices and the timings. Before you trust the result, check that the staging plan has the same shape as the logged one.

Copy-- Run on a non-production copy. EXPLAIN ANALYZE executes the statement for real.

-- 1. Read-only query: reproduce the logged plan with buffer counts.
EXPLAIN (ANALYZE, BUFFERS)
SELECT o.id, o.total, c.email
FROM orders o
JOIN customers c ON c.id = o.customer_id
WHERE o.status = 'pending'
ORDER BY o.created_at DESC;
-- Compare against the auto_explain entry:
--   rows=50 (estimate) vs actual rows=500000  -> stale statistics
--   Seq Scan ... Rows Removed by Filter: high -> missing/unusable index
--   Nested Loop child with loops=N            -> multiply time and rows by N
--   Sort Method: external merge  Disk: ...    -> sort exceeded work_mem

-- 2. Refresh statistics if estimates were far off, then re-check the plan.
ANALYZE orders;

-- 3. Write statement: wrap in a transaction and roll back.
-- The UPDATE still takes row locks, fires triggers, and writes WAL
-- and dead tuples, even though the changes are discarded.
BEGIN;
EXPLAIN (ANALYZE, BUFFERS)
UPDATE orders
SET status = 'expired'
WHERE status = 'pending'
  AND created_at < now() - interval '30 days';
ROLLBACK;

-- 4. Match production settings that affect plan shape before trusting results.
SHOW work_mem;
SET work_mem = '64MB';  -- illustrative value; use the production setting

Reproducing a logged auto_explain plan with EXPLAIN (ANALYZE, BUFFERS) on a staging copy, including a write statement wrapped in BEGIN ... ROLLBACK and a check that work_mem matches production.

Closing the loop: apply a fix and confirm it in production

Most fixes fall into three groups. If the plan showed a sequential scan filtering out most rows, add an index; CREATE INDEX CONCURRENTLY avoids blocking writes on a busy table. If the plan was reasonable but did unnecessary work, rewrite the query. If estimated and actual row counts were far apart, run ANALYZE on the affected tables. Bad estimates often cause bad join orders, and fresh statistics can fix the plan without any schema change.

Before deploying, take a baseline. You can call pg_stat_statements_reset(), but that discards history for every query. A gentler option is to copy the view into a table with a timestamp before the change and again after. After the change, wait for a window of traffic comparable to the baseline, such as the same hours on a similar weekday. Comparing a Monday peak with a Sunday night will mislead you.

For the target queryid, compare total time, mean time, calls, and shared blocks hit and read. A drop in mean time alongside a large drop in blocks read means the fix worked. A drop in mean time with no change in blocks may only mean the cache was warmer. If you rewrote the query, the queryid changes, so match the old and new entries by their normalized text.

Then check the whole workload. Compare the sum of total time across all statements, not just the one you fixed. Look at the INSERT and UPDATE statements on the indexed table, since every new index adds work to each write and can stop updates from qualifying as HOT updates. Also check the new index's size, and confirm in pg_stat_user_indexes that the planner actually uses it.

When to avoid this approach and what it can hide

Even a well-run loop has blind spots, and on some systems the capture side costs more than it reveals.

Eviction distorts rankings. pg_stat_statements.max caps the number of tracked entries. When it fills, the least-executed entries are discarded. Workloads with ad hoc reporting SQL, or ORMs that inline literals or build IN lists of varying length, produce many distinct normalized entries. An expensive query that runs rarely can be evicted before you look, and frequent resets make totals look smaller than they are.

Means hide variance. A query averaging 5 ms might run in 1 ms for most parameter values and 2 seconds for a skewed one. The standard deviation and max columns tell you variance exists, but not which parameters cause it or which plan ran. Parameter-sensitive plans need captured plans tied to specific executions, not aggregates.

Instrumentation is not free. With auto_explain.log_analyze enabled, every statement in scope is instrumented, including the many that finish under the threshold and are never logged. Per-node timing reads the clock repeatedly, which is expensive on hosts with slow clock sources. Turning off auto_explain.log_timing or lowering the sample rate reduces that cost.

Logs grow and leak. Full plans, especially with buffers and verbose output, multiply log volume, storage, and shipping costs. Logged query text can include literal values such as emails or tokens.

Scope the loop down, or skip it, on high-throughput OLTP systems with sub-millisecond queries, on hosts with slow clock sources, and on databases holding regulated data where logs leave the trust boundary.

Alternatives and impact on cost and engineering time

The loop costs more to set up than the alternatives. Preloading either module through shared_preload_libraries needs a server restart, so it has to be scheduled into a maintenance window. Changing logging thresholds only needs a reload. You also need to budget storage for auto_explain output and decide how long to retain it. A fix has its own cost. Every new index adds work to inserts and to updates that touch indexed columns, and it can prevent HOT updates. Measure write latency after you deploy one.

The time savings come from what you stop working on. Ranking by total time keeps you away from rare outliers. Captured plans spare you from chasing a slow plan you cannot reproduce on your own machine.

Illustrative estimate (assumed numbers, not a benchmark)

Load per hour = mean execution time × calls per hour

• Query A: 2 ms × 1,800,000 calls (500/s) = 3,600 s
• Query B: 4,000 ms × 30 calls = 120 s

Query B looks alarming in a slow log. Query A puts 30 times more load on the server.

How OneEnv can help

Disclosure: OneEnv is the product behind this blog.

OneEnv (oneenv.io) is a workspace-based governance platform for the things services share — environment variables, database structure, API routes and validation rules. A change to a shared value is staged on a branch, reviewed once, and then every affected service explicitly approves or rejects it before it goes live, so you can see who a change touches before it ships instead of finding out in production.

Applied to pg_stat_statements slow queries, this is where it helps:

Saves time

• Every service that inherits a shared value is listed in one place, so nobody searches repos and chats to find out who is affected.
• One review per branch replaces coordinating each team separately; each service still keeps its own approve/reject.
• Reviewers see the exact diff and the list of affected services up front, so approval is a decision rather than an investigation.

Saves cost

• Fewer production incidents and rollbacks caused by a shared value, route or column changing under a consumer unannounced.
• Less duplicated configuration to maintain: one shared definition inherited by many services.
• Per-service approve/reject means a bad shared value can be refused where it would break something, before it is live.
• OneEnv has a free plan (1 workspace, unlimited services and members, full governance), so trying it costs nothing.

These are qualitative benefits, not measured results — how much you save depends on how many services share the value.

Want to try it? Start at oneenv.io.