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 -ppgrep 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 microsecondsn", self->uuri, (timestamp - self->ts) / 1000);
self->uuri = 0;
self->ts = 0;
}
Writing DTrace scripts is fun!