Timing the run: EXPLAIN ANALYZE

Query blueprints no longer look like cryptography to you: cost, rows, width — you read them like a navigator's plot. But on the way down to the engine room an unpleasant thought catches up with you: all of it is forecasts. The navigator PROMISES a route for so many parrots. And how does the run actually go?

QUERY is waiting for you by the test bench — a slab with clamps, above which an ancient stopwatch with a mechanical hand dangles on a chain.

QUERY: A blueprint says how the navigator intended to travel. The timing says how the travelling went. An engineer who believes blueprints alone builds a bridge out of paper sooner or later. Wind the stopwatch.

The second bracket: the fact beside the forecast

One word is added to the familiar EXPLAIN:

EXPLAIN ANALYZE <your query>;

With ANALYZE the machine does not stop at a forecast — it EXECUTES the query for real, with a stopwatch on every node, and prints the same blueprint with the readings written in. You have met this command in Vault-9 already; now we take its output apart figure by figure. Every node grows a second bracket:

(cost=… rows=… width=…)                     ← the navigator's forecast, parrots
(actual time=startup..total rows=… loops=…) ← the stopwatch readings, the fact

• actual time=startup..total — built like cost (the previous lesson), only the units are honest: MILLISECONDS. The first figure is when the node handed out its first row, the second when it finished.
• rows — how many rows the node returned IN REALITY. Beside the forecast rows of the first bracket this is the plan's main pair of numbers — we devote a whole lesson to it.
• loops — how many times the node was launched during the run. For now keep "usually 1" in mind; a little further down you will see this number explode.

Two service lines are added at the bottom of the plan: Planning Time — how long the navigator thought, and Execution Time — how long the executor travelled.

The estimate meets the fact

The subject is thermal sensor #388: it hangs right above the engine-room hatch, on deck J. The query collects its entire ribbon of readings by time: a full pass over the log with a filter, and a sort above it.

First the blueprint with no run, as you already know how to do:

Reading the stopwatch

Three observations from this fresh timing:

1. The navigator almost guessed it. The forecast promised about 360 rows — the fact gave exactly 361. When the estimate and the fact agree, the navigator is steering by fresh charts; a discrepancy of an order of magnitude is an alarm signal, and a whole lesson of this chapter is devoted to it.
2. actual time shows a node's character. Seq Scan's startup is around zero and its total is nearly the whole run: it hands out the first row at once and then streams evenly — the stream node of the previous lesson. Sort's startup and total nearly coincide: a sort cannot hand out A SINGLE row until it has seen them all — that same dam: it accumulates and releases in one go. Two figures, and you already know which one you are looking at.
3. The milliseconds float. Run the cell again and the times will change slightly: caches, neighbouring processes, the station's mood. But rows=361 and Rows Removed by Filter: 179639 will not shift by a single row. The fact of a run is deterministic — only the stopwatch's hand trembles, and, as you remember from the previous lesson, the navigator's forecast. Which is why an engineer quotes rows and nodes in reports, and times only by orders of magnitude.

The node that was launched forty times

In the plans above every node had loops=1: the node worked once during the run. That is not always so. Remember the report that hung: the machine launched the counting subquery afresh for EVERY sensor. Now you will see what that looks like on the stopwatch.

We take the forty sensors of deck J — the very one whose hatch you came down through — and ask about each one: when did it last make contact?

The main rule of the bracket: multiply by loops

The numbers in the actual bracket are the AVERAGE FOR ONE launch of the node (rounded), not the sum. A node's full contribution is counted by multiplying:

• Aggregate: rows=1 × loops=40 → forty rows for the whole run, one "last contact" per sensor.
• Seq Scan on ls_readings: rows=361 × loops=40 ≈ 14,440 rows returned. And far more were LEAFED THROUGH: every launch goes through the whole log, 40 × 180,000 = 7,200,000 rows — seven million for the sake of forty answers.
• actual time is an average per launch too: the node's full time ≈ the final figure × loops.

That is why, before judging a node by its milliseconds, an engineer looks at loops: a modest node of a few milliseconds, launched thousands of times, eats minutes — the forty seconds of the morning report are made of exactly this test, only with more sensors.

QUERY: A stopwatch does not accuse — it testifies. A node of a few milliseconds is innocent. Take a closer look at whoever launched it forty times.

The stopwatch said HOW MUCH time was spent. An engineer's next question is WHERE: what exactly was the machine leafing through all those milliseconds? The answer is measured not in rows but in pages — in the next lesson we open BUFFERS and count the input and output.