EXPLAIN and EXPLAIN ANALYZE

Read a real query plan node by node — and reproduce "30 seconds on production, 0.1 seconds locally" with nothing but a cold cache

EXPLAIN alone shows what the planner intends to do and what it estimates that will cost — useful, but entirely theoretical. EXPLAIN ANALYZE actually runs the query and reports what really happened at every node: real row counts, real timing, and — with BUFFERS added — exactly how many blocks came from shared_buffers versus how many had to be read from disk.\n\nThat last distinction is the entire explanation behind this lab's opening scenario. The exact same query, run twice against this course's own beer_db data, tells two different stories: the first run pays for real disk reads because nothing is cached yet, and the second run — identical query, identical data — is served entirely from memory. This is "fast locally, slow in production" reproduced directly, not asserted: a warmed-up development database and a cold production one are not running different queries, they are paying a completely different price for the same one.

The Cost Model

Seq Scan on beers b  (cost=0.00..31.50 rows=650 width=64)

cost=0.00..31.50 reads as startup cost..total cost, in arbitrary planner units, not milliseconds. 0.00 means this node can start producing rows immediately (a sequential scan needs no setup); 31.50 is the estimated total cost to read every row. rows=650 is the planner's estimate of how many rows this node will produce — worth remembering as an estimate, not a promise, before the next lab shows exactly how wrong it can be.

Adding ANALYZE: What Actually Happened

EXPLAIN ANALYZE SELECT * FROM beers WHERE brewery_id = '...';

Seq Scan on beers  (cost=0.00..32.00 rows=8 width=64) (actual time=0.012..0.045 rows=8.00 loops=1)

actual time=0.012..0.045 is real milliseconds elapsed for this node specifically, and rows=8.00 is what genuinely came out — comparing this against the estimate a few characters to its left is the single most useful habit in this entire block.

Adding BUFFERS: Cache or Disk

EXPLAIN (ANALYZE, BUFFERS) SELECT ...;

Buffers: shared hit=103
-- or, on a cold cache:
Buffers: shared read=100

hit means the block was already sitting in shared_buffers; read means PostgreSQL genuinely had to fetch it from disk (or the OS page cache underneath, which BUFFERS cannot distinguish from a true physical read). A query dominated by read on its first run and by hit on every run after is not two different queries — it is the same query paying a real, one-time cost to warm the cache.

Cost vs Actual Time

Cost is the planner's own internal unit for comparing candidate plans to each other before any of them run — it is not a time prediction and should never be read as one. Actual time (only present with ANALYZE) is real, measured milliseconds for that specific node. A plan with a low cost can still have a high actual time if the planner's underlying assumptions — about row counts, cache state, or correlations — turn out to be wrong.

shared hit vs shared read

Both count 8KB buffer accesses during query execution. hit means the block was already resident in shared_buffers; read means PostgreSQL had to request it from the OS, which may itself still be served from the OS page cache or may hit physical disk — BUFFERS alone cannot tell those two apart, only that shared_buffers itself did not already have it.

📖 Read a Plan Without Running Anything

Run plain EXPLAIN on a real 3-table join and read the cost estimates before anything actually executes.

psql -U postgres -d beer_db -c "EXPLAIN SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;"

student@lab:~$ psql -U postgres -d beer_db -c "EXPLAIN SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;" SET QUERY PLAN ------------------------------------------------------------------------------------------ GroupAggregate (cost=160.69..160.79 rows=5 width=96) Group Key: b.name -> Sort (cost=160.69..160.70 rows=5 width=76) Sort Key: b.name -> Hash Join (cost=41.41..160.63 rows=5 width=76) Hash Cond: (r.beer_id = b.id) -> Seq Scan on beer_ratings r (cost=0.00..106.58 rows=3358 width=28) -> Hash (cost=41.39..41.39 rows=1 width=80) -> Hash Join (cost=8.18..41.39 rows=1 width=80) Hash Cond: (b.brewery_id = br.id) -> Seq Scan on beers b (cost=0.00..31.50 rows=650 width=64) -> Hash (cost=8.17..8.17 rows=1 width=48) -> Index Scan using breweries_name_key on breweries br (cost=0.15..8.17 rows=1 width=48) Index Cond: (name = 'Golden Brewery'::text) (14 rows)

⏱️ Add ANALYZE and BUFFERS — First Run, Cold

Run the same query with ANALYZE and BUFFERS added, capturing what actually happened on a cache that has not seen this data yet.

psql -U postgres -d beer_db -c "EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT) SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;"

student@lab:~$ psql -U postgres -d beer_db -c "EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT) SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;" SET QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- GroupAggregate (cost=160.69..160.79 rows=5 width=96) (actual time=101.963..103.951 rows=8.00 loops=1) Group Key: b.name Buffers: shared read=100 -> Sort (cost=160.69..160.70 rows=5 width=76) (actual time=101.963..102.100 rows=40.00 loops=1) Sort Key: b.name Sort Method: quicksort Memory: 18kB Buffers: shared read=100 -> Hash Join (cost=41.41..160.63 rows=5 width=76) (actual time=23.259..97.239 rows=40.00 loops=1) Hash Cond: (r.beer_id = b.id) Buffers: shared read=100 -> Seq Scan on beer_ratings r (cost=0.00..106.58 rows=3358 width=28) (actual time=1.396..42.700 rows=2000.00 loops=1) Buffers: shared read=73 -> Hash (cost=41.39..41.39 rows=1 width=80) (actual time=21.758..21.758 rows=8.00 loops=1) Buffers: shared read=27 -> Hash Join (cost=8.18..41.39 rows=1 width=80) (actual time=4.020..21.627 rows=8.00 loops=1) Buffers: shared read=27 -> Seq Scan on beers b (cost=0.00..31.50 rows=650 width=64) (actual time=0.950..13.691 rows=400.00 loops=1) Buffers: shared read=25 -> Hash (cost=8.17..8.17 rows=1 width=48) (actual time=2.958..2.958 rows=1.00 loops=1) Buffers: shared read=2 -> Index Scan using breweries_name_key on breweries br (cost=0.15..8.17 rows=1 width=48) (actual time=2.782..2.821 rows=1.00 loops=1) Index Cond: (name = 'Golden Brewery'::text) Buffers: shared read=2 Planning: Buffers: shared hit=319 read=31 Planning Time: 82.087 ms Execution Time: 104.972 ms (24 rows)

🔥 Run It Again — Warm

Run the exact same query again, immediately, and watch every read become a hit.

psql -U postgres -d beer_db -c "EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT) SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;"

student@lab:~$ psql -U postgres -d beer_db -c "EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT) SELECT b.name, br.name AS brewery, avg(r.score) FROM beers b JOIN breweries br ON br.id = b.brewery_id JOIN beer_ratings r ON r.beer_id = b.id WHERE br.name = 'Golden Brewery' GROUP BY b.name, br.name;" SET QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- GroupAggregate (cost=160.69..160.79 rows=5 width=96) (actual time=49.811..51.164 rows=8.00 loops=1) Group Key: b.name Buffers: shared hit=103 -> Sort (cost=160.69..160.70 rows=5 width=76) (actual time=49.780..49.943 rows=40.00 loops=1) Sort Key: b.name Sort Method: quicksort Memory: 18kB Buffers: shared hit=103 -> Hash Join (cost=41.41..160.63 rows=5 width=76) (actual time=9.039..48.045 rows=40.00 loops=1) Hash Cond: (r.beer_id = b.id) Buffers: shared hit=100 -> Seq Scan on beer_ratings r (cost=0.00..106.58 rows=3358 width=28) (actual time=0.000..20.551 rows=2000.00 loops=1) Buffers: shared hit=73 -> Hash (cost=41.39..41.39 rows=1 width=80) (actual time=8.311..8.311 rows=8.00 loops=1) Buffers: shared hit=27 -> Hash Join (cost=8.18..41.39 rows=1 width=80) (actual time=0.267..8.152 rows=8.00 loops=1) Buffers: shared hit=27 -> Seq Scan on beers b (cost=0.00..31.50 rows=650 width=64) (actual time=0.000..3.642 rows=400.00 loops=1) Buffers: shared hit=25 -> Hash (cost=8.17..8.17 rows=1 width=48) (actual time=0.254..0.254 rows=1.00 loops=1) Buffers: shared hit=2 -> Index Scan using breweries_name_key on breweries br (cost=0.15..8.17 rows=1 width=48) (actual time=0.146..0.146 rows=1.00 loops=1) Index Cond: (name = 'Golden Brewery'::text) Buffers: shared hit=2 Planning: Buffers: shared hit=355 Planning Time: 37.019 ms Execution Time: 54.144 ms (24 rows)

Lab 3.1.1 complete. A real query plan, read node by node, with a real cold-vs-warm cache difference reproduced directly:\n\n\n Plan nodes read : ✅ Seq Scan, Index Scan, Hash Join, Sort, GroupAggregate\n Cost vs actual : ✅ told apart, correctly, on a real plan\n BUFFERS cold vs warm : ✅ real read→hit transition, ~2x execution time difference\n

Enable JavaScript to run the live terminal and track your progress.