Split View: EXPLAIN ANALYZE 읽는 법 — 실행 계획에서 진짜 병목을 찾는 순서

How to Read EXPLAIN ANALYZE — Finding the Real Bottleneck in a Query Plan

• Introduction — When You Have Read the Query Plan but Still Cannot Tell What Is Slow
• EXPLAIN and EXPLAIN ANALYZE — One Predicts, One Executes
• The Order to Read Output — Innermost Node First, Bottom to Top
• Cost Is Not Time, and the Gap in rows Is the Real Signal
• loops Multiply — actual time Is a Per-Execution Average
• Seq Scan Is Not Guilty, and Where the Three Joins Diverge
• BUFFERS and Rows Removed by Filter — The Remaining Two Clues
• Closing — Look at the Gap, Not the Node Names

Introduction — When You Have Read the Query Plan but Still Cannot Tell What Is Slow

When you hit a slow query, you probably attach EXPLAIN ANALYZE. Then you stare at a screen full of indentation and parenthesised numbers for a while, and eventually jump to the conclusion: "there is a Seq Scan, so let us build an index." Sometimes that conclusion is right. But what the query plan was trying to tell you is usually a different story.

Reading a query plan is not about skimming node names. It is the work of finding the gap between what the optimizer predicted and what actually happened. If there is no gap, the optimizer picked the best option available given what it knew, and whatever bottleneck remains is a physical problem. If the gap is large, the optimizer calculated precisely on top of a false premise, and the thing that needs fixing is not the query but the statistics.

This article dissects real output line by line and lays out which numbers to look at in which order. It uses PostgreSQL as the baseline, and points out where MySQL diverges as we go.

EXPLAIN and EXPLAIN ANALYZE — One Predicts, One Executes

The two commands only sound alike; they do different things.

-- Only builds the plan and stops. The query is not executed.
EXPLAIN
SELECT * FROM orders WHERE user_id = 42;

-- Actually executes, then overlays measured values on the plan.
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders WHERE user_id = 42;

With EXPLAIN alone you get the plan the optimizer built from statistics, plus its estimates. That is fast and safe, but you cannot tell whether those estimates are correct. Add the ANALYZE option and the query is actually executed, and the output also reports how many rows each node really produced and how long it took.

Accidents happen here all the time. EXPLAIN ANALYZE UPDATE ... really performs the UPDATE. When you analyze a write query, you must wrap it in a transaction and roll it back.

BEGIN;
EXPLAIN (ANALYZE, BUFFERS)
UPDATE orders SET status = 'shipped' WHERE id = 1001;
ROLLBACK;

There are a few more options, and the combination that is useful in practice is essentially fixed.

EXPLAIN (ANALYZE, BUFFERS, VERBOSE, SETTINGS, FORMAT TEXT)
SELECT ...;

• BUFFERS — per-node block read statistics. Without it you cannot see caching problems.
• VERBOSE — the output column list and schema-qualified names. Useful when joins get complicated.
• SETTINGS — shows planner parameters that deviate from their defaults. Decisive when you are investigating an environment somebody else built.
• FORMAT JSON — use it only when feeding a tool that parses it; for human reading, TEXT is better.

MySQL gained EXPLAIN ANALYZE in 8.0.18; before that you used EXPLAIN FORMAT=TREE or SHOW WARNINGS to see the query the optimizer had rewritten. The output shape differs, but the reading principles are the same.

The Order to Read Output — Innermost Node First, Bottom to Top

A query plan is a tree. When printed as text, the deeper the indentation, the further inside the tree the node sits — that is, the earlier it executes. Reading top to bottom means reading it backwards.

EXPLAIN (ANALYZE, BUFFERS)
SELECT u.name, o.id, o.total
FROM users u
JOIN orders o ON o.user_id = u.id
WHERE u.country = 'KR'
  AND o.created_at >= '2026-06-01';

Hash Join  (cost=1842.00..24310.55 rows=18420 width=44)
           (actual time=8.412..131.207 rows=17903 loops=1)
  Hash Cond: (o.user_id = u.id)
  Buffers: shared hit=4021 read=9877
  ->  Seq Scan on orders o  (cost=0.00..20117.00 rows=92300 width=20)
                            (actual time=0.019..92.441 rows=91188 loops=1)
        Filter: (created_at >= '2026-06-01 00:00:00'::timestamp)
        Rows Removed by Filter: 708812
        Buffers: shared hit=3110 read=9004
  ->  Hash  (cost=1610.00..1610.00 rows=18560 width=28)
            (actual time=8.287..8.288 rows=18402 loops=1)
        Buckets: 32768  Batches: 1  Memory Usage: 1408kB
        Buffers: shared hit=911 read=873
        ->  Seq Scan on users u  (cost=0.00..1610.00 rows=18560 width=28)
                                 (actual time=0.011..5.902 rows=18402 loops=1)
              Filter: (country = 'KR'::text)
              Rows Removed by Filter: 61598
              Buffers: shared hit=911 read=873
Planning Time: 0.184 ms
Execution Time: 133.902 ms

The reading order goes like this.

1. The most deeply indented Seq Scan on users u runs first and produces 18402 rows.
2. That result rises into the Hash node and is loaded into memory as a hash table.
3. Then Seq Scan on orders o streams 91188 rows through.
4. The topmost Hash Join combines the two and emits 17903 rows.

So when there are several sibling nodes, the upper one comes first, and a parent node is completed only after its children finish. Once you get used to the tree structure, you can see at a glance where the data is produced and where it flows.

There is one thing to watch out for. A parent node actual time is a cumulative value that includes the time of its children. In the output above, 92ms of the 131ms in the Hash Join was spent by the orders scan. To know the time a specific node spent purely on its own, you have to subtract the time of its children. Without knowing this you arrive at the wrong conclusion that "the join takes a whole 131ms."

Cost Is Not Time, and the Gap in rows Is the Real Signal

In cost=1842.00..24310.55, the first value is the cost to produce the first row and the second is the total cost through the last row. The problem is the unit of these numbers. It is not milliseconds. It is not seconds either. It is an arbitrary unit that puts the cost of reading one sequential page at 1.0.

-- The reference values for the cost unit
SHOW seq_page_cost;      -- 1.0  (baseline)
SHOW random_page_cost;   -- 4.0  (default; on SSD, something near 1.1 is realistic)
SHOW cpu_tuple_cost;     -- 0.01
SHOW cpu_operator_cost;  -- 0.0025

So a cost of 24310 does not mean 24 seconds. This value is merely a score for comparing several candidate plans for the same query against each other, and comparing it with the cost of a different query is effectively meaningless. You often see advice that sets a threshold like "a cost above 10000 is dangerous," but there is no basis for it.

What you really should look at is the two rows= values inside the same node.

->  Seq Scan on orders o  (cost=... rows=92300 ...) (actual ... rows=91188 loops=1)

Estimated 92300, actual 91188. An error of 1.2 percent means the statistics are healthy. Meet output like the following and the story changes.

->  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)

Estimated 1 row, actual 482913. Off by more than forty thousand times. The optimizer presumably decided "only 1 row will come out, so a Nested Loop will do," and when that premise collapses it ends up repeating the inner node 480 thousand times. What needs fixing here is not a join hint but the statistics.

-- First prescription: refresh the statistics
ANALYZE orders;

-- If it is still off, raise the histogram precision on a specific column
ALTER TABLE orders ALTER COLUMN status SET STATISTICS 1000;
ANALYZE orders;

-- When the miss comes from correlation between columns (for example, city and postal code)
CREATE STATISTICS stat_orders_geo (dependencies, ndistinct)
  ON city, postal_code FROM orders;
ANALYZE orders;

That last extended statistic is needed surprisingly often. By default the optimizer assumes the conditions are independent of one another and multiplies their selectivity. In reality many column pairs are correlated, and in those cases the estimate comes out far smaller than the truth.

loops Multiply — actual time Is a Per-Execution Average

This is where the most misreadings happen.

->  Index Scan using idx_order_items_order_id on order_items i
      (cost=0.43..3.21 rows=4 width=16)
      (actual time=0.008..0.011 rows=4 loops=52310)

Do not look at actual time=0.008..0.011 and move on thinking "0.011 milliseconds, negligible." The time and row count inside the parentheses are both averages per single execution. To get the real total you have to multiply by loops.

• Total elapsed time: 0.011ms times 52310 executions = about 575ms
• Total rows returned: 4 rows times 52310 executions = about 209,240 rows

If the whole query is 700ms, this single node consumed 80 percent of it. Because the number "575" is written nowhere in the plan, you will walk right past the bottleneck unless you do the multiplication yourself.

For the same reason you should always check loops first on the inner node of a Nested Loop. If loops runs into the tens of thousands, there is a good chance the outer row estimate is wrong. Whether to change the join order or add an index is the next question.

With parallel queries there is one more layer. The loops of a node under Gather reflect the worker count, and Workers Launched may be fewer than requested.

Gather  (cost=1000.00..38210.13 rows=210 width=8)
        (actual time=0.412..312.884 rows=198 loops=1)
  Workers Planned: 4
  Workers Launched: 2

If 4 were planned but only 2 came up, max_parallel_workers was already exhausted, and things are correspondingly slower than expected. If a benchmark result will not reproduce, look at this line first.

Seq Scan Is Not Guilty, and Where the Three Joins Diverge

The advice "if you see a Seq Scan, build an index" is only half right. Situations where a sequential scan beats an index scan definitely exist.

First, when the table is small. A code table of a few hundred rows is only a handful of pages even if you read the whole thing. Going through an index means reading index pages and then randomly accessing the heap again, which is a net loss.

Second, when selectivity is low. If a condition lets a substantial fraction of the table through, an index is at a disadvantage. An index scan visits a heap page randomly for every matching row, and when there are many rows to visit you end up reading the entire table in random order. Sequential reads are far friendlier to disks and prefetching. Roughly past 5 to 10 percent of the whole, sequential scan starts winning, and the exact boundary is determined by random_page_cost and physical ordering.

-- Check physical ordering: the closer to 1.0, the more index order matches heap order
SELECT attname, correlation
FROM pg_stats
WHERE tablename = 'orders' AND attname IN ('id', 'created_at', 'user_id');

  attname    | correlation
-------------+-------------
 id          |    0.999812
 created_at  |    0.998304
 user_id     |    0.003911

A correlation near 0 for user_id means the orders of the same user are scattered across the whole table. Such a column yields a far smaller index benefit at the same selectivity. The optimizer already knows this value and factors it into its calculation.

Join algorithms are likewise not a question of "which is good" but of "when is which right."

In a Hash Join, anything other than Batches: 1 means the hash table did not fit in work_mem and was split out to disk.

->  Hash  (actual time=412.331..412.332 rows=1840221 loops=1)
      Buckets: 65536  Batches: 32  Memory Usage: 4097kB

Batches 32 means the work was split into 32 passes, with temporary file I/O in between. In this case raising work_mem for that session is far more effective than creating an index.

SET LOCAL work_mem = '256MB';

Raising the global setting is dangerous. work_mem is allocated not per connection but per sort or hash operation inside a query, so when many queries run concurrently memory balloons several times over in an instant. Raising it only at the session level right before a heavy batch query is the safe approach.

BUFFERS and Rows Removed by Filter — The Remaining Two Clues

An EXPLAIN ANALYZE without BUFFERS is half a picture. The reason the same query took 20ms yesterday and 900ms today is usually not the plan but the cache.

->  Bitmap Heap Scan on events e  (actual time=44.201..811.339 rows=214402 loops=1)
      Recheck Cond: (tenant_id = 77)
      Heap Blocks: exact=41883
      Buffers: shared hit=1204 read=40801

shared hit is blocks found directly in the buffer cache; shared read is blocks that were not cached and had to go down to the operating system or disk. The output above means 40 thousand blocks, roughly 320MB, were read from outside the cache. If on a second execution read drops sharply and the time shortens, the plan is fine and the story is that the working set is larger than shared_buffers. Creating more indexes is not the answer here.

dirtied and written are also worth watching. If it is a SELECT and dirtied is large, that signals hint bit updates or after-the-fact cleanup happening, which is commonly seen right after a bulk load.

The second clue is Rows Removed by Filter. Let us go back to the earlier example.

->  Seq Scan on orders o  (actual time=0.019..92.441 rows=91188 loops=1)
      Filter: (created_at >= '2026-06-01 00:00:00'::timestamp)
      Rows Removed by Filter: 708812

It read 800 thousand rows and threw away 710 thousand. Only 11 percent of the total was needed. At this level of selectivity there is plenty of room for an index to win.

CREATE INDEX CONCURRENTLY idx_orders_created_at
  ON orders (created_at);

ANALYZE orders;

Hash Join  (cost=1842.00..9714.22 rows=18420 width=44)
           (actual time=7.902..28.113 rows=17903 loops=1)
  Hash Cond: (o.user_id = u.id)
  Buffers: shared hit=6188 read=1204
  ->  Index Scan using idx_orders_created_at on orders o
        (cost=0.43..5901.10 rows=92300 width=20)
        (actual time=0.028..14.882 rows=91188 loops=1)
        Index Cond: (created_at >= '2026-06-01 00:00:00'::timestamp)
  ...
Execution Time: 29.440 ms

It went from 133ms to 29ms, the Rows Removed by Filter line disappeared, and it turned into Index Cond. This difference matters. Filter throws rows away after reading them; Index Cond never reads them in the first place. If you find a large number under Filter in a plan, first examine whether that condition can be lifted into an index.

There is also the opposite case.

->  Index Scan using idx_orders_user_id on orders o
      (actual time=0.041..38.221 rows=112 loops=1)
      Index Cond: (user_id = 42)
      Filter: (status = 'pending')
      Rows Removed by Filter: 9884

The index narrowed things to 10 thousand rows, but only 112 of them survived. Here a composite index or a partial index is the answer.

CREATE INDEX CONCURRENTLY idx_orders_user_pending
  ON orders (user_id)
  WHERE status = 'pending';

Closing — Look at the Gap, Not the Node Names

When you look at a query plan, remember just one order.

1. Look at Execution Time and Planning Time first. If planning time exceeds execution time, the problem lies elsewhere.
2. Compare estimated rows against actual rows at each node. The innermost node where they diverge by an order of magnitude or more is the culprit.
3. For nodes where loops is not 1, do the multiplication to compute the real contributed time.
4. Find nodes with a large Rows Removed by Filter and check for an index opportunity.
5. Use the read ratio in Buffers to decide whether this is a plan problem or a cache problem.

Node names like Seq Scan or Nested Loop do not by themselves tell you good from bad. Within the statistics it holds, the optimizer almost always judges reasonably. So when a plan looks strange, the question to ask is not why the optimizer is stupid, but what did I tell the optimizer that was wrong.