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

こんにちは。サイオステクノロジー OSS サポート担当 Y です。

PostgreSQL では複数の contrib モジュールが提供されており、必要に応じて利用することができます。

今回は contrib モジュールの 1つである auto_explain を使ってみました。(※以下の内容は PostgreSQL 10.1 をソースコードからビルドした環境にて検証/調査しています。)

(https://www.postgresql.org/docs/10/static/contrib.html)

(https://www.postgresql.org/docs/10/static/auto-explain.html)

auto_explain を利用すると “実行時間が設定した時間を超えたクエリ” の実行計画をログに出力することができ、スロークエリの原因調査やパフォーマンスチューニング等に役立てることができます。

■auto_explain のインストール

まずは auto_explain をビルドしてインストールします。

各 contrib モジュールのソースコードは、PostgreSQL の tar ボールを展開したディレクトリ配下の contrib/<モジュール名> というディレクトリに格納されているため、当該ディレクトリに移動し make 及び make install を実行します。(※make install はインストール先ディレクトリの権限等、必要に応じて root ユーザ権限で実行します。)

インストールが完了すると、<PostgreSQL のインストールディレクトリ>/lib/ 配下に auto_explain.so というファイルが格納されているはずです。

■検証

auto_explain を使うためにはモジュールをロードする必要があるので、postgresql.conf の shared_preload_libraries に ‘auto_explain’ を設定します。

併せて、auto_explain の動作に関するいくつかの設定を実施しておきます。(auto_explain.* の設定はデフォルトの postgresql.conf には記載されていないため、必要に応じて追記します)

上記設定の場合、実行に 100ms 以上の時間を要したクエリの統計情報がログに出力されます。また、EXPLAIN ANALYZE VERBOSE を実行した際に出力される情報がログに出力されます。

※今回は DB 全体 (全セッション) で auto_explain を有効にするために shared_preload_libraries を利用していますが、LOAD/ALTER ROLE SET コマンドや session_preload_libraries 等を利用して特定のセッションでのみ auto_explain を有効にすることも可能です。

postgresql.conf の設定が完了したら PostgreSQL を起動します。(既に起動している場合は再起動します)

PostgreSQL 起動後、psql にて接続し設定内容を確認してみます。

設定内容が反映されていることが確認できたので、さっそくテスト用のテーブルを作って動作を確認してみます。

ログを確認する前に、EXPLAIN ANALYZE コマンドにてそれぞれのテーブルに対して SELECT * を実行した際の実行時間を確認してみます。

“SELECT * FROM hoge” の実行時間は “0.038 ms”、”SELECT * FROM fuga” の実行時間は “144.505 ms” となっています。

今回は “auto_explain.log_min_duration = 100” という設定にしているので、実行に 100ms 以上の時間を要している “SELECT * FROM fuga” の実行計画のみがログに記録されるはずです。

では実際に上記 2つのクエリを実行し、ログを確認してみます。

上記のように実行に 100ms 以上要している “SELECT * FROM fuga” の実行計画のみが出力されていました。

このように実行に要した時間を条件としてクエリの実行計画をログに出力することが可能ですが、auto_explain.log_min_duration の値を “0” に設定することで、全てのクエリの実行計画をログに出力することも可能です。(ログの出力量が膨大になるため、あまり現実的な設定ではありませんが…)

上記の通り、auto_explain.log_min_duration に “0” を設定すると、”SELECT * FROM hoge” (実行時間 : 0.026 ms のクエリ) の実行計画もログに出力されていることが確認できました。

■最後に

auto_explain を使うと自動的に実行計画をログに記録してくれるため、バッチ処理/アプリ内等で実行されているクエリや、特定のタイミングでのみ遅延が発生するクエリ等、手動で EXPLAIN ANALYZE を実行することが難しいクエリの実行計画を取得することができます。

auto_explain を利用した場合、ログ出力の増加等 DB の性能への影響は避けられないため常に利用することは難しいかもしれませんが、クエリの遅延事象が発生した際の調査等のためにいつでも利用できるよう準備/検証を行なっておくのも良いかもしれません。

ご覧いただきありがとうございます! この投稿はお役に立ちましたか?

役に立った 役に立たなかった

0人がこの投稿は役に立ったと言っています。

コメント投稿

メールアドレスは表示されません。


*