Stop Guessing, Start Profiling: Deep Database Latency Analysis with pg_stat_statements and EXPLAIN ANALYZE

by

Your application is slow. Users are complaining. Your APM shows p99 latency spiking at 3 AM. You add an index, deploy, and… nothing changes. You add another index. Still nothing. You restart Postgres. It gets worse.

Sound familiar?

The problem isn’t your indexes. The problem is you’re flying blind. You’re guessing at bottlenecks instead of measuring them. Every DBA who has survived a production incident will tell you the same thing: you cannot optimize what you haven’t measured.

This article will show you how to stop guessing. We’ll set up pg_stat_statements to find the queries bleeding your database dry, then rip those queries apart with EXPLAIN ANALYZE until we know exactly what Postgres is doing and why. This isn’t a "top 10 tips" list — it’s the actual workflow I use when something is on fire.

The Two Tools You Actually Need

PostgreSQL ships with everything you need to profile it. The community just does a terrible job of showing people where to look.

pg_stat_statements is an extension that tracks execution statistics for every distinct query that runs through your database. Total calls, total time, mean time, standard deviation, rows returned — all of it, accumulated over time. Think of it as a flight recorder for your SQL.

EXPLAIN ANALYZE takes a single query and shows you the execution plan Postgres chose and the actual runtime statistics from running it. It’s the difference between reading a map and actually driving the road.

You need both. pg_stat_statements tells you which queries are the problem. EXPLAIN ANALYZE tells you why.

Setting Up pg_stat_statements

The extension ships with PostgreSQL — you don’t need to install anything. But it does require a configuration change that needs a server restart.

Step 1: Enable the extension in postgresql.conf

# Find your postgresql.conf
sudo -u postgres psql -c "SHOW config_file;"

Add or modify this line:

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements'

# Optional but recommended — track all queries, not just top-level ones
pg_stat_statements.track = all

# Keep stats for the last N queries (default: 5000)
pg_stat_statements.max = 10000

# Save stats across restarts (PG 14+)
pg_stat_statements.save = on

Restart Postgres:

sudo systemctl restart postgresql

Step 2: Create the extension in your database

-- Run this in each database you want to monitor
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

-- Verify it's working
SELECT * FROM pg_stat_statements LIMIT 1;

Gotcha: The extension must be created per-database. If you have multiple databases on the same cluster, you need to run CREATE EXTENSION in each one. The stats themselves are cluster-wide, but the view is only accessible where the extension is installed.

Step 3: Reset stats before a profiling session

Stats accumulate forever until you reset them. Before profiling a specific issue, reset so you’re not reading weeks-old noise:

-- Reset stats for the current database only (PG 12+)
SELECT pg_stat_statements_reset();

-- Reset stats for all databases (superuser only)
SELECT pg_stat_statements_reset(0, 0, 0);

Reading pg_stat_statements Like a Pro

The raw view has ~30 columns. Most people look at the wrong ones. Here’s what actually matters:

SELECT
    -- Normalize the query (removes literal values)
    LEFT(query, 120)                          AS query_snippet,
    calls,
    round(total_exec_time::numeric, 2)        AS total_ms,
    round(mean_exec_time::numeric, 2)         AS mean_ms,
    round(stddev_exec_time::numeric, 2)       AS stddev_ms,
    round((100 * total_exec_time /
           SUM(total_exec_time) OVER ())::numeric, 2) AS pct_total_time,
    rows,
    round(rows::numeric / calls, 2)           AS rows_per_call,
    -- Buffer hits vs disk reads
    shared_blks_hit,
    shared_blks_read,
    round(
        100.0 * shared_blks_hit /
        NULLIF(shared_blks_hit + shared_blks_read, 0),
        2
    )                                          AS cache_hit_pct
FROM pg_stat_statements
WHERE calls > 10  -- ignore one-offs
ORDER BY total_exec_time DESC
LIMIT 25;

What you’re looking at:

  • total_exec_time — the single most important column. High-frequency cheap queries can kill you as much as rare expensive ones.
  • mean_exec_time vs stddev_exec_time — a high standard deviation means the query is inconsistent. That’s usually a cache-miss pattern or a lock contention issue.
  • pct_total_time — if one query owns 40% of total DB time, that’s your target.
  • cache_hit_pct — below 95% on a healthy OLTP system is a red flag. Below 90% means something is hammering the disk.

Finding the worst offenders by different criteria

-- Slowest by average execution time (classic "slow query" hunt)
SELECT LEFT(query, 100), calls, round(mean_exec_time::numeric, 2) AS mean_ms
FROM pg_stat_statements
ORDER BY mean_exec_time DESC LIMIT 10;

-- Most total time spent (most impactful on throughput)
SELECT LEFT(query, 100), calls, round(total_exec_time::numeric, 2) AS total_ms
FROM pg_stat_statements
ORDER BY total_exec_time DESC LIMIT 10;

-- Most disk reads (I/O bottleneck candidates)
SELECT LEFT(query, 100), shared_blks_read, calls
FROM pg_stat_statements
ORDER BY shared_blks_read DESC LIMIT 10;

-- Queries with worst cache hit rate (min 100 reads to filter noise)
SELECT
    LEFT(query, 100),
    shared_blks_hit,
    shared_blks_read,
    round(100.0 * shared_blks_hit / NULLIF(shared_blks_hit + shared_blks_read, 0), 2) AS cache_hit_pct
FROM pg_stat_statements
WHERE shared_blks_read > 100
ORDER BY cache_hit_pct ASC LIMIT 10;

Gotcha: pg_stat_statements normalizes queries — it replaces literals with $1, $2, etc. This means SELECT * FROM users WHERE id = 1 and SELECT * FROM users WHERE id = 999 appear as one row. Good for aggregation, but it means you can’t see which specific parameter values caused a spike. For that, you need pg_stat_activity or application-level logging.

EXPLAIN ANALYZE: Reading the Execution Plan

You’ve found the culprit query from pg_stat_statements. Now you need to understand what Postgres is doing with it. This is where EXPLAIN ANALYZE comes in.

Never just run EXPLAIN. It shows the planned cost without running the query. The costs are Postgres’s estimates — they can be completely wrong. EXPLAIN ANALYZE actually executes the query and shows you reality.

EXPLAIN (ANALYZE, BUFFERS, VERBOSE, FORMAT TEXT)
SELECT u.id, u.email, COUNT(o.id) AS order_count
FROM users u
LEFT JOIN orders o ON o.user_id = u.id
WHERE u.created_at > NOW() - INTERVAL '30 days'
GROUP BY u.id, u.email
ORDER BY order_count DESC
LIMIT 50;

Always use these options:

  • ANALYZE — actually runs the query and measures real times
  • BUFFERS — shows buffer cache hits and disk reads per node
  • VERBOSE — shows output columns and schema-qualified names
  • FORMAT TEXT — human-readable (use JSON when feeding to visualization tools)

Gotcha #1: EXPLAIN ANALYZE runs the query. If it’s a DELETE or UPDATE, wrap it in a transaction and roll back:

BEGIN;
EXPLAIN ANALYZE DELETE FROM sessions WHERE expires_at < NOW();
ROLLBACK;

Gotcha #2: For queries that are slow due to cold cache, run EXPLAIN ANALYZE twice in a row. The first run warms the cache; the second shows you what steady-state performance looks like. The opposite also applies — if you want to see worst-case disk performance, run pg_prewarm in reverse or just check the buffers output.

Anatomy of a Plan Node

Every plan looks like a tree. Here’s a real example output:

Limit  (cost=1842.30..1842.43 rows=50 width=24) (actual time=48.231..48.244 rows=50 loops=1)
  ->  Sort  (cost=1842.30..1847.50 rows=2078 width=24) (actual time=48.229..48.234 rows=50 loops=1)
        Sort Key: (count(o.id)) DESC
        Sort Method: top-N heapsort  Memory: 29kB
        ->  HashAggregate  (cost=1765.12..1786.20 rows=2078 width=24) (actual time=46.102..47.381 rows=2078 loops=1)
              Group Key: u.id, u.email
              Batches: 1  Memory Usage: 593kB
              ->  Hash Left Join  (cost=742.15..1744.04 rows=4216 width=16) (actual time=8.143..43.219 rows=41820 loops=1)
                    Hash Cond: (o.user_id = u.id)
                    Buffers: shared hit=1242 read=87
                    ->  Seq Scan on orders o  (cost=0.00..821.00 rows=41000 width=8) (actual time=0.012..6.311 rows=41000 loops=1)
                          Buffers: shared hit=521 read=0
                    ->  Hash  (cost=726.90..726.90 rows=1220 width=12) (actual time=8.089..8.090 rows=2078 loops=1)
                          Buckets: 4096  Batches: 1  Memory Usage: 104kB
                          ->  Seq Scan on users u  (cost=0.00..726.90 rows=1220 width=12) (actual time=0.010..7.891 rows=2078 loops=1)
                                Filter: (created_at > (now() - '30 days'::interval))
                                Rows Removed by Filter: 19422
                                Buffers: shared hit=721 read=87

Breaking down each node:

(cost=X..Y rows=N width=W) — Postgres’s estimate before running. X is startup cost, Y is total cost. These are arbitrary units, not milliseconds. What matters is whether they’re close to actual.

(actual time=X..Y rows=N loops=L) — What actually happened. Time is in milliseconds. loops is critical — if a node runs inside a nested loop, multiply the times by loops to get total time.

Buffers: shared hit=X read=Y — Cache hits vs disk reads for this node. A high read count here means this operation is going to disk. Find where in the plan disk reads are happening.

Red Flags to Hunt For

Seq Scan on a large table

Seq Scan on orders  (cost=0.00..9821.00 rows=410000 ...)

A sequential scan on hundreds of thousands of rows usually means a missing index. But not always — sometimes Postgres correctly decides a seq scan is faster than an index scan (e.g., when returning >10-15% of the table). Check the filter condition and whether an index would actually help.

Rows Removed by Filter is huge

Seq Scan on users u
  Filter: (status = 'active')
  Rows Removed by Filter: 198000

You’re reading 200k rows to find a few hundred. That index is missing.

Estimate vs actual rows is way off

Nested Loop  (cost=0.00..150.12 rows=3 ...) (actual time=0.012..1821.312 rows=92041 ...)

Postgres thought it would get 3 rows, got 92k. This is a statistics problem. Run:

ANALYZE your_table;
-- or with more samples for high-cardinality columns:
ALTER TABLE your_table ALTER COLUMN your_column SET STATISTICS 500;
ANALYZE your_table;

Nested Loop on large datasets

Nested Loop  (loops=41000)
  ->  Seq Scan on orders (actual time=0.010..0.010 rows=1 loops=41000)

A nested loop that runs 41,000 iterations on a seq scan. Total cost: 41,000 × (seq scan time). This often means a missing foreign key index or a join condition that can’t use an index.

Sort spilling to disk

Sort  (actual time=1842.100..1989.331 ...)
  Sort Method: external merge  Disk: 48128kB

"External merge" means the sort didn’t fit in work_mem and spilled to disk. Fix this by increasing work_mem for the session (not globally, unless you’re careful about memory math):

SET work_mem = '256MB';
EXPLAIN ANALYZE <your query>;

Hash Join batches > 1

HashAggregate
  Batches: 8  Memory Usage: 8192kB

Hash join spilled to disk. Same root cause — insufficient work_mem.

The Full Workflow

Here’s the actual process, not the idealized version:

1. Find the candidate queries

-- After running your workload, grab the top time consumers
SELECT
    queryid,
    LEFT(query, 150) AS q,
    calls,
    round(total_exec_time::numeric, 0) AS total_ms,
    round(mean_exec_time::numeric, 2) AS mean_ms,
    round(stddev_exec_time::numeric, 2) AS std_ms
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 15;

2. Reconstruct the actual query

pg_stat_statements normalizes parameters. Get the real query from your application logs or pg_stat_activity:

-- Catch slow queries in real-time
SELECT pid, now() - pg_stat_activity.query_start AS duration, query, state
FROM pg_stat_activity
WHERE (now() - pg_stat_activity.query_start) > interval '1 second'
  AND state != 'idle'
ORDER BY duration DESC;

3. Run EXPLAIN ANALYZE with real parameters

Use representative values — especially ones that might cause skewed plans (NULL values, extreme ranges, high-frequency values):

-- Use actual values from your production query
EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT)
SELECT ...
WHERE id = 12345 AND status = 'pending';

4. Fix, verify, re-measure

After making a change (adding an index, rewriting the query, fixing statistics), always re-run EXPLAIN ANALYZE to confirm the plan changed the way you expected. Then reset pg_stat_statements and let traffic run for a meaningful window before comparing aggregate stats.

-- Confirm your index is actually being used now
EXPLAIN (ANALYZE, BUFFERS)
SELECT ... ;

-- Look for: Index Scan using your_new_index on ...

Production-Ready Monitoring Setup

Don’t just profile ad-hoc. Set up a query to run periodically and dump results:

-- Create a snapshot table for trending (run as a cron job)
CREATE TABLE IF NOT EXISTS query_stats_snapshots (
    captured_at     TIMESTAMPTZ DEFAULT NOW(),
    queryid         BIGINT,
    query_snippet   TEXT,
    calls           BIGINT,
    total_exec_ms   NUMERIC,
    mean_exec_ms    NUMERIC,
    cache_hit_pct   NUMERIC
);

INSERT INTO query_stats_snapshots (queryid, query_snippet, calls, total_exec_ms, mean_exec_ms, cache_hit_pct)
SELECT
    queryid,
    LEFT(query, 200),
    calls,
    round(total_exec_time::numeric, 2),
    round(mean_exec_time::numeric, 2),
    round(100.0 * shared_blks_hit / NULLIF(shared_blks_hit + shared_blks_read, 0), 2)
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 50;

Or, if you want a production-grade solution without building it yourself, look at pgBadger (log analyzer) or pg_activity (real-time top-like monitor). For dashboards, the Postgres exporter for Prometheus + Grafana is the standard stack — it exposes pg_stat_statements metrics natively.

Gotchas Summary

  • Normalization hides parameter values — use pg_stat_activity to catch live queries with their actual parameters.
  • EXPLAIN without ANALYZE lies — estimates can be off by orders of magnitude. Always use ANALYZE.
  • DML statements need transaction wrappers — EXPLAIN ANALYZE DELETE deletes your data.
  • loops multiplier — always multiply actual time by loops to get real node cost in nested loops.
  • One bad work_mem default — the default is 4MB, which is almost always too low for complex queries. Set it per session when profiling, but think carefully before changing it globally (N connections × M sort operations × work_mem = your RAM).
  • Statistics staleness — after bulk loads or major data changes, run ANALYZE or wait for autovacuum. Stale stats cause bad plans.
  • pg_stat_statements needs the restart — forgetting the shared_preload_libraries restart is the #1 reason people think the extension isn’t working.

Where to Go Next

Once you’ve done this a few times, the pattern becomes muscle memory. You’ll start to recognize a bad plan from the first three lines of output. The tools are just pg_stat_statements to find and rank problems, EXPLAIN ANALYZE to dissect them, and your brain to connect the dots.

If you want to go deeper, the PostgreSQL documentation on execution plan node types and the planner’s cost model are worth a read. Markus Winand’s Use The Index, Luke remains the best resource on the web for understanding how databases actually use indexes.

Most latency problems boil down to three things: missing indexes, stale statistics, or insufficient work_mem. The tools above will show you exactly which one it is within minutes. Stop guessing.

👁 Views: 202,848 · Unique visitors: 57,406