【PostgreSQL】psqlでクエリの実行時間を計測する

\timingでクエリの実行時間を表示する

psqlの\timingメタコマンドは、それ以降に実行した各クエリの実行時間を結果の下に表示する。引数なしで実行するとon/offをトグルする。

testdb=# \timing
Timing is on.
testdb=# SELECT count(*) FROM users;
 count
-------
     2
(1 row)

Time: 2.302 ms

Time: に続けてミリ秒単位の実行時間が表示される。もう一度\timingを実行するとオフに戻る。

testdb=# \timing
Timing is off.
testdb=# SELECT count(*) FROM users;
 count
-------
     2
(1 row)

on/offを明示的に指定する

トグルだと現在の状態を意識する必要があるため、明示的にオン/オフを指定する場合は\timing on/\timing offを使う。

testdb=# \timing on
Timing is on.
testdb=# \timing off
Timing is off.

1秒を超えると分・時間表示も併記される

実行時間が1秒(1000ミリ秒)を超えると、ミリ秒表示に加えて分:秒形式の表示が括弧書きで併記される。

testdb=# \timing
Timing is on.
testdb=# SELECT pg_sleep(1.3);
 pg_sleep
----------

(1 row)

Time: 1302.674 ms (00:01.303)

1分を超える場合は時:分:秒形式になる。長時間かかるバッチ処理やマイグレーションの所要時間を確認する際に、ミリ秒表示だけより読み取りやすい。

計測対象はサーバーの処理時間だけではない

\timingが計測するのは、クエリの送信からpsqlが結果を受け取って表示し終えるまでの時間である。ネットワークのラウンドトリップや、psql側での結果整形にかかる時間も含まれる。

サーバー側での純粋な実行時間だけを知りたい場合はEXPLAIN ANALYZEを使う。

testdb=# EXPLAIN ANALYZE SELECT count(*) FROM users;
                                              QUERY PLAN
-------------------------------------------------------------------------------------------------
 Aggregate  (cost=1.02..1.02 rows=1 width=8) (actual time=0.021..0.022 rows=1 loops=1)
   ->  Seq Scan on users  (cost=0.00..1.02 rows=2 width=0) (actual time=0.010..0.011 rows=2 loops=1)
 Planning Time: 0.042 ms
 Execution Time: 0.038 ms

\timingのTime:とEXPLAIN ANALYZEのExecution Time:は測定範囲が異なるため、通常は\timingの方が長い値になる。大量の結果行を\xなしで画面に表示する場合など、psql側の表示処理が重いケースではその差が顕著になる。

参考: 【PostgreSQL】EXPLAIN ANALYZEで実測値を確認する

起動時からタイミング表示を有効にする

毎回\timingを入力する代わりに、~/.psqlrcに記述しておくと起動時から有効になる。

\timing on

-cオプションで1回だけクエリを実行する場合も、~/.psqlrcに書いておけば実行時間が表示される。

$ psql -d testdb -c "SELECT count(*) FROM users;"
Timing is on.
 count
-------
     2
(1 row)

Time: 1.168 ms

具体例: 複数のクエリを比較する

インデックスの有無による実行時間の違いなど、同じテーブルに対する複数クエリを比較する場合は\timingを有効にしたまま連続して実行すると効率がよい。

testdb=# \timing on
Timing is on.
testdb=# SELECT * FROM users WHERE email = 'alice@example.com';
Time: 1.324 ms
testdb=# CREATE INDEX users_email_idx ON users (email);
CREATE INDEX
Time: 4.305 ms
testdb=# SELECT * FROM users WHERE email = 'alice@example.com';
Time: 0.479 ms

1回の計測だけでは実行環境のばらつき(キャッシュの有無など)に影響されやすいため、複数回実行して傾向を確認する。

参考

psql - PostgreSQL Documentation