PostgreSQLで遅いSQLの実測情報付き実行計画をauto_explainを用いて自動で取得し、New Relicで確認する方法について紹介します。
はじめに
データベースのパフォーマンストラブルは経験ありますか。なぜか時間経過により遅くなるSQL、特定の時間帯や条件で特に遅くなるSQLなど...。その際は、データベースで起きている情報を一つ一つ収集し、事実を元に何が起きているかを判断し対処する必要があります。
遅いSQLが特定できれば、原因を調べるためによく利用するのは実行計画です。実行計画を確認すると、非効率にクエリが実行されているような原因を特定することができます。
PostgreSQLの実行計画は、データ量やカーディナリティ、パラメータ値によって変化することがあります。New Relicが提供しているDatabase 360の機能で取得しているEXPLAINの実行計画でも基本的な問題は解析できます。ただ、処理行数が推定であることや、問題が発生した時の実行計画と異なる場合があるため、複雑な課題を抱えているSQLに対してはEXPLAIN ANALYZEの実測値付き実行計画を見る必要があります。
以下はEXPLAINとEXPLAIN ANALYZEの簡単な比較です。
| 比較項目 | EXPLAIN | EXPLAIN ANALYZE |
|---|---|---|
| 実行計画 | SQLを実行せず、プランナーが選択した計画を表示 | SQLを実際に実行し、その実行で使われた計画を表示 |
| 確認できる情報 | スキャン方法・結合方式、推定行数・コストなど | 左記に加え、実際の処理行数・繰り返し回数。処理時間やバッファ使用状況などは設定に応じて表示 |
| 取得方法 | 手動でEXPLAINを実行。またはNew RelicではDatabase 360（NRDOT）の機能で自動収集 | 手動でEXPLAIN ANALYZEを実行。またはauto_explainで実測情報付きの計画をログに自動記録 |
この課題を解決するのがauto_explainというPostgreSQLの拡張機能です。この機能を使うと、設定した閾値の実行時間を超えたSQLの実測情報付き実行計画（EXPLAIN ANALYZE）を、実際に実行されたクエリから取得することができます。そのため、複雑なパフォーマンス問題の再現に勤しむことなく、遡って詳細な解析をすることができます。
今回は、auto_explainの設定と、出力したログをNew Relicへ転送し加工する設定、およびダッシュボード上で表示する方法を紹介します。
注意ポイント：
-
auto_explainを設定するとDBへの負荷がかかるため、利用する際は検証環境を利用する、本番に入れる際は取得設定を調整するなど十分に負荷量は検証して利用してください。
-
auto_explainの結果はSQLの中の値など難読化されていない機密情報が含まれる可能性があります。New RelicではLogs機能で難読化処理、Partitionのデータアクセスポリシーでユーザアクセスを制限する方法もありますが、セキュリティ面は留意して利用してください。
無料のアカウントで試してみよう！
New Relic フリープランで始めるオブザーバビリティ！
設定方法
今回はLinuxのセルフホストで建てたPostgreSQL16で設定しています。設定名や使用できるオプションはPostgreSQLのバージョンで変わる可能性があるので各々確認してください。
本記事では、postgresql.confで設定しDB全体に適用する例を示します。他にもALTER ROLE "user_name" IN DATABASE "database_name" SET XXで対象のユーザ、DBに限定して設定する方法もあるので、ユースケースに応じて設定は変更して利用してください。
前提事項
- New Relicの設定を変更できる管理権限
- PostgreSQLのホストにNew Relic Infrastructure Agentを導入していること
実際に何をやっているか？
auto_explainの設定を導入し、ある閾値以上の時間がかかったSQLの実行計画をホスト環境のログに書き込みます。その後、Infrastructure AgentのFluent Bitを利用してNew Relicにログを転送し、LogsのParsing機能で実行時間、SQLクエリ、実行計画に分類しダッシュボード上で見やすくして解析できるようにします。
auto_explainの設定
postgresql.confのshared_preload_librariesにauto_explainを追加しモジュールを読み込みます。
shared_preload_libraries = 'auto_explain'
他のライブラリが設定されている場合は、既存の値を残したままカンマ区切りで追加してください。
ここではログに出す閾値や出力の設定方法を定義します。
# 指定した閾値以上のSQLの実行計画を記録する。ここでは例として1秒とする。
auto_explain.log_min_duration = '1s'
# 実際の行数など、実行時の情報を含める
auto_explain.log_analyze = on
# ノードごとの時間計測を無効にする。（計測負荷を抑える）
auto_explain.log_timing = off
# バッファ使用状況を含める
auto_explain.log_buffers = on
# 計画の本文はテキスト形式で記録する。json形式でも可能
auto_explain.log_format = 'text'
# サンプリングレートを設定する。ここでは仮で1.0として全て取得する設定とする。
auto_explain.sample_rate = 1.0
# バインドパラメーターの値をログに含めない
auto_explain.log_parameter_max_length = 0
特に注意して設定するポイントはauto_explain.log_min_durationの閾値、auto_explain.sample_rateのサンプリングレートです。この2つの値を調整し、検証環境などで問題ないか負荷を確認してください。
auto_explain.log_formatはjson形式にすることも可能ですが、今回はtext形式で出力するようにしています。理由として、json形式にすることでログ量が増えやすく、この後New Relicに送付する際にattributeの文字数の最大値4,094文字を超過するとBlobに保存され、超過分は検索対象から外れる仕様になっているためです。今回は、根本解決ではないですがそれをできる限り抑えるためにtext形式にしています。（余談ですが個人的な意見として実行計画はtextの方が見やすいです。機械処理的にはjsonが好きなようですが）
PostgreSQLのログ全体をJSON形式で出力する
postgresql.confで、PostgreSQLのログ全体をJSON形式で出力するようにします。
logging_collector = on
log_destination = 'jsonlog'
PostgreSQLの出力形式をjsonにしている理由は、以下画像のようにstderrだとSQLや実行計画が1行に収まらず関係がわかりづらくなるため、json形式で出力するようにしています。
既存のログ出力形式がstderrを使用しており、JSONログにすることで何かしら問題が発生する場合は、stderrと並行でjsonのログを出力させるか、もしくはstderr形式でFluent BitのMultiline Parserを使って複数行をマージする方法で対応できる可能性がありますが、検証が必要です。
設定を反映するため、PostgreSQLを再起動します。
sudo systemctl restart postgresql
Infrastructure Agentでログを転送する
新しく出力されるjsonログをNew Relicに転送する必要があります。
今回は、PostgreSQLのホストに/etc/newrelic-infra/logging.d/postgresql-autoexplain.ymlを以下のように作成します。
logs:
- name: postgresql-json
file: /var/lib/pgsql/16/data/log/postgresql-*.json
max_line_kb: 256
attributes:
logtype: postgresql-json
fileのパスは、PostgreSQLの出力場所に合わせて任意で変更します。既存のPostgreSQLログ収集設定がある場合は、既存の方の設定を変更するなどして、重複しないことを確認してください。
LogsのParsingでSQL・実行時間・実行計画を分ける
New Relicに取り込む際、Parsing機能を用いて実行計画の情報を見やすくします。
取り込まれたログのmessageにはSQL本文、実行時間、実行計画が入っているのでParsingで別々の属性に分けます。
New RelicのLogs->Parsingでカスタムルールを作成し、解析対象のフィールドをmessageにします。対象ログを絞り込む条件は次のとおりです。
logtype = 'postgresql-json'
AND message LIKE '%Query Text:%'
AND message LIKE '%plan:%'
次の画面でWrite your own ruleには以下を入力します。
(?s)^duration: *%{NUMBER:execution_time_ms:float} +ms +plan:\nQuery Text: %{DATA:sql_query}\n(?=[A-Z][^\n]*[ \t]+\(cost=)%{GREEDYDATA:execution_plan}$
| 属性 | 内容 |
|---|---|
| execution_time_ms | ログ先頭の実行時間（ミリ秒、数値） |
| sql_query | SQL本文 |
| execution_plan | 実測行数などを含む実行計画 |
このParsingルールは新しく取り込まれるログに適用されます。
SQL本文に同様の文字列がある場合や出力形式が異なる場合には動かない場合があるため、環境に合わせて設定してください。
ダッシュボードで遅いSQLと実行計画を確認する
ダッシュボードのウィジェットを、次のNRQLを使って作成します。今回はSQL検索ができる条件でクエリを作成します。
以下のNRQLは収集したログをSQL本文ごとに集計します。ここで実行計画は複数ある場合、サンプルとしてlatestの1つを持ってきています。また平均、最大はauto_explainで収集された統計です。
FROM Log
SELECT
count(*) AS '取得件数',
average(execution_time_ms) AS '平均ms',
max(execution_time_ms) AS '最大ms',
latest(execution_plan) AS '実行計画'
WHERE logtype = 'postgresql-json'
AND execution_time_ms IS NOT NULL
AND sql_query LIKE {{sql_filter}}
FACET sql_query
SINCE 7 days ago
LIMIT 30
以下は個別のSQLに対する実行時間と実行計画を出力した表です。ダッシュボード上だと実行計画は長くて見切れるので、Chart typeはLog Tableにすると詳細を確認できます。
FROM Log
SELECT
timestamp,
sql_query AS 'SQL',
execution_time_ms AS '実行時間(ms)',
execution_plan AS '実行計画'
WHERE logtype = 'postgresql-json'
AND execution_time_ms IS NOT NULL
AND execution_plan IS NOT NULL
AND sql_query LIKE {{sql_filter}}
SINCE 7 days ago
LIMIT 100
Dashboardの変数の設定は以下とします。
実際に設定するとこちらになります。画像では、UPDATEの文字列が含まれるSQLを検索し、その統計値と実行計画の一覧を出力しています。
今回は検証のため閾値を1.0 msecにしているため、複数同じ実行計画ばかりであまり面白くありませんが、実際は閾値を超えたSQLのみに対して、実測値付き実行計画を取得できます。この情報を参照しSQLの改善点を調査、さらにはDatabase 360を導入いただければDBのロックやコネクション数を見ることができるため、データベースの複雑なパフォーマンスの原因調査を行うことができます。
おわりに
auto_explainを使うと、PostgreSQLの遅いSQLの実測値付き実行計画を自動で収集し、New Relicで確認することができます。基本的にはEXPLAINの実行計画で解決できる場合が多いので使う機会は限られるかもしれませんが、再現性が少ない場合や、ピーク負荷時や特定の条件でのみSQLの実行時間が増えるなど実際に実行された時の実行計画が取りたい場合にauto_explainは効果的に利用することができます。
また、合わせてNew RelicのDatabase 360の機能を利用することでEXPLAINの実行計画、ロックおよびコネクション数などDBに関する詳細な情報を見ることができるため、詳細な解析を行う際はぜひ組み合わせて解析することをお勧めします。
