Read a query plan in 10 minutes

A slow query is a question with a hidden answer: what is the database actually doing? Postgres will tell you if you ask. EXPLAIN ANALYZE runs the query and prints the plan it followed, with timings. The trouble is that the first plan you see looks like a wall of brackets.

You don't need to understand all of it. You need four things, in order. This post walks through them on a real query in the SQL Lab, which runs PostgreSQL in your browser with a Mangrove Market sample database. Everything below is output from that database.

Set up (1 minute)

Open the SQL Lab, choose Projects, and pick the example Speed up the slow orders report. It is free. The brief: the app's "My orders" page runs this query for one customer at a time, and it is slow.

SELECT o.id, o.ordered_at, sum(i.qty * i.unit_price_cents) AS total_cents
FROM orders o
JOIN order_items i ON i.order_id = o.id
WHERE o.customer_id = 42
GROUP BY o.id, o.ordered_at
ORDER BY o.ordered_at;

The retail database has 20,000 orders and 50,000 order lines. Customer 42 has 10 orders. Run the query, then open the Plan tab. The lab shows the plan as a tree with a time bar per step and a short note on what each kind of step does. Here is the same plan as Postgres prints it, trimmed a little:

Sort  (cost=535.07..535.10 rows=10) (actual time=2.845..2.858 rows=10 loops=1)
  Sort Key: o.ordered_at
  ->  GroupAggregate  (cost=534.56..534.91 rows=10) (actual rows=10 loops=1)
        ->  Sort  (cost=534.56..534.62 rows=25) (actual rows=40 loops=1)
              ->  Nested Loop  (cost=0.29..533.97 rows=25) (actual rows=40 loops=1)
                    ->  Seq Scan on orders o  (cost=0.00..417.00 rows=10)
                          (actual time=0.153..2.122 rows=10 loops=1)
                          Filter: (customer_id = 42)
                          Rows Removed by Filter: 19990
                    ->  Index Scan using order_items_pkey on order_items i
                          (cost=0.29..11.67 rows=3) (actual rows=4 loops=10)
                          Index Cond: (order_id = o.id)
Execution Time: 3.040 ms

1. Read from the inside out (2 minutes)

A plan is a tree. The most indented lines run first and pass their rows up to the line above. So read this one bottom-up:

1. Scan orders and keep the rows for customer 42.
2. For each of those orders, look up its lines in order_items through an index (a Nested Loop: "for each row on one side, look up matches on the other").
3. Sort by order id, group the lines into one total per order, and sort by date.

2. Find where the time goes (2 minutes)

Each line has actual time=start..end in milliseconds. The end number includes everything below it. The whole query took about 3 ms; the Seq Scan on orders alone took about 2.1 ms of that. The lab's time bars make this jump out: one bar is long and the rest are thin.

One trap: when loops is more than 1, the time and rows are per loop. The index scan on order_items ran 10 times, once per order, at about 0.009 ms each. Multiply before you compare.

3. Compare estimated and actual rows (2 minutes)

Every step shows two row counts: what the planner expected (rows= in the cost brackets) and what really happened (rows= in the actual brackets). The planner picks its strategy from the estimates, so when they are badly off, it may pick the wrong one.

Here they are close. The scan expected 10 rows and got 10; the join expected 25 and got 40. Being off by less than 2× is fine. Being off by 100× is a sign the table's statistics are stale or the filter is hard to estimate, and that is a different fix (often ANALYZE on the table). The lab marks steps where the estimate and the result are far apart.

4. Look at what was thrown away (1 minute)

The single most useful line in this plan is:

Rows Removed by Filter: 19990

Postgres read every one of the 20,000 orders and threw away 19,990 of them. That is what a Seq Scan does: it reads the whole table. On 20,000 rows it takes a couple of milliseconds. On Mangrove's real orders table, with tens of millions of rows, the same plan would read all of them for every customer who opens "My orders".

Read 20,000, keep 10. That ratio is the problem, and an index is the fix.

Fix it and prove it (2 minutes)

Add an index on the column the filter uses, before the query:

CREATE INDEX orders_customer ON orders (customer_id);

Run again and open the Plan tab. The bottom-left of the tree has changed:

->  Bitmap Heap Scan on orders o  (cost=4.37..37.15 rows=10) (actual rows=10 loops=1)
      Recheck Cond: (customer_id = 42)
      ->  Bitmap Index Scan on orders_customer  (actual rows=10 loops=1)
            Index Cond: (customer_id = 42)
Execution Time: 0.955 ms

No more rows removed: the index found the 10 matching orders directly. The total estimated cost of the query fell from 535 to 155, and this run took under 1 ms instead of 3. Your timings will differ by device; the cost and the row counts will not.

The example's criteria check this for you when you press Run: the result must be exactly the same as before, orders must not be read with a Seq Scan, and the plan cost must be 200 or less. To see why it matters at scale, open the Index lab tab, press Add 200,000 orders, and time the same query with and without the index. Everything there runs in a transaction that is rolled back, so the sample data stays as it was.

The four questions, on one card

1. Where does it start? The deepest lines.
2. Where does the time go? The biggest actual time, times loops.
3. Did the planner guess right? Estimated vs actual rows.
4. What was read and thrown away? Rows Removed by Filter, and any Seq Scan on a big table.

That covers most slow queries you will meet. When it doesn't, Reading query plans and fixing slow queries goes further: join types, sorts that spill to disk, and when an index makes things worse. Indexes from the inside explains why the index works at all. Then take the free SQL Basics campaign in the lab, or, on Plus, the Fix the slow report campaign, where the checker reads your plan as well as your result.