myfinderの技術や周辺的活動のblog

2009年7月15日水曜日

Apache1.3系の処理時間を出力するコードについて少し追ってみる

Apache1.3のログフォーマットの指定に「%T」を追加すると、各リクエストの処理時間を秒単位でログに出力することが出来る。
が、大抵のリクエストは1秒以内で終わるので、大抵0になってしまう。

ここで気になったのが、1秒に満たない場合どこまでを0秒として扱っているのかという点。
つまり四捨五入なのか小数点以下切り捨てなのかなどなど。

あまりググっても出てこなかったので、ソースを開いてみた。
(C&C++バリバリわかる!とかApacheのソースコードバリバリわかる!というわけじゃないので間違った認識だったりしたら突っ込みいただけるとうれしいです)

LogFormatの指定については「src/modules/standard/mod_log_config.c」に書かれている。

static struct log_item_list {
char ch;
item_key_func func;
int want_orig_default;
} log_item_keys[] = {

{
'a', log_remote_address, 0
},
{
'A', log_local_address, 0
},
{
'b', clf_log_bytes_sent, 0
},
{
'B', log_bytes_sent, 0
},
{
'c', log_connection_status, 0
},
{
'e', log_env_var, 0
},
{
'f', log_request_file, 0
},
{
'h', log_remote_host, 0
},
{
'H', log_request_protocol, 0
},
{
'i', log_header_in, 0
},
{
'l', log_remote_logname, 0
},
{
'm', log_request_method, 0
},
{
'n', log_note, 0
},
{
'o', log_header_out, 0
},
{
'p', log_server_port, 0
},
{
'P', log_child_pid, 0
},
{
'q', log_request_query, 0
},
{
'r', log_request_line, 1
},
{
's', log_status, 1
},
{
't', log_request_time, 0
},
{
'T', log_request_duration, 1
},
{
'u', log_remote_user, 0
},
{
'U', log_request_uri, 1
},
{
'v', log_virtual_host, 0
},
{
'V', log_server_name, 0
},
{
'X', log_connection_status, 0
},
{
'\0'
}
};

これの

{
'T', log_request_duration, 1
},

が対応する関数を呼び出しているようで、その関数が

static const char *log_request_duration(request_rec *r, char *a)
{
return ap_psprintf(r->pool, "%ld", time(NULL) - r->request_time);
}

というような実装だった。
time関数による現在時間とリクエストのあった時間を引いている。
この関数って精度が1秒だったかな?なので、1秒に満たない場合は0として扱われると捉えてOKかなと。

すなわち、1秒に満たない場合は0、1秒以上2秒以下の場合は1と表示されるはず。

0 件のコメント: