戻る

バックエンド屋の性能最適化 実戦（4）：Slow Query でボトルネックを見つける

公開日:  at  08:00 午前
修正を提案する

前置き

性能最適化の道のりでは、アプリ自体の性能問題に加えて、データベースも避けて通れないテーマです。今どきは多くのサービスが K8s で水平スケールして性能を上げられますが、データベースはたいてい単一構成のまま残ります。そのぶんデータベースにかかる負荷は以前よりも大きくなり、データベースをどう最適化するかも重要なテーマになっています。以下では、よく使われるデータベースの性能トラブルシューティングツール——Slow Query Log と EXPLAIN 構文を紹介します。

Slow Query Log

Slow Query とは何でしょうか？ 簡単に言えば SQL の機能の一つで、実行時間がある閾値を超えたクエリを記録し、エンジニアがあとから確認しやすくしてくれるものです。あるクエリが遅いかどうかを調べたいとき、まず最初にチェックすべきなのが Slow Query です。

現在の slow query 設定は、次のコマンドで確認できます。

SHOW log_min_duration_statement;

デフォルト値は -1 で、これは機能が無効になっていることを意味します。本番環境では有効にしておくことをお勧めします。設定方法は以下の通りです。ここでは、実行に 100 ミリ秒を超えるクエリを検出したいとします。

ALTER SYSTEM SET log_min_duration_statement = 100;
SELECT pg_reload_conf();

注意点として、記録設定を終えたあとは別途 pg_reload_conf() を呼び出す必要があり、これによって設定がすぐに反映されます。また、この操作は DB を再起動しなくてもその場で有効になります。

設定が済んだら、実際にクエリを試してみましょう。例えば、以下のクエリを実行します。これは ticket というテーブルで、あらかじめ 1.5GB を超えるダミーデータを入れて低速クエリをシミュレートしています。

SELECT count(*) FROM ticket WHERE user_id = 200;

クエリを実行すると、PostgreSQL のコンテナログに記録が見つかります。

...
2026-07-13 02:49:11.796 UTC [302]: LOG:  duration: 245.075 ms  statement: SELECT count(*) FROM ticket WHERE user_id = 200;
2026-07-13 02:49:13.350 UTC [302]: LOG:  duration: 272.983 ms  statement: SELECT count(*) FROM ticket WHERE user_id = 200;
...

見ての通り、この「特定ユーザーのチケットを検索する」処理には 200 ミリ秒以上かかっており、これは私たちが設定した 100 ミリ秒の基準を超えているため、こうして記録が見つかるわけです。

さて、遅いことは分かりました。しかし、どこが遅いのでしょうか？ ここで次のツール、EXPLAIN 構文の出番です。

EXPLAIN は SQL の特殊な構文で、このクエリを解析して詳細な情報を提供してくれます。実際にクエリを先に実行するわけではなく、事前の解析だけを行います。

EXPLAIN SELECT count(*) FROM ticket WHERE user_id = 200;

結果は以下の通りです。

Finalize Aggregate  (cost=179475.17..179475.18 rows=1 width=8)
  ->  Gather  (cost=179474.96..179475.17 rows=2 width=8)
        Workers Planned: 2
        ->  Partial Aggregate  (cost=178474.96..178474.97 rows=1 width=8)
              ->  Parallel Seq Scan on ticket  (cost=0.00..178455.61 rows=7737 width=0)
                    Filter: (user_id = 200)
JIT:
  Functions: 6
  Options: Inlining false, Optimization false, Expressions true, Deforming true

初めてこの表を見ると少し目眩がするかもしれません。まずはいくつかの重要な項目を押さえましょう。

ここで最も重要なのが Parallel Seq Scan on ticket です。Seq Scan は Full Table Scan(全表スキャン) のことで、データベースがテーブル全体を1行ずつ舐めるようにして user_id = 200 を探していることを意味します。これがたいてい性能低下の元凶です——今回のケースでは user_id という外部キーにインデックスが貼られていないことが原因です。ただし、純粋な EXPLAIN はあくまで「見積もり」なので、ANALYZE を使って実際に一度実行し、これを検証してみましょう。

EXPLAIN (ANALYZE, BUFFERS) SELECT count(*) FROM ticket WHERE user_id = 200;

結果：

Finalize Aggregate  (cost=179475.17..179475.18 rows=1 width=8) (actual time=290.771..295.209 rows=1.00 loops=1)
  Buffers: shared hit=9916 read=120975
  ->  Gather  (cost=179474.96..179475.17 rows=2 width=8) (actual time=290.640..295.199 rows=3.00 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        Buffers: shared hit=9916 read=120975
        ->  Partial Aggregate  (cost=178474.96..178474.97 rows=1 width=8) (actual time=271.163..271.164 rows=1.00 loops=3)
              Buffers: shared hit=9916 read=120975
              ->  Parallel Seq Scan on ticket  (cost=0.00..178455.61 rows=7737 width=0) (actual time=11.709..270.432 rows=5624.00 loops=3)
                    Filter: (user_id = 200)
                    Rows Removed by Filter: 3038511
                    Buffers: shared hit=9916 read=120975
Planning Time: 0.080 ms
JIT:
  Functions: 14
  Options: Inlining false, Optimization false, Expressions true, Deforming true
  Timing: Generation 2.172 ms (Deform 0.667 ms), Inlining 0.000 ms, Optimization 1.948 ms, Emission 28.265 ms, Total 32.385 ms
Execution Time: 295.586 ms

ANALYZE を付けると、PostgreSQL は実際にこのクエリを一度実行するため、actual time(実際の所要時間)が追加されます。さらに BUFFERS を付けると、データがメモリから来たのかディスクから来たのかが分かります。この表の中で「どこが遅いか」を最も雄弁に語っている数字が2つあります。

約300ミリ秒のレイテンシは非常に高い数値です。ここでインデックスを追加してクエリ速度を最適化してみましょう。

CREATE INDEX CONCURRENTLY idx_ticket_user_id ON ticket(user_id);

再度 ANALYZE を実行した結果は以下の通りです。

Aggregate  (cost=435.81..435.82 rows=1 width=8) (actual time=1.882..1.883 rows=1.00 loops=1)
  Buffers: shared hit=22
  ->  Index Only Scan using idx_ticket_user_id on ticket  (cost=0.43..389.39 rows=18569 width=0) (actual time=0.019..1.036 rows=16872.00 loops=1)
        Index Cond: (user_id = 200)
        Heap Fetches: 0
        Index Searches: 1
        Buffers: shared hit=22
Planning:
  Buffers: shared hit=12 read=1
Planning Time: 0.374 ms
Execution Time: 1.935 ms

前後2つの結果の重要な数字を並べてみると、インパクトは一目瞭然です。

指標インデックス追加前インデックス追加後
スキャン方式Parallel Seq Scan(全表スキャン)Index Only Scan(インデックス経由)
Buffers read(ディスク読み取り)1209750(shared hit=22)
Rows Removed by Filter30385110
Execution Time295.586 ms1.935 ms

実行時間は約300ミリ秒から1.9ミリ秒まで下がり、およそ150倍高速化しました。さらに重要なのは、もはやテーブル全体をスキャンする必要も、ディスクから12万ブロックを読みに行く必要もなく、インデックスを経由して直接答えにたどり着けるという点です。これこそが EXPLAIN を読み解けることがこれほど重要な理由です——「どこが遅いか」を直接教えてくれるので、初めてどんな処方箋を出すべきか分かるのです。

以上が Slow Query + EXPLAIN を組み合わせたシンプルな活用例です。今回はここまでとします。

修正を提案する
この記事をシェアする:
WhatsApp を使ってこの記事をシェアするFacebook でこの記事をシェアするX でこの記事をシェアするTelegram を使ってこの記事をシェアするPinterest でこの記事をシェアするMail を使ってこの記事をシェアする
次の記事
バックエンド屋の性能最適化 実戦（3）：Grafana と Prometheus のクエリ実例