Apacheモジュールの処理時間を計測

Apacheモジュールの処理時間を計測する方法を少しでも楽にできないかと考えてみました。

使い方

後述のprofile.cを includeします。

モジュール中のハンドラにおいて、測定したい箇所で、下のように書きます。
２番目の引数は、結果表示時の並び順に使っています。

    SET_TIME_PROFILE(r, "1");

結果を出力するのはlog_transactionのハンドラ辺りでよいでしょう。

    out_time_profile(r);

とすれば結果が表示されます。

結果表示例

[notice] __profile__( sec):1mymodule_type_checker:1135155196
[notice] __profile__(usec):1mymodule_type_checker:745692
[notice] __profile__( sec):2mymodule_type_checker:1135155196
[notice] __profile__(usec):2mymodule_type_checker:745761
[notice] __profile__( sec):3mymodule_type_checker:1135155196
[notice] __profile__(usec):3mymodule_type_checker:751812
[notice] __profile__( sec):4mymodule_handler:1135155196
[notice] __profile__(usec):4mymodule_handler:751907
[notice] __profile__( sec):5mymodule_handler:1135155196
[notice] __profile__(usec):5mymodule_handler:751913
[notice] __profile__( sec):6mymodule_handler:1135155196
[notice] __profile__(usec):6mymodule_handler:751919
[notice] __profile__( sec):7mymodule_handler:1135155196
[notice] __profile__(usec):7mymodule_handler:762555

profile.c

#ifdef TIME_PROFILE
#define SET_TIME_PROFILE(r, prefix) set_time_profile(r, prefix, __func__);
#else
#define SET_TIME_PROFILE //
#endif

int iterate_out_time_profile(void* req, const char* key, const char* value)
{
    request_rec* r = (request_rec*)req;
    if (strstr(key, "__profile__") == NULL) return 1;
    TRACE("%s:%d", key, value);
    return 1;
}

void out_time_profile(request_rec* r)
{
    apr_table_do(iterate_out_time_profile, r, r->notes, NULL);
}

void set_time_profile(request_rec* r, const char* prefix, const char* key)
{
    struct timeval tv;
    struct timezone tzp;
    char* key1 = apr_psprintf(r->pool, "__profile__( sec):%s%s", prefix, key);
    char* key2 = apr_psprintf(r->pool, "__profile__(usec):%s%s", prefix, key);
    gettimeofday (&tv, &tzp);
    apr_table_setn(r->notes, key1, (char*)tv.tv_sec);
    apr_table_setn(r->notes, key2, (char*)tv.tv_usec);
}

ポイント

gettimeofdayの結果をr->notesに格納しています。
tableへのセットのときに、keyに特定文字列を埋め込んで、apr_table_doのiterateのときに使用しています。

感想とか

もう少し、調整して全公開したほうがよいだろうか。
module開発者の皆様のご感想をお待ちしております。