What happened
We created a new index and ran EXPLAIN ANALYZE to compare it with the old query. The first run of the query using the new index looked alarmingly slow, and we nearly concluded that the index did not help.
Running it again, the time dropped sharply even though nothing had changed.
Why it happens
EXPLAIN ANALYZE is not wrong, but it measures according to the cache state of that particular run. If the data or index pages are not yet in PostgreSQL's shared buffers, Postgres has to request them from the operating system, which may mean a real disk read. The first run therefore includes the cost of loading the data.
On the next run those pages are already cached, so the time shrinks a lot. The trap is comparing the first (cold) run of one query against a later (warm) run of another, which can make an index look helpful or useless when the difference comes from caching, not from the plan.
What we do now
We now always run the query twice, read the second result, and add BUFFERS. In the output, shared hit counts pages found in shared buffers and read counts pages that had to be requested from outside. If the first run shows many reads and the second is almost all hits, the time difference is cache.
Keep in mind that a read may be served from the operating system's page cache rather than the disk itself, and that if production often meets uncached data, the warm number can look better than reality, so it is worth looking at both cases.
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders
WHERE customer_id = 42 AND deleted_at IS NULL;
-- run it twice, then compare "shared hit" and "read" in each runQuick checklist
- 1Run EXPLAIN (ANALYZE, BUFFERS) once and note the result.
- 2Run it again and read the second result.
- 3Compare shared hit with read in each run.
- 4When comparing before and after an index, compare warm runs with warm runs.
Rule of thumb
Run EXPLAIN ANALYZE twice with BUFFERS, and always compare warm runs with warm runs.