Apache1.3の処理経過時間をマイクロ秒で記録する

By Hiroyuki OYAMA Wed Feb 9 01:57:04 2005

Apache 2.0はリクエスト処理の所要時間を秒単位(%T)とマイクロ秒単位(%D)で記録できますが、Apache 1.3の場合は秒単位(%T)でしか記録できません。ってなわけでApache 1.3でマイクロ秒精度で記録する方法。

AP20とAP13の時間の管理方法

Apache 2.0系の場合、内部的にマイクロ秒単位で時間を管理しているのでLogFormatディレクティブで%Tで秒単位、%Dでマイクロ秒単位で処理の所要時間を記録できます。その点Apache 1.3の場合は内部的に秒単位で時間を管理しているため秒単位でしか記録できません。ではどうすれば記録できるようになるのか？そこはやはりモジュールをチョロっと書くのです。

Apache1.3でマイクロ秒のログを出力するには

自分でゼロからmod_log_config相当のモジュールを書くことでも対応できますが、さすがにそれは面倒です。というわけで今回はリクエスト処理の所要時間を計測し、その結果をApacheの環境変数にセットしログに記録する方法で対応してみます。

まずやることは、リクエスト処理サイクルの最初の方のap_run_post_read_requestフェーズで、基準となるマイクロ秒精度の時刻を記録します。最近のPOSIX準拠な環境ならgettimeofday()が使えるので、これを使ってマイクロ秒単位の時刻が取得できます。取得した時刻はrequest_rec構造体のnotesフィールドにでもセットしておきましょう。だいたいこんな感じのハンドラ関数になります。

 static int begin_msec_count(request_rec *r)
{
    struct timeval *stime;
    int rc;

    if (!ap_is_initial_req(r))
        return DECLINED;

    stime = ap_pcalloc(r->pool, sizeof(struct timeval));
    rc = gettimeofday(stime, NULL);
    if (rc == -1) {
        return DECLINED;
    }

    ap_table_setn(r->notes, "REQUEST_MICRO_SECONDS", (const char *)stime);

    return OK;
}

今度はリクエストの処理が終わったap_log_transactionフェーズで、もう一度gettimeofday()で時刻を取得し、事前に記録しておいた処理開始時点の時刻と比較して所要時間を計算します。

 static int end_msec_count(request_rec *r)
{
    struct timeval *stime, etime;
    int rc;
    const char *msec;
    double start, end;

    stime = (struct timeval *)ap_table_get(r->notes, "REQUEST_MICRO_SECONDS");
    if (stime == NULL) {
        return DECLINED;
    }
    rc = gettimeofday(&etime, NULL);
    if (rc == -1) {
        return DECLINED;
    }

    start = stime->tv_sec + stime->tv_usec * 1e-6;
    end   = etime.tv_sec  + etime.tv_usec * 1e-6;

    msec = ap_psprintf(r->pool, "%.6f", end - start);
    while (r->next)
        r = r->next;
    ap_table_setn(r->subprocess_env, "D", msec);
    return OK;
}

で、最後のap_table_setn(r->subprocess_env, "D", msec)がミソなのですが、計算したマイクロ秒精度の処理所要時間を環境変数"D"にセットします。これによってLogFormatディレクティブで

 LogFormat "%{D}e"

といった記述でマイクロ秒精度の所要時間をログに出力することができるようになります。

と、こんな感じで標準のmod_log_configモジュールが環境変数などをログに出力できる機能を利用して、任意の情報の出力を実現するモジュールが記述できるわけです。独自にログ出力モジュールを開発するのも手ですが、既存のモジュールにオンブにダッコさせてもらった方が楽ですよね。
完成版のコードは