An Apache module to measure && log the time taken by Apache handlers

gistfile1.c

/* 
**  mod_mod_handler_time.c -- Apache sample mod_handler_time module
**  [Autogenerated via ``apxs -n mod_handler_time -g'']
**
**  To play with this sample module first compile it into a
**  DSO file and install it into Apache's modules directory 
**  by running:
**
**    $ apxs -c -i mod_mod_handler_time.c
**
**  Then activate it in Apache's httpd.conf file for instance
**  for the URL /mod_handler_time in as follows:
**
**    #   httpd.conf
**    LoadModule mod_handler_time_module modules/mod_mod_handler_time.so
**    <Location /mod_handler_time>
**    SetHandler mod_handler_time
**    </Location>
**
**  Then after restarting Apache via
**
**    $ apachectl restart
**
**  you immediately can request the URL /mod_handler_time and watch for the
**  output of this module. This can be achieved for instance via:
**
**    $ lynx -mime_header http://localhost/mod_handler_time 
**
**  The output should be similar to the following one:
**
**    HTTP/1.1 200 OK
**    Date: Tue, 31 Mar 1998 14:42:22 GMT
**    Server: Apache/1.3.4 (Unix)
**    Connection: close
**    Content-Type: text/html
**  
**    The sample page from mod_mod_handler_time.c
*/ 

#include "httpd.h"
#include "http_config.h"
#include "http_protocol.h"
#include "apr_strings.h"
#include "ap_config.h"
#include "http_log.h"

/* The sample content handler */
static int mod_handler_time_handler(request_rec *r)
{
    if (strcmp(r->handler, "mod_handler_time")) {
        return DECLINED;
    }

    apr_table_setn(r->notes, "HANDLER_TIME", apr_ltoa(r->pool, apr_time_now()));
    return DECLINED;
}

static int mod_handler_log_transaction(request_rec *r)
{
    apr_time_t before   = apr_atoi64(apr_table_get(r->notes, "HANDLER_TIME"));
    apr_time_t now      = apr_time_now();
    apr_time_t duration = now - before;
    const char *msec = apr_psprintf(r->pool, "%" APR_TIME_T_FMT ".%" APR_TIME_T_FMT, apr_time_sec(duration), apr_time_msec(duration));
    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "%ld - %ld = %ld %s", before, now, duration, msec, NULL);
    apr_table_setn(r->notes, "HANDLER_TIME", msec);
    return DECLINED;
}

static void mod_handler_time_register_hooks(apr_pool_t *p)
{
    ap_hook_handler(mod_handler_time_handler, NULL, NULL, APR_HOOK_REALLY_FIRST);
    ap_hook_log_transaction(mod_handler_log_transaction, NULL, NULL, APR_HOOK_REALLY_FIRST);
}

/* Dispatch list for API hooks */
module AP_MODULE_DECLARE_DATA mod_handler_time_module = {
    STANDARD20_MODULE_STUFF, 
    NULL,                  /* create per-dir    config structures */
    NULL,                  /* merge  per-dir    config structures */
    NULL,                  /* create per-server config structures */
    NULL,                  /* merge  per-server config structures */
    NULL,                  /* table of config file commands       */
    mod_handler_time_register_hooks  /* register hooks                      */
};

 ~/httpd-2.2.22/bin/httpd -X -c'ErrorLog /dev/fd/1' -c'CustomLog /dev/fd/1 common'

    LogFormat "@ %{HANDLER_TIME}n %h %l %u %t \"%r\" %>s %b" common