PostgreSQL の auto_explain で実行計画をログに出力してみた
はじめに
PostgreSQL で遅いクエリを調査する際、後から EXPLAIN を実行しても、データ量や統計情報の変化で当時と同じ実行計画になるとは限りません。
auto_explain を使うと、クエリ実行時の実行計画を自動でログに記録できます。
この記事では、auto_explain を有効にして、ログに出力される様子を確認します。
検証環境
検証のための実行環境は EC2（AL2023, t3.micro）にインストールした PostgreSQL を使用しました。
EC2 に PostgreSQL をインストールする手順としては下記をご参照ください。
PostgreSQL 17.10 を利用し、検証していきます。
[ec2-user@ip-xx-xx-xx-xx ~]$ sudo -u postgres psql
psql (17.10)
Type "help" for help.
postgres=# SELECT version();
version
---------------------------------------------------------------------------------------------------------------
PostgreSQL 17.10 on x86_64-amazon-linux-gnu, compiled by gcc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-5), 64-bit
(1 row)
サンプルDBの準備
検証のためのサンプル DB とテーブルを作成します。
-- DB 作成
postgres=# CREATE DATABASE blog_sample_db;
CREATE DATABASE
-- DB 切り替え
postgres=# \c blog_sample_db
You are now connected to database "blog_sample_db" as user "postgres".
-- テーブル作成
blog_sample_db=# CREATE TABLE orders (id int PRIMARY KEY, customer_id int, amount int);
CREATE TABLE
-- データ投入
blog_sample_db=# INSERT INTO orders
SELECT g, (random()*10000)::int, (random()*1000)::int
FROM generate_series(1, 500000) g;
INSERT 0 500000
-- 統計情報を最新化
blog_sample_db=# ANALYZE orders;
ANALYZE
続いて、auto_explain モジュールを有効化します。
blog_sample_db=# LOAD 'auto_explain';
LOAD
なお上記のように、LOAD しただけでは何も記録されません。
デフォルトでは auto_explain.log_min_duration が -1 のため、何も記録しない設定になっています。
-- デフォルトではログは一切記録されない
-- -1 は無効（デフォルト）
blog_sample_db=# SHOW auto_explain.log_min_duration;
auto_explain.log_min_duration
-------------------------------
-1
(1 row)
そこで、auto_explain.log_min_duration を 0（全クエリを記録）にして記録を有効化します。あわせて、実測値も出すために log_analyze を on に設定します。
-- 全クエリの実行計画を記録する（検証用）
blog_sample_db=# SET auto_explain.log_min_duration = 0;
SET
-- EXPLAIN ANALYZE 相当（実測値つき）で出力する
blog_sample_db=# SET auto_explain.log_analyze = true;
SET
なお、LOAD と SET は現在のセッションのみ有効です。接続を切ると元に戻るため、別のセッションで試す場合は再度実行してください。
auto_explainモジュールは、手動でEXPLAINの実行を必要とせず、自動的に遅い文の実行計画をログ記録する手段を提供します。
...
このモジュールはSQLでアクセスできる関数を提供しません。 使用するには、サーバに単に読み込ませます。 ある個別のセッションに読み込ませることができます。
LOAD 'auto_explain';
...
auto_explainの動作を制御するいくつかの設定パラメータが存在します。 デフォルトの動作は何もしないことなので、なんらかの結果を望むのであれば少なくともauto_explain.log_min_durationを設定しなければならないことに注意してください。
auto_explain.log_min_duration (integer)
auto_explain.log_min_durationは、文の実行計画がログに記録されるようになる、ミリ秒単位の最小の文実行時間です。 これを0にすれば、すべての計画が記録されます。 -1（デフォルト）は計画の記録を無効にします。 例えば、250msに設定すると、250ms以上実行する文すべてが記録されます。
...
auto_explain.log_analyze (boolean)
auto_explain.log_analyzeは、実行計画のログが取得されたときに出力されるものとして、単にEXPLAIN出力ではなく、EXPLAIN ANALYZE出力を行います。 このパラメータはデフォルトで無効です。 スーパーユーザのみがこの設定を変更できます。
インデックス有り無しそれぞれでクエリを実行
auto_explain を設定したため、インデックスありなしそれぞれでクエリを 1 回実行します。
blog_sample_db=# SELECT sum(amount) FROM orders WHERE customer_id = 123;
sum
-------
24609
(1 row)
-- インデックス作成
blog_sample_db=# CREATE INDEX idx_orders_customer ON orders(customer_id);
CREATE INDEX
-- 念の為統計情報を最新化
blog_sample_db=# ANALYZE orders;
ANALYZE
-- 検索
blog_sample_db=# SELECT sum(amount) FROM orders WHERE customer_id = 123;
sum
-------
24609
(1 row)
ログの確認
続いて、ログを確認します。
PostgreSQL ログは data_directory + log_directory のパスにあるため、各パラメータを確認します。(ブログ参照)
blog_sample_db=# SHOW data_directory;
data_directory
---------------------
/var/lib/pgsql/data
(1 row)
blog_sample_db=# SHOW log_directory;
log_directory
---------------
log
(1 row)
上記よりログは、/var/lib/pgsql/data/log にあることがわかります。
パスを確認すると下記のようにログが記録されています。
$ sudo ls -lt /var/lib/pgsql/data/log/
...
-rw-------. 1 postgres postgres 14107 Nov 3 03:27 postgresql-Tue.log
-rw-------. 1 postgres postgres 768 Oct 9 05:16 postgresql-Fri.log
-rw-------. 1 postgres postgres 12942 Oct 8 02:57 postgresql-Thu.log
...
前項の SELECT sum(amount) クエリを実行した日付のログ postgresql-Tue.log を確認します。
まず、grep で、SELECT の実行計画が記録されているかを調べます。(auto_explain のログは "Query Text" の文字列が記録されるのでそれで引っ掛けるといいです。公式ドキュメント参照)
$ sudo grep -n "Query Text: SELECT sum" /var/lib/pgsql/data/log/postgresql-Tue.log
92: Query Text: SELECT sum(amount) FROM orders WHERE customer_id = 123;
102: Query Text: SELECT sum(amount) FROM orders WHERE customer_id = 123;
2件ヒットしました。索引なし（92行目）と索引あり（102行目）の2回分です。
ヒットした行番号（92、102）の前後を含めて、実行計画の部分を抜き出します。
ログ全体を目視で確認すると、実行計画は 91〜108 行目にあったため、その範囲を表示します。
$ sudo sed -n '91,108p' /var/lib/pgsql/data/log/postgresql-Tue.log
※ sed -n '91,108p' は、指定した行（91〜108行目）だけを表示するコマンドです。
結果は以下です。
2026-11-03 03:16:13.944 UTC [3706] LOG: duration: 34.478 ms plan:
Query Text: SELECT sum(amount) FROM orders WHERE customer_id = 123;
Finalize Aggregate (cost=7379.66..7379.67 rows=1 width=8) (actual time=32.679..34.460 rows=1 loops=1)
-> Gather (cost=7379.54..7379.65 rows=1 width=8) (actual time=32.558..34.452 rows=2 loops=1)
Workers Planned: 1
Workers Launched: 1
-> Partial Aggregate (cost=6379.54..6379.55 rows=1 width=8) (actual time=26.872..26.873 rows=1 loops=2)
-> Parallel Seq Scan on orders (cost=0.00..6379.47 rows=29 width=4) (actual time=1.419..26.858 rows=24 loops=2)
Filter: (customer_id = 123)
Rows Removed by Filter: 249976
2026-11-03 03:16:31.638 UTC [3706] LOG: duration: 0.117 ms plan:
Query Text: SELECT sum(amount) FROM orders WHERE customer_id = 123;
Aggregate (cost=185.16..185.17 rows=1 width=8) (actual time=0.111..0.112 rows=1 loops=1)
-> Bitmap Heap Scan on orders (cost=4.81..185.03 rows=50 width=4) (actual time=0.052..0.103 rows=48 loops=1)
Recheck Cond: (customer_id = 123)
Heap Blocks: exact=47
-> Bitmap Index Scan on idx_orders_customer (cost=0.00..4.80 rows=50 width=0) (actual time=0.039..0.039 rows=48 loops=1)
Index Cond: (customer_id = 123)
実行計画がログに記録されていました。それぞれ見ていきます。
1. インデックス無し（duration: 34.478 ms）
Parallel Seq Scan on ordersで、テーブルを先頭から順に読んでいますFilter: (customer_id = 123)で条件に合う行を探し、合わない行は捨てていますRows Removed by Filter: 249976から、大量の行を読んで捨てていたことが分かります
2. インデックスあり（duration: 0.117 ms）
Bitmap Index Scan on idx_orders_customerで、作成した索引を使って該当行の場所を探していますBitmap Heap Scanで、その場所のブロック（Heap Blocks: exact=47）だけを読んでいます
比較
| 1.インデックスなし | 2.インデックスあり | |
|---|---|---|
| 実行時間 | 34.478 ms | 0.117 ms |
| スキャン方法 | Parallel Seq Scan | Bitmap Heap Scan + Bitmap Index Scan |
| 注目の項目 | Rows Removed by Filter: 249976 |
Heap Blocks: exact=47 |
インデックスなし検索では、結果が約 48 行なのに、約 50 万行を読んでいたことがログから分かります。この読み取りが実行時間に影響していたと考えられます。
一方でインデックスありの検索は、索引を見て必要なブロックだけを読むため、実行時間が大幅に短縮されました。
※ 実行時間はこの環境での一例です。
※actual time や Rows Removed by Filter のような実測値は、auto_explain.log_analyze = true にしたことで出力されています。
終わりに
auto_explain を有効にすると、手動で EXPLAIN を実行しなくても、クエリ実行時の実行計画がログに残ることを確認できました。
インデックスなしでは Rows Removed by Filter: 249976 から「大量の行を読んで捨てている」ことが分かり、インデックスありでは必要なブロックだけを読む計画に変わっていました(34.478 ms -> 0.117 ms)。
「遅いクエリが後から再現しない」という場面でも、当時の実行計画がログに残っていれば、原因調査の手がかりになります。
※今回は検証のため log_min_duration = 0 で全クエリを記録しているので、本番ではログ量を考慮し、調べたい遅さの基準(数百 ms 〜 数秒など)に調整してください。また log_analyze = true は計測のオーバーヘッドがあるため、影響を確認しながら導入することをおすすめします。
本記事がどなたかのお役に立てば幸いです。
参考情報
