PostgreSQL EXPLAIN (ANALYZE, BUFFERS) Mastery: Diagnosing Cache Hits, Temp File Spills, and SSD I/O Thrashing

Beyond Execution Time: Why Milliseconds Lie in Database Profiling

When database queries misbehave in production, the standard diagnostic reflex is to run EXPLAIN ANALYZE and search for the step with the highest execution duration. While intuitive, execution time is an inherently noisy, deceptive metric: a query executed while all pages are resident in memory might execute in 8 milliseconds on staging, yet balloon to 4,500 milliseconds in production when disk caches are cold or under NVMe I/O queue pressure.

To perform true database forensics, senior database architects rely on a mandatory modifier: EXPLAIN (ANALYZE, BUFFERS). Buffers reveal the exact physical and shared memory economics of your query—quantifying page hits, random disk reads, dirty page generation, and temporary spill files.

1. Decoding the Buffers Metric Line

Whenever BUFFERS is enabled, PostgreSQL appends memory allocation metrics to every node in the execution plan. The anatomy of this output dictates whether your query is database-friendly or a silent I/O killer:

Buffers: shared hit=4281 read=149 dirtied=12 written=4
Buffers: temp read=1240 written=1240

• shared hit: Number of 8KB database pages retrieved directly from PostgreSQL’s shared_buffers pool in RAM. This incurs zero disk I/O and near-zero latency.
• shared read: Number of 8KB pages not found in shared_buffers, forcing an operating system system call (pread()). These pages were either served from Linux page cache or read directly from NVMe/SSD storage.
• shared dirtied: Number of pages modified in memory by this query (e.g. updating tuple headers, HOT chain updates). High dirty rates signal impending checkpoint write spikes.
• shared written: Number of dirty pages evicted and written to storage by this backend process during buffer allocation because no clean shared buffer was immediately available.
• temp read / written: Number of 8KB temporary pages written to disk because an intermediate operation (sorting, hashing, CTE materialization) exceeded the backend's allocated work_mem.

2. Case Study: Diagnosing the Silent I/O Killer

Consider an un-optimized audit query filtering user activity:

EXPLAIN (ANALYZE, BUFFERS)
SELECT user_id, action, COUNT(*) 
FROM event_stream 
WHERE created_at >= NOW() - INTERVAL '30 days'
GROUP BY user_id, action 
ORDER BY COUNT(*) DESC LIMIT 20;

The resulting execution plan exposes two catastrophic bottlenecks:

Limit  (cost=14250.20..14250.25 rows=20 width=48) (actual time=242.110..242.115 rows=20 loops=1)
  Buffers: shared hit=1820 read=32840, temp read=2840 written=2840
  ->  Sort  (cost=14250.20..14285.40 rows=14080 width=48) (actual time=242.108..242.112 rows=20 loops=1)
        Sort Method: external merge  Disk: 22720kB
        Buffers: shared hit=1820 read=32840, temp read=2840 written=2840
        ->  HashAggregate  (cost=11200.00..12800.00 rows=14080 width=48) (actual time=182.400..204.100 rows=14080 loops=1)
              Buffers: shared hit=1820 read=32840
              ->  Seq Scan on event_stream  (cost=0.00..9800.00 rows=280000 width=40) (actual time=0.040..98.200 rows=280000 loops=1)
                    Filter: (created_at >= (now() - '30 days'::interval))
                    Buffers: shared hit=1820 read=32840

3. Forensic Analysis & Root-Cause Remediation

Examining the buffers output uncovers two critical failures that standard timing metrics conceal:

1. Disk Spill (Sort Method: external merge Disk: 22720kB): The sort operation required 22.7MB of RAM, but the active work_mem was constrained to the default 4MB. PostgreSQL was forced to write 2,840 temporary 8KB pages to local disk storage, perform an external merge sort, and read those 2,840 pages back into memory.
2. Buffer Cache Thrashing (read=32840): 32,840 pages (262.7MB) were read from disk because no partial index existed on created_at. This massive scan pushed active web session data out of the shared buffer pool.

4. Targeted Optimization

We remediate both issues with surgical precision:

-- 1. Create covering composite index on recent events
CREATE INDEX CONCURRENTLY idx_event_stream_recent_covering 
ON event_stream (created_at DESC) 
INCLUDE (user_id, action);

-- 2. Dynamically allocate work_mem for this specific batch execution
SET work_mem = '64MB';

Re-running EXPLAIN (ANALYZE, BUFFERS) reveals an astonishing transformation:

Limit  (cost=0.56..120.40 rows=20 width=48) (actual time=0.048..0.082 rows=20 loops=1)
  Buffers: shared hit=84 read=0
  ->  Index Only Scan using idx_event_stream_recent_covering on event_stream ...
        Sort Method: quicksort  Memory: 2480kB
        Buffers: shared hit=84 read=0
Execution Time: 0.112 ms

The query dropped from 242 milliseconds and 262MB of disk I/O to 0.11 milliseconds and 0 disk reads, entirely contained within 84 memory buffers. Never optimize database performance without BUFFERS.