PostgreSQL の auto_explain モジュールを使ってみた

Posted on 29 Jun 2014

PostgreSQL の auto_explain モジュールを使えば、スロークエリの実行計画を自動的にロギングできます。

auto_explain モジュールは、手動で EXPLAIN の実行を必要とせず、自動的に遅い文の実行計画をログ記録する手段を提供します。大きなアプリケーションにおける最適化されていない問い合わせを追跡するのに特に有用です。

試す機会があったので忘れないようにメモしておきます。

インストール

auto_explain は contrib パッケージに含まれています。今回は PostgreSQL 公式のリポジトリを使っているので yum コマンドでインストールできます。

$ sudo yum install postgresql93-contrib

自分の環境では依存関係を解決するために libxslt と uuid がインストールされました。

$ rpm -ql postgresql93-contrib | grep auto_explain
/usr/pgsql-9.3/lib/auto_explain.so

rpm コマンドで確認すると、auto_explain の共有ライブラリがインストールされたことがわかります。

postgresql.conf の変更

ログに出力されることを確認するため、0 秒に設定して全クエリの実行計画を出力してみます（ログが増えるので注意してください）。

$ sudo vi /var/lib/pgsql/9.3/data/postgresql.conf
shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 0

shared_preload_libraries で auto_explain を読み込ませ、auto_explain.log_min_duration で実行計画を記録するクエリ時間を指定します。保存したら shared_preload_libraries を反映させるために PostgreSQL サーバを再起動します。

$ sudo service postgresql-9.3 restart

適当な SQL を実行してログを確認してみます。

$ psql
postgres=# SELECT * FROM pg_roles;

$ sudo tail /var/log/postgresql/postgresql-`date +%Y-%m-%d`.log
>LOG:  duration: 0.056 ms  plan:
    Query Text: SELECT * FROM pg_roles;
    Nested Loop Left Join  (cost=0.15..9.19 rows=1 width=119)
      ->  Seq Scan on pg_authid  (cost=0.00..1.01 rows=1 width=87)
      ->  Index Scan using pg_db_role_setting_databaseid_rol_index on pg_db_role_setting s  (cost=0.15..8.17 rows=1 width=36)
            Index Cond: ((setdatabase = 0::oid) AND (pg_authid.oid = setrole))

ちゃんと実行計画が記録されていますね。

問題なければ本来の値を設定します。 log_min_duration_statement と同じ値を設定しておけばいいと思います。

$ sudo vi /var/lib/pgsql/9.3/data/postgresql.conf
auto_explain.log_min_duration = 1s

すでにモジュールはロードされているので、PostgreSQL サーバをリロードすれば反映されます。

$ sudo service postgresql-9.3 reload

$ sudo tail /var/log/postgresql/postgresql-`date +%Y-%m-%d`.log
>LOG:  received SIGHUP, reloading configuration files
>LOG:  parameter "auto_explain.log_min_duration" changed to "1s"