PostgreSQLのクエリ実行時間計測、pg_stat_statementsのカラム名はPG13で変わってる

  • PostgreSQL
  • Performance

この記事は、構成と文章の整理にAIを使っています。
あくまで読みやすくするための補助で、内容そのものをAIにすべて任せて書いているわけではありませんが、ところどころ相談しながら整えています。

クエリの実行時間を測る方法をいくつか整理した。定番のEXPLAIN ANALYZEやpg_stat_statementsだけど、バージョン差異とか設定の重複とか、地味に見落としやすいポイントがあった。

EXPLAIN (ANALYZE)

EXPLAIN (ANALYZE) SELECT * FROM example_table WHERE example_column = 'value';

結果の最後にExecution Timeが出る。これは知ってる人が多いと思う。

注意点として、ANALYZEは実行計画を出すだけじゃなく実際にクエリを実行する。SELECTなら問題ないけど、INSERT/UPDATE/DELETEで確認したい場合はデータが本当に変わるので、トランザクションで包んでROLLBACKするのが安全。

BEGIN;
EXPLAIN (ANALYZE) UPDATE example_table SET example_column = 'x' WHERE id = 1;
ROLLBACK;

pg_stat_statements

過去に実行したクエリの統計をまとめて見れる拡張機能。

shared_preload_libraries = 'pg_stat_statements'

を設定してサーバー再起動、その後

CREATE EXTENSION pg_stat_statements;

で有効化。統計をリセットしたい場合はSELECT pg_stat_statements_reset();。

ここで一つ気づいたことがあった。集計カラムの名前がPostgreSQLのバージョンで違う。

  • PostgreSQL 13以降: total_exec_time / mean_exec_time
  • PostgreSQL 12以前: total_time / mean_time

13でプランニング時間（total_plan_timeなど）が新設されたタイミングで、実行時間側のカラムも「exec」を付けて明示的にリネームされたらしい。古い記事のクエリ例をそのまま使うとcolumn "total_time" does not existで落ちることがある。

SELECT query, total_exec_time, mean_exec_time
FROM pg_stat_statements
WHERE query LIKE 'SELECT%'
ORDER BY total_exec_time DESC
LIMIT 10;

自分の環境のバージョンがどっちなのか先に確認してから書いたほうがいい。

\timing（psql）

psqlで\timingを有効にすると、実行したクエリの直後にTime: 2.345 msのように出る。一番手軽。特に落とし穴はなかった。

ログでの計測

log_min_duration_statement = 0

だけで、すべてのクエリが実行時間付きでログに出る。閾値を設けたい場合はlog_min_duration_statement = 1000のようにミリ秒指定。

ここで一つ注意。log_statement = 'all'も一緒に有効にすると、1クエリにつきログが2行出る。log_statement側はステートメント内容だけ、log_min_duration_statement側は実行時間付きのログで、それぞれ別々に出力される。実行時間だけ知りたいならlog_min_duration_statement = 0単体で十分で、log_statement = 'all'は不要（むしろログ量が倍になって読みにくくなる）。

アプリケーション側での計測（Python例）

import psycopg2
import time


conn = psycopg2.connect("dbname=example user=example")
cur = conn.cursor()


start_time = time.time()
cur.execute("SELECT * FROM example_table")
end_time = time.time()


print(f"Execution Time: {end_time - start_time:.3f} seconds")

これはDB側の実行時間だけじゃなく、ネットワーク往復やドライバのオーバーヘッドも含んだ時間になる。「クエリの実行時間」というより「アプリから見た体感時間」に近い。DB側の純粋な実行時間を知りたいなら、EXPLAIN ANALYZEかpg_stat_statementsを使ったほうが正確。

まとめると

  • 一回だけ確認したい: EXPLAIN (ANALYZE)
  • 継続的に統計を見たい: pg_stat_statements（バージョンでカラム名が違う点に注意）
  • 対話的にさっと確認: psqlの\timing
  • 全クエリをログに残したい: log_min_duration_statement = 0（log_statement = ’all’は併用しない）
  • アプリ視点の体感時間: アプリケーション側で計測（ただしDB側の実行時間そのものではない）