EXPLAIN ANALYZE — What to Look At, and in What Order

In a nutshell

Reading an execution plan is not skimming node names but finding the gap between the optimizer's predictions and the actual results.

Why this was needed

It is common to attach EXPLAIN ANALYZE to a slow query, stare for a long time at the numbers in parentheses filling the screen, and then jump to "I see a Seq Scan, so let's create an index". That conclusion is sometimes right, but what the plan was trying to tell you is usually a different story.

If there is no gap, the optimizer chose the best within the information it knew and the remaining bottleneck is a physical problem. If the gap is large, the optimizer calculated accurately on a wrong premise, and what needs fixing is not the query but the statistics.

How it works

EXPLAIN only makes the plan, and EXPLAIN ANALYZE actually executes. So EXPLAIN ANALYZE UPDATE ... really performs the UPDATE. When analyzing write queries, you must wrap them in a transaction and roll back.

The reading order is from the most deeply indented node. The deeper the indentation, the earlier it runs, and the parent node is completed after its children finish. And the parent's actual time is a cumulative value that includes the children's time. If you do not know this, you reach the wrong conclusion that "the join takes 131ms".

In cost=1842.00..24310.55, the first is the cost up to the first row and the second is the cost up to the last row. The unit is not milliseconds but an arbitrary unit that sets reading one sequential page to 1.0. So comparing with another query's cost is meaningless, and a criterion such as "it's dangerous above some cost" has no basis.

What you really need to look at is the two numbers within the same node.

->  Index Scan using idx_orders_status on orders o
      (cost=0.42..8.44 rows=1 width=20)
      (actual time=0.031..214.882 rows=482913 loops=1)

Expected 1 row, actual 480,000 rows. It is off by more than a factor of 40,000. The optimizer must have judged, "only 1 row will come out, so a nested loop will do", and once that premise collapsed, it ends up repeating the inner node 480,000 times. What you fix here is not a join hint but the statistics.

You must always multiply by loops. The displayed time and row count are averages per execution. If it is actual time=0.011 rows=4 loops=52310, the total time is about 575ms and the total rows are about 200,000. The number 575 is not written anywhere in the plan, so if you do not do the multiplication yourself, you pass over the bottleneck.

EXPLAIN ANALYZE without the BUFFERS option is only half. shared hit is blocks found in the buffer cache, and shared read is blocks read from outside the cache. The reason the same query takes 20ms yesterday and 900ms today is usually not the plan but the cache.

What it looks like in the field

The difference between Filter and Index Cond is important. A Filter discards rows after reading them, and an Index Cond does not read them in the first place. If there is a large number under Rows Removed by Filter, it is a sign that there is a chance to move that condition up into the index.

If Batches in a Hash Join is not 1, it means the hash table could not fit entirely in work_mem and was split to disk. In this case, raising the work_mem of that session is far more effective than creating an index. However, raising the global setting is risky, because work_mem is allocated not per connection but per sort or hash operation within a query.

What to do when the statistics are wrong

The 40,000-fold gap we saw earlier did not arise because the optimizer was lazy; it is the result of calculating accurately on a wrong premise. Then you must fix the premise.

First, check whether the statistics are stale. Right after a bulk insert or delete, the statistics differ greatly from reality. There is a mechanism that updates them automatically, but the threshold at which it runs is proportional to the table size, so on a large table a considerable amount of change has to build up before it runs. After a bulk operation, the standard practice is to refresh them by hand once.

Check whether the sample is insufficient. Statistics are built from a sample, and the default sample size is not large. For a column with very diverse values or a heavily skewed column, that sample cannot capture the real distribution. You can raise the sample target per column, and after raising it you must rebuild the statistics for it to take effect.

Check whether the columns are entangled with each other. This is the place most often missed. By default the optimizer assumes the conditions are independent of each other and multiplies the selectivities. But city = '서울' and region = '수도권' (Seoul and the metropolitan area) are not independent. Multiplying them gives a number far smaller than reality, and it trusts that small number and chooses a nested loop. If you create extended statistics that measure the correlation of several columns together, this kind of misestimate disappears.

Filtering by an expression is the same. If you wrap a column in a function, as in lower(email) = ..., there are no statistics for that expression, so the optimizer uses a fixed rough value. If you create an expression index, then along with being able to use the index, statistics for that expression are created as well.

And there are cases that cannot be fixed. These are cases where the condition depends on values in another table, or where the same query meets entirely different distributions depending on the parameters. In that case, before forcing a plan, first consider splitting the query in two. If one query is doing two entirely different things, it is unreasonable in itself to ask the optimizer to choose a single plan.

What you will do in the next lab

You will measure for yourself and save in files the difference between EXPLAIN and EXPLAIN ANALYZE, the usefulness of BUFFERS, the multiplication by loops, the Batches of a Hash, and the cases that become slower when an index is forced.