kotememo

【PostgreSQL】SQL実行時の実行計画を自動でログ出力する設定

作成日：2023/04/05

はじめに

遅いSQLを検知するためにlog_min_duration_statementパラメータを設定していましたが、実行時間は分かりますが実行当時の実行計画はログに出力されていません。

そのため、後からの調査・改善が困難になる場合があります。

調べたところauto_explainモジュールを利用することで、遅いSQLの実行計画を自動でログに出力できるようなため試してみました。

概要

実行時間が一定時間を超えた場合にSQL文をログ出力するlog_min_duration_statementパラメータはOFFにしておきます。

先にauto_explainを試した後に2つのパラメータを同時に設定した場合の挙動を確認します。

  1. セッション単位の設定
  2. 全体設定
  3. log_min_duration_statementパラメータと併用するための注意点

環境

  • Windows 10 Home
  • PostgreSQL 14.6

1. セッション単位の設定

スーパーユーザのみがセッション中にパラメータを変更できるようです。

以下のSQLを実行し、セッション終了後の別セッションでもう一度実行したところ、パラメータ変更は保持されていませんでした。

そのため、個別のSQLのみ調査対象としたい場合に有効と考えられます。

実行SQL

SELECT * FROM testtable;

LOAD 'auto_explain';
SET auto_explain.log_min_duration = '0ms';
SET auto_explain.log_analyze = true;

SELECT * FROM testtable;

auto_explainを設定した後のSQL文のみログ出力されており、2回目セッションの1文目はログ出力されていませんでした。

2023-04-05 21:24:50.205 JST [19940] LOG:  database system is ready to accept connections
2023-04-05 21:25:40.657 JST [14520] LOG:  duration: 0.026 ms  plan:
	Query Text: SELECT * FROM testtable;
	Seq Scan on testtable  (cost=0.00..1.01 rows=1 width=5) (actual time=0.016..0.017 rows=1 loops=1)
2023-04-05 21:31:02.901 JST [19780] LOG:  duration: 0.026 ms  plan:
	Query Text: SELECT * FROM testtable;
	Seq Scan on testtable  (cost=0.00..1.01 rows=1 width=5) (actual time=0.016..0.017 rows=1 loops=1)

2. 全体設定

全体設定はdata\postgresql.confで設定します。

全てのSQLに対して適用されますが、その分ログ出力するため全体的な負荷は上がると思われます。

# postgresql.conf

#------------------------------------------------------------------------------
# CUSTOMIZED OPTIONS
#------------------------------------------------------------------------------

# Add settings for extensions here

session_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '0ms'
auto_explain.log_analyze = true;

3. log_min_duration_statementパラメータと併用するための注意点

data\postgresql.confで両方のパラメータを設定します。

この状態でSQL文を実行した場合、auto_explainの次に標準のログが出力されていました。

# postgresql.conf

#------------------------------------------------------------------------------
# REPORTING AND LOGGING
#------------------------------------------------------------------------------

log_min_duration_statement = 0

#------------------------------------------------------------------------------
# CUSTOMIZED OPTIONS
#------------------------------------------------------------------------------

# Add settings for extensions here

session_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '0ms'
auto_explain.log_analyze = true;

auto_explainのログ出力に時間がかかるためか2個目の通常ログの実行時間が長くなっています。

2023-04-05 21:48:10.924 JST [18704] LOG:  duration: 0.074 ms  plan:
	Query Text: select * from testtable;
	Seq Scan on testtable  (cost=0.00..1.01 rows=1 width=5) (actual time=0.048..0.051 rows=1 loops=1)
2023-04-05 21:48:10.926 JST [18704] LOG:  duration: 9.262 ms  statement: select * from testtable;