Introduction#
EXPLAIN ANALYZE is PostgreSQL’s query profiler. It shows how the query planner executes a query, actual row counts, actual timing, and buffer usage. Reading query plans is an essential skill for diagnosing slow queries.
Basic Usage#
1
2
3
4
5
6
7
8
9
10
11
12
13
| -- EXPLAIN: shows plan without executing
EXPLAIN SELECT * FROM orders WHERE user_id = 42;
-- EXPLAIN ANALYZE: executes the query and shows actual timing
EXPLAIN ANALYZE SELECT * FROM orders WHERE user_id = 42;
-- Full diagnostic output
EXPLAIN (ANALYZE, BUFFERS, VERBOSE, FORMAT TEXT)
SELECT o.*, u.email
FROM orders o
JOIN users u ON o.user_id = u.id
WHERE o.created_at > NOW() - INTERVAL '7 days'
AND o.status = 'pending';
|
Reading the Output#
1
2
3
4
5
6
7
8
9
10
11
12
13
14
| Nested Loop (cost=0.43..125.67 rows=12 width=156)
(actual time=0.128..2.341 rows=8 loops=1)
Buffers: shared hit=45 read=12
-> Index Scan using idx_orders_status_created on orders
(cost=0.43..89.12 rows=12 width=120)
(actual time=0.089..1.987 rows=8 loops=1)
Index Cond: ((status = 'pending') AND (created_at > '...'))
Buffers: shared hit=20 read=10
-> Index Scan using users_pkey on users
(cost=0.43..3.04 rows=1 width=36)
(actual time=0.044..0.044 rows=1 loops=8)
Buffers: shared hit=25 read=2
Planning Time: 1.234 ms
Execution Time: 2.567 ms
|
Cost: (startup_cost..total_cost) — planner’s estimate. Not wall-clock time, it is in abstract units.
Rows: planner estimate vs actual rows. Large discrepancies indicate stale statistics.
Loops: number of times this node was executed. actual time is per-loop; multiply by loops for total.
Buffers:
shared hit: pages read from buffer cache (fast)shared read: pages read from disk (slow)shared dirtied/written: pages modified
Node Types#
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
| -- Seq Scan: full table scan — usually bad on large tables
Seq Scan on orders (cost=0.00..4521.00 rows=100000 width=120)
Filter: (user_id = 42)
Rows Removed by Filter: 99980
-- Index Scan: uses index to find rows, fetches heap pages for each row
Index Scan using idx_orders_user_id on orders
Index Cond: (user_id = 42)
-- Index Only Scan: all needed columns in the index — no heap fetch
Index Only Scan using idx_orders_user_id_status on orders
Index Cond: ((user_id = 42) AND (status = 'pending'))
Heap Fetches: 0 ← ideal
-- Bitmap Heap Scan: used when many rows match — batches heap fetches
Bitmap Heap Scan on orders
Recheck Cond: (user_id = 42)
-> Bitmap Index Scan on idx_orders_user_id
Index Cond: (user_id = 42)
|
Join Types#
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
| -- Nested Loop: good for small result sets
-- For each row in outer, scan inner once
Nested Loop (actual rows=8)
-> (outer table scan)
-> (inner index scan, once per outer row)
-- Hash Join: build hash table from smaller table, probe with larger
-- Good for larger equi-joins
Hash Join (actual rows=10000)
Hash Cond: (orders.user_id = users.id)
-> Seq Scan on orders
-> Hash
Buckets: 1024 Batches: 1 Memory Usage: 256kB
-> Seq Scan on users
-- Merge Join: both inputs must be sorted on join key
-- Good when both sides have indexes on join column
Merge Join
Merge Cond: (orders.user_id = users.id)
-> Index Scan using idx_orders_user_id on orders
-> Index Scan using users_pkey on users
|
Diagnosing Common Problems#
Row Count Estimate Far Off#
1
2
3
4
5
6
7
8
9
| EXPLAIN ANALYZE SELECT * FROM orders WHERE user_id = 42 AND status = 'rare_status';
-- actual rows=10000, estimated rows=5 ← planner will choose wrong join strategy
-- Fix: update statistics
ANALYZE orders;
-- Or increase statistics target for the column
ALTER TABLE orders ALTER COLUMN status SET STATISTICS 500;
ANALYZE orders;
|
Slow Hash Join Due to Work Mem#
1
2
3
4
5
6
7
8
9
10
| -- Hash Join batching to disk (slow)
Hash Join
-> Hash
Buckets: 1024 Batches: 8 Memory Usage: 4096kB
-- Batches > 1 means it spilled to disk
-- Increase work_mem for the session
SET work_mem = '256MB';
-- Or globally in postgresql.conf (affects all sessions)
-- work_mem = 64MB
|
Missing Index Hint#
1
2
3
4
5
6
7
8
9
10
11
12
| -- Seq Scan on large table with low selectivity filter
Seq Scan on events (cost=0.00..521000.00 rows=500000 width=240)
Filter: (event_type = 'page_view')
Rows Removed by Filter: 9500000
-- Check if an index exists
\d events
-- No index on event_type
-- Add the index
CREATE INDEX CONCURRENTLY idx_events_type ON events(event_type);
-- Re-run EXPLAIN ANALYZE to verify index is used
|
pgBadger and auto_explain#
1
2
3
4
5
6
7
8
9
10
| -- Log slow queries automatically
-- postgresql.conf:
-- log_min_duration_statement = 1000 -- log queries > 1s
-- auto_explain.log_min_duration = 500 -- auto EXPLAIN queries > 500ms
-- auto_explain.log_analyze = on
-- In psql for the current session:
LOAD 'auto_explain';
SET auto_explain.log_min_duration = 100;
SET auto_explain.log_analyze = true;
|
1
2
3
| # Parse PostgreSQL log and generate HTML report
pgbadger /var/log/postgresql/postgresql.log -o report.html
open report.html
|
Conclusion#
EXPLAIN ANALYZE with BUFFERS gives you everything needed to diagnose a slow query: which nodes are slow, whether indexes are used, whether row estimates are accurate, and whether you’re hitting disk. Focus on nodes with high actual time and high shared read. Row estimate discrepancies indicate statistics need updating. Large Batches in Hash Join nodes indicate insufficient work_mem.