本記事では PostgreSQL の EXPLAIN コマンドの TIMING パラメータのオーバーヘッドがどこから生じているかを解説します。
EXPLAIN コマンドの TIMING パラメータの説明を引用します。
実際のスタートアップ時間とノードで費やされた時間が追加表示されます。一部のシステムでは、システムクロックを何度も読み取るオーバーヘッドのため問い合わせがかなり低速になる可能性があります。このため、実際の時間ではなく実際の行数のみが必要であるのであれば、このパラメータはFALSEに設定する方が有益でしょう。
EXPLAIN
「システムクロックを何度も読み取るオーバーヘッド」がどの程度かを調べるために pg_test_timing ツールを利用できます。
pg_test_timing
また、pg_test_timing ツールのマニュアルには、実際のクエリを用いて EXPLAIN ANALYZE のオーバーヘッドを測定する方法も記載されています。記載を引用します。
問い合わせエクゼキュータがEXPLAIN ANALYZEを使って文を実行するとき、要約を表示する他に、個々のオペレーションについての時間計測もされます。次のpsqlプログラムで行を数えれば、システムのオーバーヘッドを調べることができます。
CREATE TABLE t AS SELECT * FROM generate_series(1,100000); \timing SELECT COUNT(*) FROM t; EXPLAIN ANALYZE SELECT COUNT(*) FROM t;測定に使ったi7-860システムでは、countの問い合わせを9.8ミリ秒で実行しましたが、EXPLAIN ANALYZEをつけたときは16.6ミリ秒かかりました。どちらの問い合わせもちょうど10万行を処理しています。この6.8ミリ秒の差は、行あたりの時間計測のオーバーヘッドが68ナノ秒であることを示しており、これはpg_test_timingによる推定値の約2倍です。この比較的小さな量のオーバーヘッドでも、countの文の完全な時間計測をすると70%長くかかりました。もっと本質的な問い合わせでは、時間計測のオーバーヘッドはあまり問題にならないでしょう。
pg_test_timing
ここで疑問に感じるのが「行あたりの時間計測のオーバーヘッド」という点です。EXPLAIN ANALYZE は計画ノードごとに要した実行時間を表示します。なのに「行あたりの時間計測」とはどういうことでしょうか？
「行あたりの時間計測」に対する回答を以下の記事で確認できます。
OnGres | EXPLAIN ANALYZE may be lying to you
この記事から要約します。PostgreSQL のクエリ実行モデルは Volcano model を採用しています。このモデルでは各ノードが全ての処理を完了してから次のノードの処理に移るのではなく、処理したタプルを上位ノードに順次渡します。このため、各ノードの実行時間は行ごとの実行時間を測定し、集計することになります。これが「行あたりの時間計測」を必要とする理由です。
さきほどの記事ではこの実装に対する懸念を以下のように示しています。
The overhead EXPLAIN ANALYZE introduces is not proportional to the real duration of the query plan, but rather proportional to the number of rows processed by the node. While they may be aligned, more rows processed does not always lead to higher execution times, and counting on this assumption may lead to believing a node is slower when it is in fact faster than another one. In turn leading to a bad query optimization strategy.
OnGres | EXPLAIN ANALYZE may be lying to you
また、auto_explain モジュールで auto_explain.log_timing を有効にしていると、クエリ実行の度に「行あたりの時間計測のオーバーヘッド」が加わることになります。このオーバーヘッドを許容できるかは慎重に判断する必要があるでしょう。
