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が発生し、パフォーマンスへの影響が予想されます。

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

検証

検証環境

Windows の Hyper-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 に同梱されている 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 の内部処理を解析しての検証ではありません。よって、環境やクエリによってパフォーマンスへの影響が変わる可能性は大いにあります。今回の検証は一つの参考とし、実際の環境で検証を行うことを強くお勧めします。

ぱと隊長日誌

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