PostgreSQL初心者のためのEXPLAIN ANALYZEの読み方
1. 概要
EXPLAIN ANALYZEはPostgreSQLで遅いクエリを診断するための最も重要なツールです。このガイドでは、出力の各部分(ノードのタイプ、cost、rows、actual time)を読み解く方法を学びます。読み終わる頃には、execution planを自信を持って読み、どこにインデックスを追加すべきか、またはどこでクエリを修正すべきかが分かるようになります。
2. EXPLAIN と EXPLAIN ANALYZE
EXPLAINは統計情報に基づいた推定プラン(estimated plan)を表示するだけで、クエリを実行しません。EXPLAIN ANALYZEは実際にクエリを実行して、実際の実行時間を測定します。
-- 推定プランのみを表示、クエリは実行されない
EXPLAIN SELECT * FROM orders WHERE customer_id = 42;
-- 実際にクエリを実行し、実際の実行時間を測定
EXPLAIN ANALYZE SELECT * FROM orders WHERE customer_id = 42;
注意:
EXPLAIN ANALYZEは実際にクエリを実行するため、UPDATEやDELETEの場合、データが変更されます。テストのためだけの場合は、トランザクション内で実行してROLLBACKを使用してください:
BEGIN;
EXPLAIN ANALYZE UPDATE orders SET status = 'SHIPPED' WHERE id = 1;
ROLLBACK;
3. プラン内のノードの構造
出力の各行はノードです。つまり、データ処理の1つのステップを表します。ordersテーブルの例を見てみましょう:
EXPLAIN ANALYZE
SELECT * FROM orders WHERE customer_id = 42;
Seq Scan on orders (cost=0.00..1834.00 rows=10 width=72)
(actual time=0.015..12.430 rows=8 loops=1)
Filter: (customer_id = 42)
Rows Removed by Filter: 99992
Planning Time: 0.120 ms
Execution Time: 12.465 ms
各部分の説明:
Seq Scan on orders: ノードの種類。ここではテーブル全体を順序立ててスキャンします。cost=0.00..1834.00: 推定コスト(スタートアップコスト..総コスト)。単位は相対的で、ミリ秒ではありません。rows=10: プランナーが返されると予想する推定行数。width=72: 平均的な各行のサイズ(バイト単位)。actual time=0.015..12.430: 実際の時間(ミリ秒)。最初の行を返すまでの時間..ノード全体の完了。rows=8 loops=1: 実際に返された行数。このノードが実行された回数(loops)。Rows Removed by Filter: スキャンされたが、フィルタに一致しない行数。この数が大きいのはインデックスがないことを示す兆候です。
4. Seq Scan と Index Scan の比較
4.1. インデックスがない場合
EXPLAIN ANALYZE
SELECT * FROM orders WHERE customer_id = 42;
Seq Scan on orders (cost=0.00..1834.00 rows=10 width=72)
(actual time=0.015..12.430 rows=8 loops=1)
Filter: (customer_id = 42)
Execution Time: 12.465 ms
PostgreSQLはテーブル全体を読んで、各行をフィルタする必要があります。大きなテーブルの場合、これが遅さの主な原因となります。
4.2. インデックスを追加した後
CREATE INDEX idx_orders_customer_id ON orders (customer_id);
EXPLAIN ANALYZE
SELECT * FROM orders WHERE customer_id = 42;
Index Scan using idx_orders_customer_id on orders
(cost=0.29..8.31 rows=10 width=72)
(actual time=0.018..0.025 rows=8 loops=1)
Index Cond: (customer_id = 42)
Execution Time: 0.045 ms
比較:costは1834から8.31に削減され、実行時間は12.465 msから0.045 msに削減されました。これはインデックスがPostgreSQLテーブル全体をスキャンせずに必要な行に直接ジャンプするのにどのように役立つかを示す典型的な例です。
注意: インデックスがある場合でも、PostgreSQLは必ずしも使用するとは限りません。クエリがテーブルの大部分(例:20~30%以上の行)を返す場合、プランナーは
Seq Scanを選択することが多いです。なぜなら、順序スキャンの方が、インデックスを通じてランダムにジャンプしてテーブルに戻すよりもコストが低いからです(ランダムI/O)。
5. JOIN を含むプランの読み方
クエリにJOINが含まれている場合、プランには複数のネストされたノードが存在します。子のノードが最初に実行され、その結果が親のノードに渡されます。
EXPLAIN ANALYZE
SELECT o.id, c.name
FROM orders o
JOIN customers c ON o.customer_id = c.id
WHERE c.country = 'VN';
Hash Join (cost=45.50..520.75 rows=200 width=40)
(actual time=1.200..8.900 rows=195 loops=1)
Hash Cond: (o.customer_id = c.id)
-> Seq Scan on orders o
(cost=0.00..420.00 rows=10000 width=12)
(actual time=0.010..3.500 rows=10000 loops=1)
-> Hash (cost=40.00..40.00 rows=440 width=36)
(actual time=1.100..1.100 rows=440 loops=1)
-> Seq Scan on customers c
(cost=0.00..40.00 rows=440 width=36)
(actual time=0.005..0.700 rows=440 loops=1)
Filter: (country = 'VN'::text)
Execution Time: 9.050 ms
読み方:Hash Joinは最も外側のノード(ルート)で、2つの子ノード(Seq Scan on ordersとHashを含むSeq Scan on customers)からデータを受け取ります。PostgreSQLはフィルタされたcustomersテーブルからハッシュテーブルを構築し、その後ordersをスキャンしてハッシュテーブルに一致させます。親ノードのactual timeには、その内部の子ノードの時間がすでに含まれています。
6. 注意が必要な警告信号
6.1. 推定値が実際と大きく異なる
Seq Scan on orders (cost=0.00..1834.00 rows=10 width=72)
(actual time=0.015..12.430 rows=9500 loops=1)
プランナーがrows=10と予想していたのに、実際には9500行が返されました。このような大きな差異は通常、古い統計情報が原因です。以下のコマンドで解決できます:
ANALYZE orders;
このコマンドは、プランナーがより正確に推定するための統計情報を更新します。
6.2. 異常に大きいloops(Nested Loop)
Nested Loop (cost=0.43..5000.00 rows=1 width=40)
(actual time=0.020..450.000 rows=1 loops=1)
-> Seq Scan on customers c (actual time=0.010..0.015 rows=1 loops=1)
-> Index Scan on orders o
(actual time=0.002..0.450 rows=1 loops=1000)
loops=1000は、Index Scan on ordersノードが1000回呼び出されたことを意味します(外側のノードから1000行に対応)。ノードが呼び出されるたびに時間がかかる場合、総コストは非常に大きくなり、actual timeが個別に小さく見えても同じです。ノードの実際の総時間を推定するには、actual timeにloopsを掛けてください。
6.3. バッファを確認するためにBUFFERSを使用
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders WHERE customer_id = 42;
Index Scan using idx_orders_customer_id on orders
(cost=0.29..8.31 rows=10 width=72)
(actual time=0.018..0.025 rows=8 loops=1)
Index Cond: (customer_id = 42)
Buffers: shared hit=4
Execution Time: 0.045 ms
shared hit=4は、4つのブロックがキャッシュ(メモリ)から読み込まれ、ディスクには触れていないことを意味します。shared readが大きい場合、データをディスクから読み込む必要があります。これはキャッシュミスの兆候で、shared_buffersが小さすぎるか、クエリが多くのコールドデータをスキャンしている可能性があります。
7. JavaやSpringでEXPLAINを使用
Spring Bootアプリケーションでのパフォーマンスデバッグ時に、JdbcTemplateを通じてプランを直接ログに記録できます:
@Service
public class QueryDiagnosticsService {
private final JdbcTemplate jdbcTemplate;
public QueryDiagnosticsService(JdbcTemplate jdbcTemplate) {
this.jdbcTemplate = jdbcTemplate;
}
public List<String> explainAnalyze(String sql) {
String query = "EXPLAIN (ANALYZE, FORMAT TEXT) " + sql;
return jdbcTemplate.queryForList(query, String.class);
}
}
explainAnalyzeは元のSQLを受け取り、EXPLAIN (ANALYZE, FORMAT TEXT)でラップして、プランの各行をStringとして返します。遅いクエリを検出した場合、dev/staging環境でプランをログに記録するために使用できます。
@Test
void explainAnalyze_shouldReturnPlanWithExecutionTime() {
QueryDiagnosticsService service = new QueryDiagnosticsService(jdbcTemplate);
List<String> plan = service.explainAnalyze(
"SELECT * FROM orders WHERE customer_id = 42"
);
assertThat(plan)
.isNotEmpty()
.anyMatch(line -> line.contains("Execution Time"));
}
このテストは特定の数値をアサートしません(実行時間はマシンによって異なるため)。プランがExecution Time行を含むことを確認するだけです。これにより、ステートメントが正常に実行され、有効なプランが返されたことを確認するのに十分です。
注意: productionでUPDATEやDELETE操作を含むクエリに対して、トランザクション+
ROLLBACKでラップせずにEXPLAIN ANALYZEを実行しないでください。実際に実行されてしまいます。
8. EXPLAIN ANALYZE が不要な場合
- クエリが既に高速で安定している(数ミリ秒未満、データ量が少ない)場合。さらに最適化する必要はなく、労力に見合いません。
- スキーマ設計の早期段階にあり、まだ実データが十分になく、統計情報が現実を反映していない場合(少数の行ではSeq Scanが常にIndex Scanに勝ちます)。
- 一時テーブル(
TEMP TABLE)で1回だけ実行されるクエリの場合。分析のオーバーヘッドは利益に見合いません。
9. まとめ
EXPLAIN ANALYZEは、PostgreSQLが考えていること(推定されたcost、rows)と実際に起きていること(actual time、実際の行数)の違いを示します。プランを読む際には、実行順序(内から外へ)、ノードのタイプ(Seq ScanかIndex Scan)に注目し、特に推定値と実際の値のズレに注意を払ってください。ここが、インデックスを追加する必要があるのか、テーブルのANALYZEをやり直す必要があるのか、またはロジックを書き直す必要があるのかを判断する鍵となります。