The index that made our query slower, and other things EXPLAIN ANALYZE told me

Short version: someone added an index "because we order by that column", and the dispatcher dashboard went from 40 ms to 9 seconds for our smallest depots. The someone was me. I found out on the bike home, which is 14 km, which is enough time to stop being angry at yourself.

The query

SELECT id, reference, created_at
FROM shipments
WHERE depot_id = 42
  AND status = 'pending'
ORDER BY created_at DESC
LIMIT 50;

Dispatchers open this page all day. 380 million rows in shipments, around 2% of them pending at any moment. Before my change there was an index on depot_id. I added one on created_at.

What the plan said

Always EXPLAIN (ANALYZE, BUFFERS). Plain EXPLAIN gives you the planner's guesses. ANALYZE runs the query and shows what actually happened. BUFFERS shows how many pages came from memory and how many from disk.

Limit  (cost=0.57..1423.10 rows=50 width=40) (actual time=8712.334..9104.551 rows=50 loops=1)
  Buffers: shared hit=181220 read=402113
  ->  Index Scan Backward using shipments_created_at_idx on shipments
        (cost=0.57..2843391.02 rows=99941 width=40) (actual time=8712.331..9104.512 rows=50 loops=1)
        Filter: ((depot_id = 42) AND (status = 'pending'::text))
        Rows Removed by Filter: 4812330
        Buffers: shared hit=181220 read=402113
Planning Time: 0.311 ms
Execution Time: 9104.602 ms

Read it from the inside out. Postgres walked my new index backwards, newest first, and checked every row against the filter until it had 50 matches. It removed 4.8 million rows to find 50. Why did the planner choose that? Because of the LIMIT. It assumes matching rows are spread evenly over time, so "walk by date and stop after 50" looks cheap. For a big depot that is true. Depot 42 is small and its pending shipments are old, so the walk goes very far.

The classic trap: ORDER BY + LIMIT + a selective filter on other columns.

The fix

CREATE INDEX CONCURRENTLY shipments_depot_pending_created_idx
    ON shipments (depot_id, created_at DESC)
    WHERE status = 'pending';

A composite index that matches the filter and the sort, and partial, so it only contains the 2% of rows that are pending. Small, hot, always in memory.

Limit  (cost=0.43..61.20 rows=50 width=40) (actual time=0.041..0.198 rows=50 loops=1)
  Buffers: shared hit=54
  ->  Index Scan using shipments_depot_pending_created_idx on shipments
        (cost=0.43..4120.77 rows=3390 width=40) (actual time=0.039..0.187 rows=50 loops=1)
        Index Cond: (depot_id = 42)
        Buffers: shared hit=54
Planning Time: 0.402 ms
Execution Time: 0.231 ms

54 buffers instead of 583,000. Then I dropped my created_at index, after checking nothing else used it:

SELECT relname, indexrelname, idx_scan,
       pg_size_pretty(pg_relation_size(indexrelid)) AS size
FROM pg_stat_user_indexes
WHERE relname = 'shipments'
ORDER BY idx_scan;

Things I check every time now

1. Estimated rows vs actual rows. If they differ by 100x, the planner is working from bad information. Fix the statistics before you fix the query.
2. Correlated columns. The planner assumes depot_id and status are independent. They are not. Extended statistics help: CREATE STATISTICS shipments_depot_status (dependencies) ON depot_id, status FROM shipments; and then ANALYZE shipments;
3. Test on real data. A staging copy with evenly generated rows will happily show you the fast plan. Production has skew. Our three biggest depots have 60% of all rows.
4. EXPLAIN ANALYZE executes the query. For an UPDATE or DELETE, wrap it: BEGIN; EXPLAIN ANALYZE ...; ROLLBACK;
5. Index for the query, not for the column.

For reading big plans I paste them into explain.dalibo.com or explain.depesz.com. Both are free and both are better at this than my eyes at 18:00.