[pgsql-jp: 40307] Re: SQL処理時間の計測について

[Takahiro Itagaki]

こんにちわ。pg_stat_statements の作者です :-)

戸川　一成 <togawa ＠ kdl.co.jp> wrote:

> > 4 と 3 は同じになりそうなのですが、顕著な差がでましたでしょうか？
> > pg_stat_statements の作者の方からコメントがあるかもしれません。
> 
> ２．と４．はほぼ同じ(誤差は±1ms)です。
> 
> ですが、３．と４．では以下の違いがありました。
> ３．の結果：1011.281 ms
> ４．の結果： 765.851 ms

ざっと調べてみましたが、1 > 3 > 2 = 4 となるのは、内部の動作と
照らし合わせても妥当だと思いました。それぞれのタイマの開始/終了
タイミングと、内部の処理を一覧にすると以下のようになっていました。

<始> 1.psql \timing
            クエリ送信＋受信
<始> 3.ログ出力結果
            トランザクションの開始
            SQL解析 (Parser)
            実行計画の生成 (Planner)
<始> 2.explain analyze / 4.pg_stat_statements
            実行計画の実行 (Executor)
<終> 2.explain analyze / 4.pg_stat_statements
            結果送信
            トランザクションの完了
<終> 3.ログ出力結果
            結果受信
<終> 1.psql \timing
            psql 画面表示

アプリケーションの最終的な総合レスポンスは、1 で見ることになります。
ネットワークを無視して DB 内の処理時間に限るなら 3 が妥当でしょうか。

ただ、2.EXPLAIN はもともと重いクエリ (I/Oやソート) の個別解析用なので
Parser や Planner にかかる時間は相対的に小さいでしょうし、
4.pg_stat_statements も準備済み文 (prepared statement) で利用すれば、
Parser や Planner の結果がキャッシュされるため、影響は小さくなります。
どちらも「もともと想定される使い方」では、3.との差は小さくなると思われます。

------------------------------------------------------------
NTT オープンソース ソフトウェア センタ
板垣貴裕 <itagaki.takahiro ＠ oss.ntt.co.jp>