EXPLAIN (ANALYZE, BUFFERS)

EXPLAIN (ANALYZE) runs the statement and prints what actually happened beside what was predicted. Every node gains a second parenthesis carrying real elapsed time, a real row count and the number of times the node was executed, and since 18 the buffer counts come along without being asked for. One command now shows the estimate, the reality and the I/O, which is most of what a slow query investigation needs.

It also means the query really executes. Postgres discards the rows a SELECT would have returned, but an UPDATE updates and a DELETE deletes, and the plan is not the most notable thing that happened. That one property is why this command needs a habit around it rather than a keyboard shortcut, and the habit is three characters long.

Actual Against Estimated

The comparison that matters most is the cheapest one to make. Each node prints rows= in the cost parenthesis, which is the planner's estimate, and rows= again in the actual parenthesis, which is what arrived. Divide one by the other. A factor of two is normal and no plan choice turns on it. A factor of ten deserves a look. A factor of a hundred or more means the planner was pricing an entirely different query from the one you ran, and every decision above that node was made on a false premise: which scan, which join, whether to parallelize. Since 18 the actual count is printed with two decimal places, because a node inside a loop reports an average and averages are rarely whole.

EXPLAIN (ANALYZE)
SELECT o.public_id, o.placed_at, o.total, s.label
  FROM orders o JOIN order_statuses s ON s.status = o.status
 WHERE o.customer_id = 88213
   AND o.placed_at >= date_trunc('month', now());

 Nested Loop  (cost=0.99..17.32 rows=1 width=34)
              (actual time=1204.663..6087.412 rows=21.00 loops=1)
   Buffers: shared hit=107883 read=196204
   ->  Index Scan using orders_placed_at_idx on orders o
         (cost=0.56..8.58 rows=1 width=28)
         (actual time=1204.611..6086.902 rows=21.00 loops=1)
         Index Cond: (placed_at >= date_trunc('month'::text, now()))
         Filter: (customer_id = 88213)
         Rows Removed by Filter: 300461
         Index Searches: 1
         Buffers: shared hit=107841 read=196204
   ->  Index Scan using order_statuses_pkey on order_statuses s
         (cost=0.42..8.44 rows=1 width=14)
         (actual time=0.004..0.004 rows=1.00 loops=21)
         Index Cond: (status = o.status)
         Buffers: shared hit=42
 Planning Time: 0.212 ms
 Execution Time: 6087.502 ms

Twenty-one rows came back, which is the right answer, in 6.1 seconds. Read the plan from the bottom and the waste is unmissable. The inner node is an index lookup into the seven-row status table, run once per result row, and it costs nothing. The outer node walks the date index on orders, was estimated to produce one row, and produced 300,482 before the customer filter — Rows Removed by Filter: 300461 is the whole month's orders, for every customer, fetched from the heap one at a time and thrown away. The planner did not choose that index because it is a bad planner. It chose it because it believed the date predicate matched a single row, and a single-row index scan is the cheapest access path there is. This is Cartwheel's Saturday, and Topic 49 finishes it.

loops, and the Multiplication Trap

The actual time and rows figures on a node are per execution, averaged, and the operations dashboard has a query that makes the point better than any prose can.

 Nested Loop  (actual time=0.061..5904.118 rows=1201928.00 loops=1)
   ...
   ->  Index Scan using delivery_events_order_id_idx on delivery_events d
         (actual time=0.012..0.015 rows=4.00 loops=300482)
         Index Cond: (order_id = o.id)
         Index Searches: 300482

A node reporting 0.015 ms and four rows looks like the least interesting line in the output until you read loops=300482 beside it and multiply. Four and a half seconds went there, and 1.2 million rows came out of a node whose row count reads 4.00. Misreading this is the most common way people optimize the wrong node, because the eye goes to the largest number and the largest number is always on the parent. Since 18 the Index Searches line states the repetition directly, 300,482 separate descents into that index, so the arithmetic no longer has to be inferred. Node timings are exclusive of siblings but inclusive of children, so a parent's total is its children's totals plus its own overhead; when the numbers refuse to add up, the missing time is in a node you trimmed away.

Buffers, and What They Reveal

Buffer counts turn "this query is slow" into "this query is slow for one of two reasons". shared hit is a page found already in shared_buffers. shared read is a page that had to be fetched from the operating system, which may serve it from its own cache or go to the device. dirtied counts pages this query modified, and written counts pages it had to flush to make room, so a read-only query with a non-zero written is evicting somebody else's working set. Since 18 all of it appears with ANALYZE automatically; before that, half the plans shared in incident channels were missing the number that explained them.

On the Saturday plan the split is the diagnosis. The inner scan reports 42 hits and no reads at all, because it is reading a single-page table that never leaves memory. The outer scan reports 196,204 reads against 107,841 hits: nearly two thirds of its page accesses missed the cache and went to the device, and 196,204 scattered fetches at roughly twenty-five microseconds each is five seconds. That is where the time went, and it is not a CPU problem, an index problem or a join problem.

Spills to Disk

A sort or a hash that does not fit in work_mem does not fail — it spills to temporary files, and the plan says so plainly. The reporting line for a sort names the method and the space it needed, and a matching temp read and written pair appears in the buffer counts.

EXPLAIN (ANALYZE)
SELECT customer_id, sum(total) AS spend
  FROM orders
 WHERE placed_at >= date_trunc('month', now())
 GROUP BY customer_id
 ORDER BY spend DESC;

 Sort  (cost=71904.22..72614.51 rows=284117 width=40)
       (actual time=1284.663..1331.902 rows=284117.00 loops=1)
   Sort Key: (sum(total)) DESC
   Sort Method: external merge  Disk: 11416kB
   Buffers: shared hit=3492 read=118, temp read=1427 written=1431

Eleven megabytes of sorted data did not fit in the 4 MB that work_mem grants by default, so Postgres wrote runs to temporary files and merged them back, and the 1,431 temp blocks written are the receipt. The in-memory alternative would have said Sort Method: quicksort with a memory figure instead. This is the most frequently actionable single line in a slow analytic query, and it has exactly two honest fixes: give this session more memory, or arrange for fewer rows to reach the sort. Which of those applies, and why raising the setting globally is how servers start swapping, is Chapter 10's material.

Running It Without Consequences

Wrap every write in a transaction you throw away. BEGIN, then EXPLAIN (ANALYZE) the UPDATE or DELETE, then ROLLBACK: the plan and the real timings survive, the rows do not change, and you have measured the statement rather than performed it. The cost of forgetting is a data-loss incident with a plan attached, and it is entirely avoidable by making the three-statement form the only way you ever type the command.

Timing itself is not free. Postgres reads the clock twice per row per node, and on hardware with a slow system clock that instrumentation can dominate the measurement — pg_test_timing exists to tell you how bad it is on your machine. When the overhead distorts the result, run with TIMING OFF: you keep the row counts, the loops and the buffers, which is most of the diagnosis, and you lose only the per-node durations. Two more habits are worth building. Run the same statement twice on purpose, because the cold number describes a Saturday morning and the warm one a Tuesday afternoon, and both are real. And never draw a conclusion from a single cold run: the second execution finds the pages cached and the hint bits already set.

The Rest of the Options

The command takes a parenthesized option list, and five of them earn their keystrokes. VERBOSE adds output column lists and schema-qualified names, which is how you find out that the id in a plan is the one from order_items. SETTINGS prints the planner parameters that differ from the built-in defaults, so a plan captured with enable_nestloop turned off in that session carries the evidence with it. WAL reports how much write-ahead log the statement generated, which is the number that matters for a bulk update's effect on replicas. FORMAT JSON produces something a tool can parse. And BUFFERS can still be requested explicitly, which is the only way to get buffer counts out of a plan without running the query.

Another two are situational and worth knowing before you need them. SERIALIZE measures the cost of converting the result to wire format, which is the missing piece when a query is fast in psql and slow in the application and the payload is large. GENERIC_PLAN plans a statement containing $1 placeholders without any values, which is how you see the plan a prepared statement can be given; it cannot be combined with ANALYZE, for the obvious reason that there is nothing to substitute.