8409ms → 15ms: PostgreSQL の EXPLAIN ANALYZE で 555倍の高速化を見つけた話

ある日、こんなエラーが出ました。 ActiveRecord::QueryCanceled: PG::QueryCanceled:ERROR: canceling statement due to statement timeout

エラーの発生源となったメソッドは、月間の対話数をカウントしてリミットに達したかチェックするだけのもの。データ量も多くないはずなのに、なぜ timeout に? 本記事ではこのケースを題材に、EXPLAIN ANALYZEの読み方を実践的に紹介します。

ステップ 1: 実行されている SQL を取得

APM ツール（Datadog 等）で normalize された SQL を取得:

SELECT COUNT(*) FROM conversations
  INNER JOIN room
    ON room.id = conversations.room_id
  INNER JOIN public.chat
    ON public.chat.chat_room_id = room.chat_room_id
  WHERE public.chat.tenant_id IN (
    SELECT id FROM public.tenants WHERE schema = $1
  )
  AND conversations.sent_at BETWEEN $2 AND $3
  AND conversations.conversation_type IN ($4, ..., $11);

ステップ 2: データ規模をざっくり把握

SELECT COUNT(*) FROM conversations
  WHERE sent_at BETWEEN '2026-05-01' AND '2026-06-01'
    AND conversation_type IN (1,2,3,6,7,9,10,99);
  -- 21087

21087 件。本来ミリ秒で返るはず。問題はデータ量ではなく実行計画と確信できます。

ステップ 3: EXPLAIN ANALYZE で現状を見る

SET search_path TO "<tenant_schema>", public;
SET statement_timeout = '5min';       -- これがないと EXPLAIN 自体がtimeout する

EXPLAIN (ANALYZE, BUFFERS, VERBOSE)
  SELECT COUNT(*) FROM conversations ...（省略）

結果（要約）:

Aggregate (actual time=8408.974..8408.975)
    Buffers: shared hit=70199 read=6549
    I/O Timings: read=8255.453 ms

    -> Nested Loop (rows=21087, loops=1)
         -> Nested Loop (rows=10707, loops=1)
              -> Nested Loop (rows=4, loops=1)
                   [tenants & chat の Index Scan]
              -> Index Scan on room
                   (rows=2677, loops=4)
         -> Index Scan on conversations
              (rows=2, loops=10707)              ★ 1万ループ
              Filter: sent_at BETWEEN ... AND conversation_type IN ...
              Rows Removed by Filter: 9

  Execution Time: 8409.036 ms

8.4 秒。これは確かに timeout します。

ステップ 4: 実行計画を日本語で読む

tenants から現在のテナント ID を取得（1 件）
そのテナントの chat を取得（4 件）
4 つの chat をループしながら、各 chat の room を全部取得（10707 件）
10707 件の room をループしながら、各 room の conversation を index で引いて、sent_at と conversation_type で絞り込み

問題はステップ 4。10707 回の独立した Index Scan、毎回ほぼ 2 行しか残らないのに 11 行ほどスキャンして 9 行捨てる。累計 70000+ ページ、うち 6549ページはディスクから読まされ 8.25 秒の I/O 時間が発生。

根本原因は rows=3 という見積もり (実測 210877000 倍ズレ)。これが planner に「Nested Loop で十分速い」と誤解させ、本来効くはずの (sent_at, conversation_type)複合インデックスが選ばれませんでした。

ステップ 5: JOIN を外してみる

このアプリは schema-per-tenant のマルチテナント。conversations 自体がテナント schema 内にあるので、chat.tenant_id への JOIN は冗長です。

  SELECT COUNT(*) FROM conversations
  WHERE sent_at BETWEEN $1 AND $2
    AND conversation_type IN ($3, ..., $10);

  Aggregate (actual time=15.124..15.125)
    Buffers: shared hit=4713      ← ディスク read ゼロ
    -> Index Only Scan using idx_on_sent_at_conversation_type
         (rows=21087, loops=1)

  Execution Time: 15.154 ms

15 ms — 555 倍の高速化。

まとめ

「シンプルに見えるのに遅い SQL」の正体は、しばしば設計上の前提と planner の見立てのミスマッチです。今回も schema 隔離による暗黙の絞り込みを、コード側の防御的JOIN が打ち消していました。 EXPLAIN ANALYZE は索引情報以上に、設計の認識ズレを可視化するレンズでもあります。