雑記

Web屋のネタ帳 - Apacheのログ出力に追加しておいたほうがいい（かもしれない）設定

%D リクエストを処理するのにかかった時間、マイクロ秒単位

「あるページだけが異様に重い気がするんだけど？」といった場合に体感スピードではなくその正確な値を得ることができる。純粋にWebアプリ的な処理時間であってネットワーク的な遅延時間などはこれじゃ取れないけど。なお、「%T リクエストを扱うのにかかった時間、秒単位」というのもあるんだが、「処理するのにかかった時間」と「扱うのにかかった時間」がどう違うのかわからん（笑）。いずれにせよ秒単位よりはマイクロ秒単位のほうがいいだろう。

• %T ... リクエストを扱うのにかかった時間、秒単位
• %D ... リクエストを処理するのにかかった時間、マイクロ秒単位

ということなので、%Tと%Dで精度以外に何か違うのか気になったので調べてみた。

結論としてマニュアルの日本語訳にブレがあるだけだと分かった。

%Tも%Dも apr_time_now() - r->request_time から算出していて、返す精度が違うだけ。

// httpd-2.0.63/modules/loggers/mod_log_config.c　の冒頭のコメント部分
// たぶんここを訳してる

* %...T: the time taken to serve the request, in seconds.
* %...D: the time taken to serve the request, in micro seconds.

// httpd-2.0.63/modules/loggers/mod_log_config.c
// 実際に算出してる箇所のソース
// apr_time_sec()があるかないかの違い

static const char *log_request_duration(request_rec *r, char *a)
{
    apr_time_t duration = apr_time_now() - r->request_time;
    return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, apr_time_sec(duration));
}

static const char *log_request_duration_microseconds(request_rec *r, char *a)
{
    return apr_psprintf(r->pool, "%" APR_TIME_T_FMT,
                        (apr_time_now() - r->request_time));
}

まあつまり、たまにはapacheのソース眺めてみるのも悪くないんじゃないかということで。

(2.0.63のソースになってるけど、2.2.11でも同じだった)