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
```

以上。