Using DTrace to measure Apache request processing time

While fiddling with Apache and DTrace this week, I wrote a script (requestime.d) to measure the time it takes to read and process each request sent to an httpd process:

$ dtrace -q -32 -s requestime.d -p `pgrep httpd`
Processed / in 3023 microseconds
Processed /apache_pb.gif in 752 microseconds

$ cat requestime.d

pid$target::ap_read_request:entry
{
   self->apread = 1;
}

pid$target::apr_time_now:entry
/ self->apread /
{
   self->ts = timestamp;
   self->apread = 0;
}

pid$target::ap_read_request:return
{
    self->method = arg1 == 0 ? "Unknown" : 
                   copyinstr(*(uintptr_t *)copyin(arg1 + 72, sizeof(uintptr_t)));

    self->uuri   = arg1 == 0 ? "Unknown" : 
                   copyinstr(*(uintptr_t *)copyin(arg1 + 200, sizeof(uintptr_t)));
}

pid$target::ap_process_request:return
{
    printf("Processed %s in %d microseconds\n", self->uuri, (timestamp - self->ts) / 1000);

    self->uuri = 0;
    self->ts = 0;
}

Writing DTrace scripts is fun!

3 thoughts on “Using DTrace to measure Apache request processing time”

  1. Hi,

    First, Congratulations by script.
    But, What’s DTrace ???
    I haven’t listen to DTrace.

    Thank you
    Ricardo

Leave a Reply

Your email address will not be published. Required fields are marked *