필사 모드: EXPLAIN ANALYZEの読み方 — 実行計画から本当のボトルネックを見つける順序

• はじめに — 実行計画は見たが、どこが遅いのか分からないなら
• EXPLAINとEXPLAIN ANALYZE — 一方は予測、もう一方は実行
• 出力を読む順序 — 内側のノードから、下から上へ
• costは時間ではなく、rowsの乖離こそが本当のシグナル
• loopsは掛け算される — actual timeは1回あたりの平均です
• Seq Scanに罪はない、そして三つの結合が分かれる地点
• BUFFERSとRows Removed by Filter — 残る二つの手がかり
• おわりに — ノード名ではなく乖離を見る

はじめに — 実行計画は見たが、どこが遅いのか分からないなら

遅いクエリに出会うと、たいていはEXPLAIN ANALYZEを付けてみます。そして画面いっぱいのインデントと括弧の中の数字をしばらく眺めたあげく、結局「Seq Scanがあるからインデックスを作ろう」という結論に飛びます。その結論が正しいこともあります。しかし実行計画が教えようとしていたのは、たいてい別の話です。

実行計画を読むとは、ノード名をざっと眺めることではありません。オプティマイザの予測と実際の結果との乖離を見つける作業です。乖離がなければ、オプティマイザは自分が知っている情報の範囲で最善を選んだということであり、残ったボトルネックは物理的な問題です。乖離が大きければ、オプティマイザは誤った前提の上で正確に計算したということであり、手を入れるべき対象はクエリではなく統計情報です。

この記事では実際の出力を一行ずつ解剖しながら、どの数字をどの順序で見るべきかを整理します。PostgreSQLを基準にし、MySQLで異なる点はその都度指摘します。

EXPLAINとEXPLAIN ANALYZE — 一方は予測、もう一方は実行

この二つのコマンドは名前が似ているだけで、やることが違います。

-- 計画を立てるだけで終わり。クエリは実行されない。
EXPLAIN
SELECT * FROM orders WHERE user_id = 42;

-- 実際に実行したうえで、計画に実測値を重ねて見せる。
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders WHERE user_id = 42;

EXPLAINだけを付けると、オプティマイザが統計情報をもとに立てた計画と推定値だけが出ます。速くて安全ですが、その推定が正しいかどうかは分かりません。ANALYZEオプションを付けるとクエリを実際に実行し、各ノードが実際に何行を返したか、どれくらいかかったかを併せて出力します。

ここで事故がよく起きます。EXPLAIN ANALYZE UPDATE ...は本当にUPDATEを実行します。書き込みクエリを分析するときは、必ずトランザクションで囲んでロールバックしなければなりません。

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

オプションはほかにもいくつかありますが、実務で有用な組み合わせは事実上決まっています。

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

• BUFFERS — ノードごとのブロック読み取り統計です。これがないとキャッシュの問題が見えません。
• VERBOSE — 出力カラムの一覧とスキーマ修飾名です。結合が複雑なときに役立ちます。
• SETTINGS — デフォルト値から外れたプランナパラメータを表示します。他人が作った環境を調査するときに決定的です。
• FORMAT JSON — ツールに入れてパースするときだけ使い、人間が読むときはTEXTのほうが良いです。

MySQLでは8.0.18からEXPLAIN ANALYZEが入り、それ以前はEXPLAIN FORMAT=TREEやSHOW WARNINGSでオプティマイザが書き換えたクエリを確認する方式でした。出力の形は違いますが、読む原則は同じです。

出力を読む順序 — 内側のノードから、下から上へ

実行計画はツリーです。テキストで出力されるとき、インデントが深いほどツリーの内側、つまり先に実行されるノードです。上から下へ読むと、逆に読むことになります。

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

読む順序はこうです。

1. 最も深くインデントされたSeq Scan on users uが先に実行され、18402行を作ります。
2. その結果がHashノードへ上がり、メモリにハッシュテーブルとして展開されます。
3. 次にSeq Scan on orders oが91188行を流します。
4. 最上段のHash Joinが両者を結合して17903行を出します。

つまり兄弟ノードが複数あるときは上側が先で、親ノードは子が終わったあとに完成します。ツリー構造に慣れると、計画を見た瞬間に「データがどこで作られ、どこへ流れるのか」が目に入ってきます。

一つ注意すべき点があります。親ノードのactual timeは子の時間を含んだ累積値です。上の出力でHash Joinの131msのうち92msはordersのスキャンが使った時間です。特定のノードが純粋に使った時間を知るには、子の時間を引かなければなりません。この事実を知らないと、「結合に131msもかかっている」という誤った結論にたどり着きます。

costは時間ではなく、rowsの乖離こそが本当のシグナル

cost=1842.00..24310.55の前の値は最初の行を返すまでのコスト、後ろの値は最後の行までの総コストです。問題はこの数字の単位です。ミリ秒ではありません。秒でもありません。シーケンシャルなページ1枚を読むコストを1.0と置いた任意の単位です。

-- コスト単位の基準値
SHOW seq_page_cost;      -- 1.0  (基準)
SHOW random_page_cost;   -- 4.0  (デフォルト値。SSDなら1.1前後が現実的)
SHOW cpu_tuple_cost;     -- 0.01
SHOW cpu_operator_cost;  -- 0.0025

ですからcost 24310は24秒を意味しません。この値は同じクエリの複数の計画候補を互いに比較するためのスコアにすぎず、別のクエリのcostと比較することも事実上意味がありません。「costが10000を超えたら危険だ」といった基準を立てる助言をときどき見かけますが、根拠がありません。

本当に見るべきなのは、同じノードの中にある二つのrows=です。

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

予想92300、実際91188。誤差1.2パーセントなら統計情報は健全だということです。逆に次のような出力に出会うと話が変わります。

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

予想1行、実際482913行。4万倍以上外れています。オプティマイザは「1行しか出ないのだからNested Loopでつなげばよい」と判断したはずで、その前提が崩れた結果、内側のノードを48万回繰り返すことになります。このとき直すべきなのは結合ヒントではなく統計情報です。

-- 一次処方: 統計情報の更新
ANALYZE orders;

-- それでもずれるなら特定カラムのヒストグラム精度を上げる
ALTER TABLE orders ALTER COLUMN status SET STATISTICS 1000;
ANALYZE orders;

-- カラム間の相関のせいで外れる場合 (例: 市区町村と郵便番号)
CREATE STATISTICS stat_orders_geo (dependencies, ndistinct)
  ON city, postal_code FROM orders;
ANALYZE orders;

最後の拡張統計は意外とよく必要になります。オプティマイザは基本的に条件どうしが互いに独立だと仮定して選択度を掛け合わせます。実際には相関のあるカラムの組が多く、その場合の推定値は実際よりはるかに小さく出ます。

loopsは掛け算される — actual timeは1回あたりの平均です

最も多い誤読がここから生まれます。

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

actual time=0.008..0.011を見て「0.011ミリ秒なら無視してよい」と流してはいけません。括弧の中の時間と行数はどちらも1回の実行を基準にした平均値です。実際の合計はloopsを掛けて初めて出ます。

• 総所要時間: 0.011ms かける 52310回 = 約575ms
• 総返却行数: 4行 かける 52310回 = 約209,240行

クエリ全体が700msなら、このノード一つで80パーセントを使った計算になります。計画のどこにも「575」という数字は書かれていないので、掛け算を自分でやってみないとボトルネックを見逃します。

同じ理由で、Nested Loopの内側のノードは常にloopsを先に確認すべきです。loopsが数万回を超えるなら、外側の行数推定が外れている可能性が高いです。結合順序を変えるか、インデックスを追加するかはその次の問題です。

並列クエリではもう一段あります。Gatherの下のノードのloopsはワーカー数を反映し、Workers Launchedが要求した数より少ないことがあります。

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

4個を計画したのに2個しか立ち上がらなかったのならmax_parallel_workersがすでに使い切られている状態ということで、その分だけ予想より遅くなります。ベンチマーク結果が再現しないなら、まずこの行を見てください。

Seq Scanに罪はない、そして三つの結合が分かれる地点

「Seq Scanが見えたらインデックスを作れ」という助言は半分しか当たっていません。シーケンシャルスキャンがインデックススキャンより速い状況は確かに存在します。

第一に、テーブルが小さいときです。数百行のコードテーブルは丸ごと読んでもページ数枚です。インデックスを使うとインデックスページを読んでヒープへ再びランダムアクセスしなければならないので、かえって損です。

第二に、選択度が低いときです。条件がテーブルのかなりの割合を通すなら、インデックスは不利です。インデックススキャンはマッチする行ごとにヒープページをランダムに訪れますが、訪れる行が多いと結局テーブル全体をランダムな順序で読むのと同じことになります。シーケンシャル読み取りはディスクとプリフェッチにはるかに親和的です。おおむね全体の5から10パーセントを超えるとシーケンシャルスキャンが勝ち始め、正確な境界はrandom_page_costと物理的な整列度が決めます。

-- 物理的な整列度の確認: 1.0に近いほどインデックス順とヒープ順が一致する
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

user_idの相関度が0に近いということは、同じユーザーの注文がテーブル全体に散らばっているという意味です。こうしたカラムは同じ選択度でもインデックスの利得がはるかに小さくなります。オプティマイザはこの値をすでに知っていて計算に入れています。

結合アルゴリズムも同様に、「何が良いか」ではなく「いつ何が正しいか」の問題です。

Hash JoinでBatches: 1でないなら、ハッシュテーブルがwork_memに収まらずディスクへ分割されたという意味です。

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

Batches 32は32回に分けて処理したという意味で、その間に一時ファイルの入出力が発生します。この場合はインデックスを作るより、そのセッションのwork_memを上げるほうがはるかに効果的です。

SET LOCAL work_mem = '256MB';

グローバル設定を上げるのは危険です。work_memはコネクション単位ではなくクエリ内のソートやハッシュ演算1つあたりに割り当てられるため、同時実行クエリが多いとメモリが一瞬で何倍にも膨らみます。重いバッチクエリの直前にセッション単位でだけ上げるのが安全です。

BUFFERSとRows Removed by Filter — 残る二つの手がかり

BUFFERSのないEXPLAIN ANALYZEは片手落ちです。同じクエリが昨日は20ms、今日は900msという理由は、たいてい計画ではなくキャッシュにあります。

->  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はバッファキャッシュからすぐ見つかったブロック、shared readはキャッシュになくてOSやディスクまで降りたブロックです。上の出力は4万ブロック、約320MBをキャッシュの外から読んだという意味です。2回目の実行でreadが激減し時間が短くなるなら、計画には問題がなくワーキングセットがshared_buffersより大きいという話です。このときインデックスをさらに作るのは答えではありません。

dirtiedとwrittenも注目すべき値です。SELECTなのにdirtiedが大きいなら、ヒントビットの更新や事後の後始末が起きているシグナルで、大量ロードの直後によく見られます。

二つ目の手がかりはRows Removed by Filterです。先ほどの例に戻ってみましょう。

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

80万行を読んで71万行を捨てました。必要な行は全体の11パーセントだけです。この程度の選択度ならインデックスが勝つ余地は十分あります。

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

133msから29msに減り、Rows Removed by Filterの行が消えてIndex Condに変わりました。この違いは重要です。Filterは行を読んだあとに捨てるもので、Index Condはそもそも読まないものです。計画でFilterの下に大きな数字を見つけたら、その条件をインデックスに載せられるかをまず検討してください。

逆にこういう場合もあります。

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

インデックスで1万行まで絞りましたが、そのうち112行しか残りませんでした。この場合は複合インデックスか部分インデックスが答えです。

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

おわりに — ノード名ではなく乖離を見る

実行計画を見るときは、順序を一つだけ覚えてください。

1. Execution TimeとPlanning Timeをまず見ます。計画時間が実行時間を超えるなら、問題は別のところにあります。
2. 各ノードで予想rowsと実際のrowsを比較します。一桁以上の倍率で開いた最も内側のノードが犯人です。
3. loopsが1でないノードは掛け算をして実際の寄与時間を計算します。
4. Rows Removed by Filterが大きいノードを探し、インデックスの余地を確認します。
5. Buffersのreadの比率で、これが計画の問題かキャッシュの問題かを切り分けます。

Seq ScanやNested Loopといったノード名そのものは、良し悪しを教えてはくれません。オプティマイザは自分が持っている統計情報の範囲ではほぼ常に合理的に判断します。ですから計画がおかしく見えるなら、投げるべき問いは「なぜオプティマイザは愚かなのか」ではなく、自分がオプティマイザに何を間違って伝えたのかです。