PostgreSQL auto_explain モジュールの出力情報

PostgreSQLのcontribで提供されている auto_explain モジュールについて、出力結果を調査した結果のまとめ。

auto_explain モジュール

PostgreSQLに投げられたクエリのうち、特定の条件にマッチしたクエリの実行計画をログに出力してくれるようにできるモジュール。
スロークエリの監視と改善を運用で行っていく際にあると便利。

詳細は、公式ドキュメント参照：
https://www.postgresql.jp/document/11/html/auto-explain.html

log_min_duration_statement を設定すればスロークエリ自体をログで捉えることはできるが、その時の実行計画は捉えられないため、時間がたってDBの状況が変わってしまうことでクエリが遅延した原因がわからなくなってしまうことがある。こういう場合に、auto_explain を仕込んでおくとスロークエリが発生したときの実行計画を取れるので事象の把握にとても役立つ。

インストール

今回はソースコードでインストールしたPostgreSQL環境を利用。

$ cd contrib/auto_explain
$ make
$ sudo make install

設定

auto_explain.log_min_duration で設定した時間以上かかったクエリの実行計画がサーバログに出力されるようになる。

今回は実験用なので、0 を設定して、全てのクエリを auto_explain の対象にしておく。

postgresql.conf

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '0'

出力情報

お試しのクエリを実行してその出力結果を調べた。

postgres=# SELECT count(*)
           FROM pg_class, pg_index
           WHERE oid = indrelid AND indisunique;
 count 
-------
   147
(1 row)

デフォルト

duration と plan が出力される。
planは手動でEXPLAINした時と同じ情報。

2020-02-28 00:44:59.026 JST [17490] LOG:  duration: 0.221 ms  plan:
	Query Text: SELECT count(*)
	           FROM pg_class, pg_index
	           WHERE oid = indrelid AND indisunique;
	Aggregate  (cost=28.23..28.24 rows=1 width=8)
	  ->  Hash Join  (cost=21.89..27.86 rows=147 width=0)
	        Hash Cond: (pg_index.indrelid = pg_class.oid)
	        ->  Seq Scan on pg_index  (cost=0.00..5.59 rows=147 width=4)
	              Filter: indisunique
	        ->  Hash  (cost=16.95..16.95 rows=395 width=4)
	              Buckets: 1024  Batches: 1  Memory Usage: 22kB
	              ->  Seq Scan on pg_class  (cost=0.00..16.95 rows=395 width=4)

auto_explain.log_verbose を有効にした場合

EXPLAINのVERBOSEオプションを使ったときと同じ情報が出力される。

2020-02-28 01:09:08.415 JST [18243] LOG:  duration: 0.327 ms  plan:
	Query Text: SELECT count(*)
	           FROM pg_class, pg_index
	           WHERE oid = indrelid AND indisunique;
	Aggregate  (cost=28.23..28.24 rows=1 width=8)
	  Output: count(*)
	  ->  Hash Join  (cost=21.89..27.86 rows=147 width=0)
	        Inner Unique: true
	        Hash Cond: (pg_index.indrelid = pg_class.oid)
	        ->  Seq Scan on pg_catalog.pg_index  (cost=0.00..5.59 rows=147 width=4)
	              Output: pg_index.indexrelid, pg_index.indrelid, pg_index.indnatts, pg_index.indnkeyatts, pg_index.indisunique, pg_index.indisprimary, pg_index.indisexclusion, pg_index.indimmediate, pg_index.indisclustered, pg_index.indisvalid, pg_index.indcheckxmin, pg_index.indisready, pg_index.indislive, pg_index.indisreplident, pg_index.indkey, pg_index.indcollation, pg_index.indclass, pg_index.indoption, pg_index.indexprs, pg_index.indpred
	              Filter: pg_index.indisunique
	        ->  Hash  (cost=16.95..16.95 rows=395 width=4)
	              Output: pg_class.oid
	              Buckets: 1024  Batches: 1  Memory Usage: 22kB
	              ->  Seq Scan on pg_catalog.pg_class  (cost=0.00..16.95 rows=395 width=4)
	                    Output: pg_class.oid

auto_explain.log_analyze を有効にした場合

auto_explain.log_analyze を有効にすると、単なるEXPLAIN情報ではなく、EXPLAIN ANALYZEを実行した情報が出力されるようになる。

2020-02-28 00:46:23.513 JST [17587] LOG:  duration: 0.380 ms  plan:
	Query Text: SELECT count(*)
	           FROM pg_class, pg_index
	           WHERE oid = indrelid AND indisunique;
	Aggregate  (cost=28.23..28.24 rows=1 width=8) (actual time=0.364..0.364 rows=1 loops=1)
	  ->  Hash Join  (cost=21.89..27.86 rows=147 width=0) (actual time=0.262..0.343 rows=147 loops=1)
	        Hash Cond: (pg_index.indrelid = pg_class.oid)
	        ->  Seq Scan on pg_index  (cost=0.00..5.59 rows=147 width=4) (actual time=0.018..0.063 rows=147 loops=1)
	              Filter: indisunique
	              Rows Removed by Filter: 12
	        ->  Hash  (cost=16.95..16.95 rows=395 width=4) (actual time=0.206..0.206 rows=395 loops=1)
	              Buckets: 1024  Batches: 1  Memory Usage: 22kB
	              ->  Seq Scan on pg_class  (cost=0.00..16.95 rows=395 width=4) (actual time=0.008..0.117 rows=395 loops=1)

auto_explain.log_buffers を有効にした場合

EXPLAINのBUFFERSオプションを使ったときと同じ情報が出力される。
auto_explain.log_analyzeを有効にしていないと効果がない。

2020-02-28 01:07:33.007 JST [18183] LOG:  duration: 0.445 ms  plan:
	Query Text: SELECT count(*)
	           FROM pg_class, pg_index
	           WHERE oid = indrelid AND indisunique;
	Aggregate  (cost=28.23..28.24 rows=1 width=8) (actual time=0.426..0.426 rows=1 loops=1)
	  Buffers: shared hit=20
	  ->  Hash Join  (cost=21.89..27.86 rows=147 width=0) (actual time=0.313..0.398 rows=147 loops=1)
	        Hash Cond: (pg_index.indrelid = pg_class.oid)
	        Buffers: shared hit=20
	        ->  Seq Scan on pg_index  (cost=0.00..5.59 rows=147 width=4) (actual time=0.023..0.066 rows=147 loops=1)
	              Filter: indisunique
	              Rows Removed by Filter: 12
	              Buffers: shared hit=4
	        ->  Hash  (cost=16.95..16.95 rows=395 width=4) (actual time=0.238..0.238 rows=395 loops=1)
	              Buckets: 1024  Batches: 1  Memory Usage: 22kB
	              Buffers: shared hit=13
	              ->  Seq Scan on pg_class  (cost=0.00..16.95 rows=395 width=4) (actual time=0.011..0.128 rows=395 loops=1)
	                    Buffers: shared hit=13

以上。