Diagnosing I/O Wait with track_io_timing #

Two plans read the same number of buffers and take 400 ms and 4 seconds. Buffer counts alone cannot explain the difference, because they count pages touched, not time spent. One plan found its pages in the operating system cache; the other waited on storage for each of them. track_io_timing turns that difference into a number in the plan.

Ranking nodes by buffers is covered in using BUFFERS to find I/O hotspots. This page adds the timing dimension.

The Condition #

With track_io_timing = on, PostgreSQL measures the time spent in read and write system calls and reports it per node when BUFFERS is requested:

Buffers: shared hit=4102 read=18204
I/O Timings: shared read=3841.204 write=12.402

shared read is wall-clock time waiting for those 18,204 page reads — here 3.8 seconds, an average of 0.21 ms per page, which indicates storage rather than page cache. Crucially, a page counted as read may still have been served by the operating system’s cache, in which case the time per page is a few microseconds. Without timings there is no way to tell those cases apart.

The setting has a cost: two clock reads per I/O operation. On systems with a fast clock source it is negligible and many installations leave it on permanently; on systems where clock_gettime is slow it can be measurable. pg_test_timing reports the clock’s cost, and the same consideration applies to EXPLAIN ANALYZE’s own per-node timing, as noted in EXPLAIN options and output formats.

The same counters feed pg_stat_statements (shared_blk_read_time, shared_blk_write_time), which makes it possible to rank statements by I/O wait rather than by total time.

Same buffers, different waiting Left, a plan reading 18,204 pages with I/O timings of 3,841 milliseconds, about 0.21 milliseconds per page, indicating storage reads. Right, the same plan after the data is cached, reading the same 18,204 pages with I/O timings of 31 milliseconds, about 0.002 milliseconds per page, indicating operating system cache hits. cold: storage reads Buffers: read=18204 I/O Timings: read=3841 ms ≈ 0.21 ms per page total 4.1 s warm: OS cache Buffers: read=18204 I/O Timings: read=31 ms ≈ 0.002 ms per page total 0.4 s the buffer counts are identical; only the timings differ

Annotated EXPLAIN Evidence #

SET track_io_timing = on;

EXPLAIN (ANALYZE, BUFFERS)
SELECT count(*) FROM events WHERE occurred_at >= '2026-09-01' AND kind = 'purchase';
Aggregate  (actual time=4102.6..4102.6 rows=1 loops=1)
  Buffers: shared hit=4102 read=18204
  I/O Timings: shared read=3841.204
  ->  Bitmap Heap Scan on events  (actual time=42.1..4080.2 rows=1204110 loops=1)
        Recheck Cond: (occurred_at >= '2026-09-01'::date)
        Filter: (kind = 'purchase'::text)
        Rows Removed by Filter: 7204110
        Heap Blocks: exact=17204
        Buffers: shared hit=4020 read=18108
        I/O Timings: shared read=3822.104
        ->  Bitmap Index Scan on events_occurred_at_idx  (actual time=38.4..38.4 rows=8408220 loops=1)
              Buffers: shared hit=82 read=96
              I/O Timings: shared read=19.100
Execution Time: 4104.1 ms
-- 3.84 s of 4.10 s is waiting for storage: this is an I/O problem, not a CPU one
-- per-page read time 0.21 ms suggests the pages were not in any cache

The same query after the data is cached:

  Buffers: shared hit=22104 read=202
  I/O Timings: shared read=41.204
Execution Time: 402.6 ms
-- same work, 10× faster, purely from cache state
Three numbers from I/O Timings Three items are annotated. The ratio of I/O time to node time shows whether the node is I/O bound. Time divided by pages read gives per-page latency, which distinguishes storage from operating system cache. Comparing hits with reads shows how much the shared buffer cache absorbed. I/O read 3841 ms of 4102 ms total 94% waiting on storage 3841 ms ÷ 18204 pages = 0.21 ms storage latency, not cache hit=4102 vs read=18204 shared buffers covered 18% without timings, all three of these are guesses

Step-by-Step Resolution #

  1. Enable timing for the session or globally after checking the clock cost:

    SET track_io_timing = on;      -- session
-- or ALTER SYSTEM SET track_io_timing = on; SELECT pg_reload_conf();

  2. Compute the I/O share per node: I/O Timings ÷ actual time. Above roughly half means the node is I/O bound and CPU tuning will not help.

  3. Compute per-page latency: I/O time ÷ pages read. Microseconds indicate cache; tenths of a millisecond indicate storage; milliseconds indicate slow or contended storage.

  4. Reduce pages read rather than making storage faster: a better index, a covering index for an index-only scan, or a filter pushed lower. The candidates are identified by the buffer ranking in using BUFFERS to find I/O hotspots.

  5. Check cache sizing when the same pages are read repeatedly across runs: shared_buffers, and whether the working set fits in RAM at all.

  6. Rank statements by I/O wait to find the workload’s worst offenders:

    SELECT round(shared_blk_read_time)::bigint AS read_ms, calls, left(query, 60)
FROM pg_stat_statements ORDER BY shared_blk_read_time DESC LIMIT 5;

  7. Re-measure on a cold cache when comparing two plans, since a warm cache hides the difference you are trying to measure.

Where the four seconds went On a cold cache the query spends 3,841 milliseconds waiting for storage and 263 milliseconds on CPU. On a warm operating system cache it spends 41 milliseconds on I/O and 362 on CPU. After adding a covering index it spends 4 milliseconds on I/O and 38 on CPU. cold: I/O wait 3,841 ms cold: CPU 263 ms warm: I/O wait 41 ms indexed: total 42 ms reducing pages read helps in every cache state

Before and After #

-- BEFORE: bitmap heap scan over a wide date range, cold cache
Buffers: read=18204  I/O Timings: shared read=3841.204                Execution Time: 4104.1 ms

-- AFTER: composite index on (kind, occurred_at), index-only scan
Buffers: read=104  I/O Timings: shared read=22.104                     Execution Time: 41.8 ms

Reading temp I/O separately #

BUFFERS also reports temp read and temp written for spills, and with timing enabled, I/O Timings: temp read=… write=…. Those are a different problem from table I/O: they mean a sort, hash or materialise node exceeded its memory budget and went to disk. The fix is memory sizing or a plan change, not caching or storage, and the diagnostics are in temp file usage and log_temp_files.

Separating the three categories — shared reads (table and index pages), temp I/O (spills), and CPU — is what makes a slow plan actionable. A node that is 90% shared reads needs fewer pages; one that is 90% temp I/O needs more memory or a different algorithm; one that is 90% CPU needs less per-row work, which usually means fewer rows.

Note that I/O Timings measures only the time PostgreSQL spends in read and write calls. Waiting for a lock, for a parallel worker, or for the client to consume rows appears as node time without I/O time, which is a useful negative signal: a node that is slow with neither I/O nor obvious CPU work is usually waiting for something else, and lock waits that look like slow plans covers the most common cause.

Using the numbers to size the cache #

Per-node I/O timings also answer a capacity question that is otherwise guesswork: whether the working set fits in memory. If the same queries, run repeatedly over a day, keep reporting substantial shared read time, the pages they need are being evicted between runs — either because shared_buffers and the operating system cache together are smaller than the working set, or because other workloads are pushing them out.

Comparing hit against read per node over several runs makes the pattern visible: a node whose hit ratio improves on the second run and degrades again an hour later is competing for cache. The remedies are ordered by cost: reduce the pages the query needs (index or projection changes), reduce what else competes for cache (smaller indexes, as in B-tree deduplication and index size), and only then add memory.

Common Pitfalls #

Measuring on a warm cache. The I/O disappears. Diagnostic signal: fast repeated runs, slow first runs. Fix: measure cold, or accept that you are measuring cache state.

Leaving timing off. Buffer counts alone cannot distinguish cache from storage. Diagnostic signal: plans with identical buffers and very different times. Fix: enable track_io_timing.

Chasing storage speed. Faster disks help; reading fewer pages helps more. Diagnostic signal: hardware proposals before index review. Fix: reduce pages first.

Confusing temp I/O with table I/O. They have different fixes. Diagnostic signal: high temp read or write in the timings. Fix: treat as a memory problem.

Frequently Asked Questions #

What does track_io_timing do? #

It makes PostgreSQL measure the time spent in read and write system calls, which EXPLAIN then reports per node as I/O Timings when BUFFERS is requested, and which pg_stat_statements exposes per statement.

Is track_io_timing expensive? #

It adds two clock reads per I/O operation. On most modern systems that is negligible and it can be left on permanently; check with pg_test_timing if the clock source is slow.

How do I tell whether a query is I/O bound? #

Compare I/O Timings with the node’s actual time. If most of the time is I/O, the fix is to read fewer pages — a better index or an index-only scan — rather than to reduce CPU work.

Up: Identifying Plan Bottlenecks