はじめに
PostgreSQLの実行計画の読み解き方は公式マニュアルで説明されています。PostgreSQL 10 でのリンクを示します。
14.1. EXPLAINの利用
ですが、若干分かり辛い個所があるため、本エントリでは以下の観点に着目して補足することにします。
- ノードの実行順
- コストの累積
- 実行時間の累積
本エントリの引用は特記無い場合、 PostgreSQL 10 マニュアル の上記ページから引用（一部追記）しています。
ノードの実行順
原則ルール
ノードの実行順は以下の原則に従って決まります。
- ネストのより深いノードを優先する（右→左）
- ネストが同じレベルであれば先のノードを優先する（上→下）
ただし、必ずしもこの実行順となるわけではありません。これを例で確認します。
EXPLAIN SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2;
QUERY PLAN
------------------------------------------------------------------------------------------
(5) Hash Join (cost=230.47..713.98 rows=101 width=488)
Hash Cond: (t2.unique2 = t1.unique2)
(1) -> Seq Scan on tenk2 t2 (cost=0.00..445.00 rows=10000 width=244)
(4) -> Hash (cost=229.20..229.20 rows=101 width=244)
(3) -> Bitmap Heap Scan on tenk1 t1 (cost=5.07..229.20 rows=101 width=244)
Recheck Cond: (unique1 < 100)
(2) -> Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
Index Cond: (unique1 < 100)括弧付き数字は原則に従った場合の実行順を示しています。ですが、この実行計画に対するマニュアルの解説は原則と異なった実行順を説明しています。
片方のテーブルの行がメモリ内のハッシュテーブルに格納され、もう片方のテーブルがスキャンされた後、各行に対して一致するかどうかハッシュテーブルを探索します。 繰り返しますが、インデント付けにより計画の構造が表されます。 tenk1に対するビットマップスキャンはハッシュノードへの入力です。 外部の子計画から行を読み取り、各行に対してハッシュテーブルを検索します。
原則に従った実行順となっていることを理解するためのポイントとなるのが、各ノードは実行途中でも出力結果を上位ノードに渡し、上位ノードは可能であればそれまでに受け取った出力結果をもとに処理を進めるということです。
この実行計画が選択され、かつtenk2が0行であった場合、ハッシュテーブル作成処理（②～④）はスキップされます。PostgreSQL 10.3 で 同様の条件にして EXPLAIN ANALYZE を実行したところ、ハッシュテーブル作成処理が "never executed" になることを確認しました。このことから言えるのが、①でtenk2が1行以上あることを確認してから、ハッシュテーブル作成処理を行っているということです。
ここからは推測となりますが、上位ノードである Hash Join が下位ノードの①でtenk2から最初の1行を読み込んだ後、ハッシュテーブル作成処理（②～④）を行っていると思われます。マニュアルの解説は分かりやすさを優先したため、実際の挙動とは相違したものと思われます。
上位ノードが下位ノードの途中結果を受けて処理を行うことは別の例でも確認できます。
EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 LIMIT 2;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.29..14.71 rows=2 width=244) (actual time=0.177..0.249 rows=2 loops=1)
-> Index Scan using tenk1_unique2 on tenk1 (cost=0.29..72.42 rows=10 width=244) (actual time=0.174..0.244 rows=2 loops=1)
Index Cond: (unique2 > 9000)
Filter: (unique1 < 100)
Rows Removed by Filter: 287
Planning time: 0.096 ms
Execution time: 0.336 ms
インデックススキャンノードの推定コストと行数が実行完了したかのように表示されます。 しかし現実では、Limitノードが２行を取り出した後に行の要求を停止します。
下位ノードの Index Scan の結果を受けた 上位ノードの Limit が処理を停止させました。つまり、下位ノードの処理完了を待たず上位ノードは処理可能であれば処理を進めるということです。
例外ルール
前節の冒頭でノードの実行順の原則を示しましたが、例外もあることに注意が必要です。その一例が SubPlan ノードです。
http://www.nminoru.jp/~nminoru/postgresql/pg-plan-tree.html
この記事内にある"sample-corelated-subquery.sql"を用いて検証します。PostgreSQL 10.3 でsqlファイル内の CREATE TABLE, INSERT を発行後、VACUUM ANALYZE を実行しました。そして、SELECT の実行計画を取得した結果を示します。
EXPLAIN SELECT ID, name FROM employee WHERE salary < (SELECT population FROM cities WHERE employee.city = cities.city);
QUERY PLAN
--------------------------------------------------------------
Seq Scan on employee (cost=0.00..10.47 rows=3 width=10)
Filter: (salary < ((SubPlan 1))::double precision)
SubPlan 1
-> Seq Scan on cities (cost=0.00..1.04 rows=1 width=4)
Filter: ((employee.city)::text = (city)::text)
(5 rows)"Seq Scan on employee" よりも "Seq Scan on cities" のネストが深いため、"Seq Scan on cities" が先に実行されるように見えます。ですが、実際には "Seq Scan on employee" が先に実行されます。その理由を説明します。
"Seq Scan on cities" を含む SubPlan 1 は "Seq Scan on employee" のFilterで評価（実行）されています。Filter は "Seq Scan on employee" がスキャンした各行に対してその条件を検査することを意味していることから、"Seq Scan on employee" が先に実行されるとわかります。そして、SubPlan ノードは評価される度にサブプランを実行します。
PostgreSQL 内部の挙動の詳細は本節冒頭の記事内で解説されているため、ご参照ください。
http://www.nminoru.jp/~nminoru/postgresql/pg-plan-tree.html#Param
今回示したケースのように、SQLがどのような処理に分解され、それらがどのような順で実行されるかを理解していないと、実行計画を読み違えてしまうことがあります。より深く学ぶためには以下の本をお勧めします。
- 作者: エンコアコンサルティング
- 出版社/メーカー: 翔泳社
- 発売日: 2006/07/07
- メディア: 大型本
- 購入: 21人 クリック: 343回
- この商品を含むブログ (38件) を見る
コストの累積
マニュアルに記載の以下の点に注意してください。
上位ノードのコストには、すべての子ノードのコストもその中に含まれていることを理解することは重要です。
これを実行計画の例から確認します。
EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000;
QUERY PLAN
-------------------------------------------------------------------------------------
Bitmap Heap Scan on tenk1 (cost=25.08..60.21 rows=10 width=244)
Recheck Cond: ((unique1 < 100) AND (unique2 > 9000))
-> BitmapAnd (cost=25.08..25.08 rows=10 width=0)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
Index Cond: (unique1 < 100)
-> Bitmap Index Scan on tenk1_unique2 (cost=0.00..19.78 rows=999 width=0)
Index Cond: (unique2 > 9000)BitmapAnd の下位ノードである2つの Bitmap Index Scan の総コストを合算します。
5.04 + 19.78 = 24.82
これと比較すると BitmapAnd の総コストはわずかに大きくなっています。これは下位ノードの Bitmap の結果を受けてAND処理したことによるコストが加算されたためと考えられます。
BitmapAnd 単体のコストは以下の通りです。
(BitmapAnd の cost) - (下位ノードの cost) = 25.08 - (5.04 + 19.78) = 0.26
このように、BitmapAnd 単体の総コストが25.08なのではなく、下位ノードを含めたコストであることを理解して読み解く必要があります
実行計画に Loop ノードが加わると、より複雑になります。
EXPLAIN SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;
QUERY PLAN
--------------------------------------------------------------------------------------
Nested Loop (cost=4.65..118.62 rows=10 width=488)
-> Bitmap Heap Scan on tenk1 t1 (cost=4.36..39.47 rows=10 width=244)
Recheck Cond: (unique1 < 10)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..4.36 rows=10 width=0)
Index Cond: (unique1 < 10)
-> Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244)
Index Cond: (unique2 = t1.unique2)Nested Loop の下位ノードの総コストは
39.47 + 7.91 = 47.38
ではありません。
Index Scan ノードに示された総コストはノード実行1回分です。Nested Loop ノードは Bitmap Heap Scan の出力1行毎に Index Scan を1回実行します。Bitmap Heap Scan は rows=10 であることから、Index Scan は10回実行されることが分かり、そこから計算される Nested Loop の下位ノードの総コストは
39.47 + 7.91 * 10 = 118.57
となります。
また、EXPLAIN ANALYZE の結果に出力されるloops値は実際のノード実行回数であり、コストの計算に用いた実行回数とは異なる可能性があることに注意が必要です。コストの計算に用いる実行回数は実行計画から慎重に見極める必要があります。
実行時間の累積
実行時間についても上位ノードは下位ノードの実行時間を含むこと、またループ数の考慮も必要なことに注意が必要です。
EXPLAIN ANALYZE SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=4.65..118.62 rows=10 width=488) (actual time=0.128..0.377 rows=10 loops=1)
-> Bitmap Heap Scan on tenk1 t1 (cost=4.36..39.47 rows=10 width=244) (actual time=0.057..0.121 rows=10 loops=1)
Recheck Cond: (unique1 < 10)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..4.36 rows=10 width=0) (actual time=0.024..0.024 rows=10 loops=1)
Index Cond: (unique1 < 10)
-> Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244) (actual time=0.021..0.022 rows=1 loops=10)
Index Cond: (unique2 = t1.unique2)
Planning time: 0.181 ms
Execution time: 0.501 msこの実行計画に対する以下の説明に注意を払ってください。
問い合わせ計画の中には、何回も副計画ノードを実行する可能性のあるものがあります。 例えば、上述のネステッドループの計画では、内部インデックススキャンは外部の行ごとに一度行われます。 このような場合、loops値はそのノードを実行する総回数を報告し、表示される実際の時間と行数は1実行当たりの平均です。 これで値を表示された推定コストと比較できるようになります。 loops値をかけることで、そのノードで実際に費やされた総時間を得ることができます。 上の例では、tenk2に対するインデックススキャンの実行のために合計0.220ミリ秒要しています。
つまり、Nested Loop の下位ノードの総実行時間は
0.121 * 1 + 0.022 * 10 = 0.341
となります。
Nested Loop 単体の実行時間は以下の通りです。
(Nested Loop の actual time * loops) - (下位ノードの総実行時間) = 0.377 * 1 - 0.341 = 0.036
パフォーマンス改善のために actual time の急増するノードを探すことがありますが、
- 上位ノードは下位ノードの総実行時間を含むこと
- 全体の総実行時間を知るにはループ数を考慮する必要があること
を意識しないと、読み間違えることになります。
各ノードでループ数を踏まえた総実行時間を計算し、かつノード単体でかかった実行時間を計算するために下位ノードの総実行時間を差し引き、時間のかかっているノードを見つけることが必要です。
おわりに
今回取り上げたテーマは公式マニュアルや様々な資料で繰り返し説明されています。それだけ重要なポイントですが、説明は軽く触れられるにとどまり、実際に実行計画を読み取る際に考慮から漏れがちです。
参考
実行計画をさらに深く知るための参考資料集を以前にまとめました。併せてご参照ください。
PostgreSQLの実行計画を読み解くための参考資料集 - ぱと隊長日誌
更新情報
2018/05/12
ノード単体のコストや実行時間の計算を追記しました。
2018/05/20
「ノードの実行順 - 原則ルール」の記述を一部見直しました。
「ノードの実行順 - 例外ルール」を追加しました。
2018/05/22
「ノードの実行順 - 例外ルール」の記述を一部見直しました。
