ぱと隊長日誌

ブログ運用もエンジニアとしての生き方も模索中

PostgreSQL のエクゼキュータによるノードの処理順

PostgreSQL のエクゼキュータによるノードの処理順はマニュアルに解説されています。
50.6. エクゼキュータ

この説明をかみ砕いて説明します。

エクゼキュータはプランナ/オプティマイザで作成された計画に従って処理を進めます。その際、上位ノードの要求に応じて下位ノードはタプル(行)を返します。例えば、Sort ノードを実行するためにはソート対象のタプルが必要となります。そこで、Sort ノードの下位ノードは Sort ノードの要求に応じてタプルを渡します。

マニュアルの記載に近い具体例で説明します。

=# CREATE TABLE tab1(c1 INTEGER);
=# CREATE TABLE tab2(c1 INTEGER);

=# INSERT INTO tab1 SELECT generate_series(1, 3);
=# INSERT INTO tab2 SELECT generate_series(1, 3);

=# VACUUM ANALYZE;

=# SET enable_hashjoin TO OFF;

=# EXPLAIN SELECT tab1.c1 FROM tab1 INNER JOIN tab2 ON tab1.c1 = tab2.c1;
                           QUERY PLAN
----------------------------------------------------------------
 Merge Join  (cost=2.11..2.17 rows=3 width=4)
   Merge Cond: (tab1.c1 = tab2.c1)
   ->  Sort  (cost=1.05..1.06 rows=3 width=4)
         Sort Key: tab1.c1
         ->  Seq Scan on tab1  (cost=0.00..1.03 rows=3 width=4)
   ->  Sort  (cost=1.05..1.06 rows=3 width=4)
         Sort Key: tab2.c1
         ->  Seq Scan on tab2  (cost=0.00..1.03 rows=3 width=4)
(8 rows)

この計画の最上位ノードは Merge Join ノードです。マージ結合は結合キーでソートしてから順番に突き合わせて結合する方法です。このため、tab1 / tab2 テーブルはそれぞれ結合キーでソートされています。そして、ソートするタプルを Seq Scan ノードで取得します。

マニュアルの記載に従って処理が進むとすれば、以下の動作になります。

  1. Merge Join ノードが tab1 の結合キーでソートされた最初のタプルを Sort ノードに要求する
    1. Sort ノードが tab1 のタプルを要求する(全てのタプルを取得するまで繰り返す)
      1. SeqScan ノードが tab1 のタプルを 1 つ返す
    2. Sort ノードが tab1 のタプルを結合キーでソートする
    3. Sort ノードが tab1 の結合キーでソートされた最初のタプルを返す(ソート結果は後の要求に備えて残す)
  2. Merge Join ノードが tab2 の結合キーでソートされた最初のタプルを Sort ノードに要求する
    1. Sort ノードが tab2 のタプルを要求する(全てのタプルを取得するまで繰り返す)
      1. SeqScan ノードが tab2 のタプルを 1 つ返す
    2. Sort ノードが tab2 のタプルを結合キーでソートする
    3. Sort ノードが tab2 の結合キーでソートされた最初のタプルを返す(ソート結果は後の要求に備えて残す)
  3. Merge Join ノードが tab1 と tab2 の最初のタプルで結合できるかを比較する
  4. 結合できれば呼び出し側に結果を返す
  5. Merge Join ノードは tab1 と tab2 の残りのタプルについて結合できるかを比較する
    1. 各 Sort ノードは残したソート結果から Merge Join ノードの要求に応じてタプルを返す

この処理の流れからわかるのが、各ノードは処理したタプルを上位ノードに順次渡しているということです。各ノードが処理を完了させてから次のノードの処理に移るわけではありません。

エクゼキュータの処理順を理解することで、実行計画から処理の流れをイメージしやすくなります。本記事が実行計画を読み解く際のヒントになれば幸いです。

PostgreSQL の auto_explain のパフォーマンスへの影響

概要

PostgreSQL の auto_explain モジュールはスロークエリの実行計画をログ出力する手段を提供します。このモジュールを有効化することでパフォーマンスにどの程度影響を与えるのか、PostgreSQL に同梱されている pgbench で検証を行いました。

対象バージョン

検証には PostgreSQL 14.1 を用いました。
ただし、日本語ドキュメントは現時点の最新である 13.1 を参照しています。

事前調査

マニュアル

auto_explain のマニュアルでパフォーマンスに関して特に目を引くのが以下の2点でした。

より一般的な使用方法は、postgresql.confのsession_preload_librariesまたはshared_preload_librariesにauto_explainを含めて、特定のまたはすべてのセッションで事前にロードしておくことです。すると、想定外に低速な問い合わせを発生時に何も行うことなく追跡することができます。当然ながらこのためのオーバーヘッドという代償があります。

F.4. auto_explain

※設定パラメータ auto_explain.log_analyze の注記
このパラメータが有効の場合、計画ノードごとの時間的調整は事実上ログされるまで如何に時間が掛かろうと、全ての実行文に対して引き起こります。極端に性能上のマイナスの影響が起こり得ます。auto_explain.log_timingを無効にすれば、得られる情報が少なくなるという犠牲を払って、性能の損失が改善されます。

F.4. auto_explain

これら影響がありうることを念頭に調査します。

また、ノードの実行時間を測定するためにシステムクロックを何度も読み取り、それがオーバーヘッドになっていることを以前の記事で示しました。
PostgreSQL の EXPLAIN コマンドの TIMING パラメータのオーバーヘッド - ぱと隊長日誌

別の記事でパラレルモードだとシステムクロックの読み取り回数が減ることを示唆しています。

It is a very interesting the case when parallel mode is activated. Here the time is reported in blocks to some degree, significantly lowering the number of times the clock is called.

OnGres | EXPLAIN ANALYZE may be lying to you

この観点でも調査することにします。

ソースコード

contrib/auto_explain.c

とてもシンプルなコードとなっていました。

auto_explain は Hook という仕組みを用いて組み込んでいます。

Executor の開始時に EXPLAIN ANALYZE 用の設定を行います。auto_explain の設定が単なる EXPLAIN 出力であれば、この EXPLAIN ANALYZE 用の設定はスキップされます。

Executor のソースコードを追いかけきれなかったので推測になりますが、EXPLAIN ANALYZE 用の設定があると、Executor は実行時に情報を収集している模様です。これは auto_explain.log_min_duration (実行計画をログ出力する最小の実行時間)設定によらないため、『全ての実行文に対して引き起こります』とマニュアルで注記されています。

※設定パラメータ auto_explain.log_analyze の注記
このパラメータが有効の場合、計画ノードごとの時間的調整は事実上ログされるまで如何に時間が掛かろうと、全ての実行文に対して引き起こります。

F.4. auto_explain

Executor の終了時、実際の実行時間が auto_explain.log_min_duration を超過していればログ出力となります。

auto_explain はスロークエリと判定されたときに EXPLAIN / EXPLAIN ANALYZE しているわけではありません。実行時点で必要な情報を収集し、実行完了時点でスロークエリと判定された場合にログ出力を行っています。

調査観点

auto_explain のコードから以下の推測を行いました。

EXPLAIN のみであれば、パフォーマンスへの影響は軽微に思われます。EXPLAIN ANALYZE が有効な場合は全てのクエリ実行で測定されるため、パフォーマンスへの影響がありそうです。

auto_explain.log_timing を有効にすると「行あたりの時間計測のオーバーヘッド」がかかります。クエリによってはパフォーマンスへの影響がありそうです。また、パラレルモードの有無でも違いがありそうです。

ログ出力が行われれば、ディスクI/Oが発生し、パフォーマンスへの影響が予想されます。

これらの推測が正しいかを検証しました。

検証

検証環境

WindowsHyper-V による仮想マシンを検証環境としました。

ホスト
プロセッサ Intel Core i5-6600 CPU @ 3.30GHz
メモリ 20.0 GB
SSD SanDisk SDSSDH3
OS Windows 10 Pro バージョン 21H1
Hyper-V
プロセッサ 4個の仮想プロセッサ
メモリ 8.0 GB
OS Red Hat Enterprise Linux release 8.5
DB PostgreSQL 14.1

PostgreSQL設定

全ての検証パターンで以下の設定を行います。

logging_collector = on
autovacuum = off
shared_buffers = 2GB
effective_cache_size = 6GB
maintenance_work_mem = 512MB
wal_buffers = 16MB
random_page_cost = 1.1
effective_io_concurrency = 200
work_mem = 5242kB
min_wal_size = 1GB
max_wal_size = 4GB
max_worker_processes = 4
max_parallel_workers_per_gather = 2
max_parallel_workers = 4
max_parallel_maintenance_workers = 2

検証パターンに応じて追加で設定を行いました。

検証手段

ベンチマークツールは PostgreSQL に同梱されている pgbench を利用しました。今回の検証では後述する独自のスクリプトファイルを用いています。

CPU やメモリに比べアクセス速度の遅いディスク処理を避けるべく、小さくシンプルなクエリを用いることにしました。

初期状態を準備するスクリプトです。

CREATE TABLE tab1(c1 INTEGER);
INSERT INTO tab1 SELECT generate_series(1, 1e+6);

スクリプトファイルのクエリです。
auto_explain の「行あたりの時間計測のオーバーヘッド」を計測するため、1行しか処理しないクエリ (limit.pgbench) と100万行 (1e+6) 処理するクエリ (count.pgbench) を用意しました。

-- limit.pgbench
SELECT c1 FROM tab1 LIMIT 1;
-- count.pgbench
SELECT COUNT(c1) FROM tab1;

ベンチマークの実行コマンドです。
トランザクション数の違いは現実的な測定時間かつなるべく多い回数に選定しました。

$ pgbench -f /home/postgres/limit.pgbench -c 1 -j 1 -t 5000000 testdb
$ pgbench -f /home/postgres/count.pgbench -c 1 -j 1 -t 50000 testdb

パフォーマンスは pgbench の出力から "latency average" で比較します。小さいほど良い結果です。

auto_explain をロードすることによる影響検証

auto_explain をロードすることによるパフォーマンスへの影響を調べました。今回は全てのセッションで事前にロードすることを選択しました (shared_preload_libraries)。limit.pgbench で検証しました。

(1) auto_explain ロードなし

※追加設定なし

(2) auto_explain ロードするが無効

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = -1
条件 limit.pgbench[ms]
auto_explain ロードなし 0.110
auto_explain ロードするが無効 0.111

auto_explain ロード有無による差はとても小さいものでした。shared_preload_libraries で auto_explain をロードするだけであれば、パフォーマンスへの影響はほぼないといえます。

auto_explain と処理行数による影響検証

auto_explain の処理行数によるパフォーマンスへの影響を limit.pgbench(処理行数が少ない), count.pgbench(処理行数が多い)で検証しました。

auto_explain の結果出力によるディスクI/Oを抑制するため、auto_explain.log_min_duration の値を十分に大きくすることで結果出力をなくしました。

パラレルモードによる影響を検証するため、count.pgbench は以下の設定でパラレルモードを無効にしたパターンでも測定しています。

max_parallel_workers_per_gather = 0

私の環境では count.pgbench に用いるクエリが今回のデータ量でパラレルモードに切り替わることを確認しました。

=# EXPLAIN ANALYZE SELECT COUNT(c1) FROM tab1;
                                                              QUERY PLAN

------------------------------------------------------------------------------------------------------------------
---------------------
 Finalize Aggregate  (cost=10633.55..10633.56 rows=1 width=8) (actual time=38.759..40.869 rows=1 loops=1)
   ->  Gather  (cost=10633.33..10633.54 rows=2 width=8) (actual time=38.620..40.864 rows=3 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (cost=9633.33..9633.34 rows=1 width=8) (actual time=35.323..35.324 rows=1 loops=3)
               ->  Parallel Seq Scan on tab1  (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.007..17.425
rows=333333 loops=3)
 Planning Time: 0.048 ms
 Execution Time: 40.886 ms
(8 rows)

(1) auto_explain ロードするが無効

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = -1

(2) EXPLAIN のみ かつ 結果出力なし

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 10000

(3) EXPLAIN ANALYZE かつ 結果出力なし

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 10000
auto_explain.log_analyze = on

(4) EXPLAIN ANALYZE かつ 結果出力なし かつ 時間出力なし

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 10000
auto_explain.log_analyze = on
auto_explain.log_timing = off
条件 limit.pgbench[ms] count.pgbench[ms]+パラレル有効 count.pgbench[ms]+パラレル無効
auto_explain ロードするが無効 0.111 22.521 50.726
EXPLAIN のみ かつ 結果出力なし 0.112 22.532 51.448
EXPLAIN ANALYZE かつ 結果出力なし 0.112 38.268 96.212
EXPLAIN ANALYZE かつ 結果出力なし かつ 時間出力なし 0.111 24.396 56.766

処理行数が少ない (limit.pgbench) 場合、いずれのパターンでもほぼ差がありませんでした。シンプルなクエリであったことも差がない要因かもしれません。

limit.pgbench, count.pgbench 共に「auto_explain ロードするが無効」と「EXPLAIN のみ かつ 結果出力なし」の差がほとんどありません。ここから以下の可能性が示唆されます。

  • EXPLAIN だけの処理コストであれば低い
  • EXPLAIN は処理行数の影響を受けにくい

「auto_explain ロードするが無効」と「EXPLAIN ANALYZE かつ 結果出力なし」を比較すると、処理行数が多いほど (limit.pgbench < count.pgbench) EXPLAIN ANALYZE の処理時間も増えています。これは「行あたりの時間計測のオーバーヘッド」が影響していると推察されます。また、パラレル無効にするとその差はさらに広がります。これは「パラレルモードでシステムクロックの読み取り回数が減る」ということから説明できそうです。

「auto_explain ロードするが無効」と「EXPLAIN ANALYZE かつ 結果出力なし」の比較から以下のことが言えます。

  • 処理行数が多いほど (limit.pgbench < count.pgbench) EXPLAIN ANALYZE の処理時間も増える
    • 「行あたりの時間計測のオーバーヘッド」が影響していると推察される
  • パラレルモードのほうが良い結果になる
    • 「パラレルモードでシステムクロックの読み取り回数が減る」ことから
  • EXPLAIN ANALYZE が有効だと結果を出力しなくてもパフォーマンスが悪化する
    • count.pgbench の「EXPLAIN ANALYZE かつ 結果出力なし」がその例となる
    • クエリの実行時点で EXPLAIN ANALYZE に必要な情報を収集する分の処理コストがかかっている

「EXPLAIN ANALYZE かつ 結果出力なし かつ 時間出力なし」の結果から、ノード毎の時間出力をなくす (auto_explain.log_timing = off) ことでパフォーマンスへの影響を軽減できることが分かります。これはマニュアルの以下の記述と対応しています。

auto_explain.log_timingを無効にすれば、得られる情報が少なくなるという犠牲を払って、性能の損失が改善されます。

F.4. auto_explain

auto_explain の結果出力有無の影響検証

auto_explain の結果出力有無によるパフォーマンスへの影響を limit.pgbench で検証しました。

(1) EXPLAIN のみ かつ 結果出力なし

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 10000

(2) EXPLAIN のみ かつ 結果出力あり

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 0

(3) EXPLAIN ANALYZE かつ 結果出力なし

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 10000
auto_explain.log_analyze = on

(4) EXPLAIN ANALYZE かつ 結果出力あり

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_analyze = on
条件 limit.pgbench[ms]
EXPLAIN のみ かつ 結果出力なし 0.112
EXPLAIN のみ かつ 結果出力あり 0.146
EXPLAIN ANALYZE かつ 結果出力なし 0.112
EXPLAIN ANALYZE かつ 結果出力あり 0.149

結果出力なしに比べ、結果出力ありはパフォーマンスが落ちています。これは結果出力の書き出しに伴うディスクI/Oが影響していると推測されます。

まとめ

shared_preload_libraries で auto_explain をロードすることによるパフォーマンス影響はほぼありません。

EXPLAIN のみ (auto_explain.log_analyze = off) であれば、その処理コストは小さいと思われます。また、処理行数の影響も受けにくいようです。

EXPLAIN ANALYZE (auto_explain.log_analyze = on) では結果出力の有無にかかわらず、パフォーマンスへの影響があります。クエリの実行時点で EXPLAIN ANALYZE に必要な情報を収集しているためです。

EXPLAIN ANALYZE では処理行数の影響を強く受けます。これは「行あたりの時間計測のオーバーヘッド」が影響しており、ノード毎の時間出力をなくす (auto_explain.log_timing = off) ことで影響を軽減できます。ただ、ノード毎の時間出力はスロークエリの調査で有用なため、トレードオフの検討が必要です。

auto_explain の出力量に応じたディスクI/Oが発生し、パフォーマンスに影響します。auto_explain.log_min_duration の値を適切に設定することで影響を緩和できます。

今回の検証ではシンプルなクエリを用いました。また、EXPLAIN / EXPLAIN ANALYZE の内部処理を解析しての検証ではありません。よって、環境やクエリによってパフォーマンスへの影響が変わる可能性は大いにあります。今回の検証は一つの参考とし、実際の環境で検証を行うことを強くお勧めします。

PostgreSQL の EXPLAIN コマンドの TIMING パラメータのオーバーヘッド

本記事では PostgreSQL の EXPLAIN コマンドの TIMING パラメータのオーバーヘッドがどこから生じているかを解説します。

EXPLAIN コマンドの TIMING パラメータの説明を引用します。

実際のスタートアップ時間とノードで費やされた時間が追加表示されます。一部のシステムでは、システムクロックを何度も読み取るオーバーヘッドのため問い合わせがかなり低速になる可能性があります。このため、実際の時間ではなく実際の行数のみが必要であるのであれば、このパラメータはFALSEに設定する方が有益でしょう。

EXPLAIN

「システムクロックを何度も読み取るオーバーヘッド」がどの程度かを調べるために pg_test_timing ツールを利用できます。
pg_test_timing

また、pg_test_timing ツールのマニュアルには、実際のクエリを用いて EXPLAIN ANALYZE のオーバーヘッドを測定する方法も記載されています。記載を引用します。

問い合わせエクゼキュータがEXPLAIN ANALYZEを使って文を実行するとき、要約を表示する他に、個々のオペレーションについての時間計測もされます。次のpsqlプログラムで行を数えれば、システムのオーバーヘッドを調べることができます。

CREATE TABLE t AS SELECT * FROM generate_series(1,100000);
\timing
SELECT COUNT(*) FROM t;
EXPLAIN ANALYZE SELECT COUNT(*) FROM t;

測定に使ったi7-860システムでは、countの問い合わせを9.8ミリ秒で実行しましたが、EXPLAIN ANALYZEをつけたときは16.6ミリ秒かかりました。どちらの問い合わせもちょうど10万行を処理しています。この6.8ミリ秒の差は、行あたりの時間計測のオーバーヘッドが68ナノ秒であることを示しており、これはpg_test_timingによる推定値の約2倍です。この比較的小さな量のオーバーヘッドでも、countの文の完全な時間計測をすると70%長くかかりました。もっと本質的な問い合わせでは、時間計測のオーバーヘッドはあまり問題にならないでしょう。

pg_test_timing

ここで疑問に感じるのが「行あたりの時間計測のオーバーヘッド」という点です。EXPLAIN ANALYZE は計画ノードごとに要した実行時間を表示します。なのに「行あたりの時間計測」とはどういうことでしょうか?

「行あたりの時間計測」に対する回答を以下の記事で確認できます。
OnGres | EXPLAIN ANALYZE may be lying to you

この記事から要約します。PostgreSQL のクエリ実行モデルは Volcano model を採用しています。このモデルでは各ノードが全ての処理を完了してから次のノードの処理に移るのではなく、処理したタプルを上位ノードに順次渡します。このため、各ノードの実行時間は行ごとの実行時間を測定し、集計することになります。これが「行あたりの時間計測」を必要とする理由です。

さきほどの記事ではこの実装に対する懸念を以下のように示しています。

The overhead EXPLAIN ANALYZE introduces is not proportional to the real duration of the query plan, but rather proportional to the number of rows processed by the node. While they may be aligned, more rows processed does not always lead to higher execution times, and counting on this assumption may lead to believing a node is slower when it is in fact faster than another one. In turn leading to a bad query optimization strategy.

OnGres | EXPLAIN ANALYZE may be lying to you

また、auto_explain モジュールで auto_explain.log_timing を有効にしていると、クエリ実行の度に「行あたりの時間計測のオーバーヘッド」が加わることになります。このオーバーヘッドを許容できるかは慎重に判断する必要があるでしょう。