
【初心者向け】 PostgreSQL の EXPLAIN ANALYZE の出力内容を確認してみた
以前、下記のブログにて、EXPLAIN を使ってクエリの実行計画の内容を確認する方法を紹介しました。
EXPLAIN を使うことで、クエリ実行計画の 「予測」 を確認できました。
今回は、EXPLAIN ANALYZE を使って「実測」を見てみたいと思います。
ANALYZEオプションを付けると、計画を作るだけでなく、文が実際に実行されます。 この場合は、各計画ノードで費された総経過時間(ミリ秒単位)と実際に返された全行数など、実際の実行時の統計情報が追加表示されます。 プランナの推測と実際の値が近いかどうかを確認するために、このオプションは有用です。
PostgreSQL 17.6文書 - EXPLAIN
https://www.postgresql.jp/document/17/html/sql-explain.html
実行環境
実行環境は EC2(AL2023)にインストールした PostgreSQL を使用しました。
EC2 に PostgreSQL をインストールする手順としては下記をご参照ください。
PostgreSQL 17.7 を利用し、検証していきます。
[ec2-user@ip-10-0-13-178 ~]$ sudo -u postgres psql
psql (17.7)
Type "help" for help.
postgres=# select * from version();
version
--------------------------------------------------------------------------------------------------------------
PostgreSQL 17.7 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 とテーブルの作成」の項目を参考にサンプルテーブルを作ります。
作成したテーブルは以下のようなものです。
-- 最初の 5 行を表示
explain_test=# SELECT * FROM users LIMIT 5;
id | name | age
----+--------+-----
1 | user_1 | 17
2 | user_2 | 47
3 | user_3 | 89
4 | user_4 | 17
5 | user_5 | 36
(5 rows)
-- 最後の 5 行を表示
explain_test=# SELECT * FROM users ORDER BY id DESC LIMIT 5;
id | name | age
--------+-------------+-----
100000 | user_100000 | 39
99999 | user_99999 | 54
99998 | user_99998 | 65
99997 | user_99997 | 66
99996 | user_99996 | 65
(5 rows)
各カラムの説明:
id: 1 〜 100,000 までの連番
name: user_1 〜 user_100000 までの文字列
age: 0 〜 100 のランダムな整数
補足:
age をランダムな整数にしているのは
「WHERE age = 25」のような条件で絞り込んだときに
インデックスの効果が出やすくするためです。
現在 users テーブルには、id カラムにプライマリキーのインデックスのみがあります。
不要なインデックスが存在する場合は、DROP INDEX <インデックス名>; などで削除しておきましょう。
-- テーブルとインデックスの状態確認
explain_test=# \d users
Table "public.users"
Column | Type | Collation | Nullable | Default
--------+---------+-----------+----------+-----------------------------------
id | integer | | not null | nextval('users_id_seq'::regclass)
name | text | | |
age | integer | | |
Indexes:
"users_pkey" PRIMARY KEY, btree (id)
インデックスなし
過去ブログの再掲ですが、EXPLAIN を単体で実行すると以下のようにクエリの実行計画(あくまで予測)が出力されます。
explain_test=# EXPLAIN SELECT * FROM users WHERE age = 25;
QUERY PLAN
-----------------------------------------------------------
Seq Scan on users (cost=0.00..1887.00 rows=960 width=18)
Filter: (age = 25)
(2 rows)
上記と全く同じクエリについて EXPLAIN ANALYZE を実行します。
explain_test=# EXPLAIN ANALYZE SELECT * FROM users WHERE age = 25;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Seq Scan on users (cost=0.00..1887.00 rows=960 width=18) (actual time=0.630..28.111 rows=966 loops=1)
Filter: (age = 25)
Rows Removed by Filter: 99034
Planning Time: 1.575 ms
Execution Time: 28.167 ms
(5 rows)
上記の出力結果を分解すると、以下のように「予測」と「実測」のそれぞれに分けられます。
Seq Scan on users
(cost=0.00..1887.00 rows=960 width=18) -- <- 予測
(actual time=0.630..28.111 rows=966 loops=1) -- <- 実測
Filter: (age = 25)
Rows Removed by Filter: 99034
Planning Time: 1.575 ms -- <- 実測
Execution Time: 28.167 ms -- <- 実測
各項目の意味を以下に示します。
予測値(EXPLAIN と同じ部分)
| 項目 | 値 | 意味 |
|---|---|---|
| cost=0.00 | 0.00 | 初期コスト(最初の1行を返すまでのコスト) |
| cost=..1887.00 | 1887.00 | 総コスト(全行取得し終えるまでのコスト) |
| rows | 960 | プランナーが予測した取得行数 |
| width | 18 | 1行あたりの平均バイト数 |
実測値(EXPLAIN ANALYZE で追加された部分)
| 項目 | 値 | 意味 |
|---|---|---|
| actual time=0.630 | 0.630 ms | 最初の1行を返すまでの実際の時間 |
| actual time=..28.111 | 28.111 ms | 全行返し終わるまでの実際の時間 |
| rows | 966 | 実際に取得した行数 |
| loops | 1 | このノードが実行された回数 |
WHERE 句のフィルタ情報
| 項目 | 値 | 意味 |
|---|---|---|
| Filter | age = 25 | WHERE 句の条件 |
| Rows Removed by Filter | 99034 | フィルタで除外された行数 |
966(取得)+ 99034(除外) = 100,000 なので、
今回のクエリではテーブルの全件(10万行)を読み込み、その中の 966 件を抽出したことがわかります。
実行時間
| 項目 | 値 | 意味 |
|---|---|---|
| Planning Time | 1.575 ms | クエリプランを作るのにかかった時間 |
| Execution Time | 28.167 ms | クエリ実行にかかった総時間 |
前述した実測値の actual time(28.111 ms)はノード単体の実行時間、Execution Time(28.167 ms)はクエリ全体の実行時間です。
パフォーマンスを確認する際は Execution Time を見ると分かりやすいです。
EXPLAIN ANALYZEで表示されるPlanning timeは、解析された問い合わせから問い合わせ計画を生成し最適化するのに掛かった時間です。 解析と書き換えは含みません。
EXPLAIN ANALYZEで表示されるExecution time(実行時間)にはエグゼキュータの起動、停止時間、発行される何らかのトリガの実行時間も含まれますが、解析や書き換え、計画作成の時間は含まれません。14.1. EXPLAINの利用
https://www.postgresql.jp/docs/17/using-explain.html
インデックスあり
インデックスを作成して EXPLAIN ANALYZE 結果がどのように変わるのかを見てみます。
-- インデックスを作成
explain_test=# CREATE INDEX idx_users_age ON users(age);
CREATE INDEX
-- インデックスが作成できたか確認
explain_test=# \d users
Table "public.users"
Column | Type | Collation | Nullable | Default
--------+---------+-----------+----------+-----------------------------------
id | integer | | not null | nextval('users_id_seq'::regclass)
name | text | | |
age | integer | | |
Indexes:
"users_pkey" PRIMARY KEY, btree (id)
"idx_users_age" btree (age)
-- 再度 EXPLAIN ANALYZE を実施
explain_test=# EXPLAIN ANALYZE SELECT * FROM users WHERE age = 25;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
-------------------
Bitmap Heap Scan on users (cost=11.73..690.90 rows=960 width=18) (actual time=0.149..0.681 rows=966 lo
ops=1)
Recheck Cond: (age = 25)
Heap Blocks: exact=507
-> Bitmap Index Scan on idx_users_age (cost=0.00..11.49 rows=960 width=0) (actual time=0.090..0.091
rows=966 loops=1)
Index Cond: (age = 25)
Planning Time: 0.166 ms
Execution Time: 0.728 ms
(7 rows)
出力結果の各項目の意味を概説します。
インデックスなしの時と比較して、以下のように 2 段階の処理構造に変化しています。
Bitmap Heap Scan ← 親ノード:実際にデータを取りに行く
└── Bitmap Index Scan ← 子ノード:インデックスで場所を調べる
1段階目の処理での予測と実測が示されます。
-> Bitmap Index Scan on idx_users_age
(cost=0.00..11.49 rows=960 width=0) -- ← 予測
(actual time=0.090..0.091 rows=966 loops=1) -- ← 実測
Index Cond: (age = 25)
| 項目 | 値 | 意味 |
|---|---|---|
| Index Cond | age = 25 | インデックスを使った絞り込み条件 |
| actual time | 0.090..0.091 ms | インデックスで場所を特定するのにかかった時間 |
| rows | 966 | 場所を特定した行数 |
2段階目の処理においても予測と実測が示されます。
このように各処理段階に応じてどれくらいのコストがかかっているのかを把握することが可能です。
Bitmap Heap Scan on users
(cost=11.73..690.90 rows=960 width=18) -- ← 予測
(actual time=0.149..0.681 rows=966 loops=1) -- ← 実測
Recheck Cond: (age = 25)
Heap Blocks: exact=507
| 項目 | 値 | 意味 |
|---|---|---|
| Recheck Cond | age = 25 | 取得したデータが条件に合うか再確認 |
| Heap Blocks: exact | 507 | 実際に読みに行ったブロック数 |
| actual time | 0.149..0.681 ms | 実際にデータを取得するのにかかった時間 |
| rows | 966 | 実際に取得した行数 |
最後に実行時間です。
以下のExecution Time 結果より、インデックスなしの時の 28.167 ms と比較し、0.728 ms と約 97.4% 削減されました。
| 項目 | 値 | 意味 |
|---|---|---|
| Planning Time | 0.166 ms | クエリプランを作るのにかかった時間 |
| Execution Time | 0.728 ms | クエリ全体の実行時間 |
Execution Time はクエリ全体にかかった総時間です。
今回のインデックスありのクエリのように、処理が2段階(何段階でも)になろうともこの値を見ることでパフォーマンスの改善を確認できます。
終わりに
今回は EXPLAIN ANALYZE を使って予測と実測を読み解きました。
EXPLAIN が予測のみの出力、ANALYZE オプションを付けると実測値となり、より正確な情報が手に入ることがわかりました。
また、クエリのパフォーマンスが改善しているかを把握する際は、Execution Time を見ると一発でわかりますね。便利です。
補足として、EXPLAIN ANALYZE は実際にクエリを実行するので、INSERT, UPDATE などの実行計画を見るときは、必ず BEGIN-ROLLBACK を忘れないようにしましょう。
ANALYZEを使用した場合は、文が実際に実行されることを忘れないでください。
...
データに影響を与えないようにEXPLAIN ANALYZEを実行したい場合は、以下の方法を使用してください。BEGIN; EXPLAIN ANALYZE ...; ROLLBACK;PostgreSQL 17.6文書 - EXPLAIN
https://www.postgresql.jp/document/17/html/sql-explain.html
本記事が EXPLAIN ANALYZE って何?という方へ少しでも理解の助けになれば幸いです。
参考情報











