Measuring Apache request processing time

I support a fair number of Apache web server instances, and periodically need to measure the time it takes Apache (and it’s various modules) to process a request. On Solaris 10 hosts, I can use DTrace to retrieve this information on the fly. Since Solaris 9 and CentOS and Redhat Linux don’t come with DTrace, I use a different approach on these platforms.

To get the time when each request was received by Apache, I used mod_header’s “Header” directive, and “%t” option (time when a request was received, measured in milliseconds from the epoch), to add a response header with the time each request was received:

Header set X-Request-Received: %t

To get the total time Apache spent processing a request, I use mod_header’s “Header” directive, and “%D” option (milliseconds spent processing the request), to add a response header with the total time Apache spent processing each request:

Header set X-Request-Processing-Time: %D

Since I don’t always need the headers to be present, I like to be able to enable and disable them from the command line. The easiest way to do this is by enclosing the directives in a conditional block similar to the following:

<IfDefine RequestTime>
     Header set X-Request-Received: %t
     Header set X-Request-Processing-Time: %D

And using the httpd “-D” option to enable them:

$ httpd -k start -DRequestTime

After the headers are enabled, you will see entries similar to the following in each HTTP response:

$ curl -v

* About to connect() to port 8080

< ..... >

< HTTP/1.1 200 OK
< Date: Tue, 02 Jan 2007 17:59:42 GMT
< Server: Apache/2.2.3 (Unix) DAV/2
< Last-Modified: Sat, 20 Nov 2004 20:16:24 GMT
< ETag: "34d37-2c-4c23b600"
< Accept-Ranges: bytes
< Content-Length: 44
< X-Request-Received: t=1167760782452525
< X-Request-Processing-Time: D=3513
< Content-Type: text/html
* Connection #0 to host left intact
* Closing connection #0

Similar capabilities are available for measuring request processing time on the client. Total time is helpful, but knowing how much of that time was consumed by Apache is invaluable!

8 thoughts on “Measuring Apache request processing time”

  1. Is there a way to log these numbers? I am more interested to know processing time of other’s requests rather than that of mine.

    It is interesting that Apache 2.0 docs says that “%t” in the log is “The time that the request was received”, and docs for 1.3 say that it is “The time that the server finished processing the request.” Have they actually changed it, or just did not bother with the request processing time?

  2. Hi,
    what is the time format recorded I got some thing like 3062 403 5043
    what is the meaning of it.

  3. What you would really need …
    Have a close look at those additional nrg-fields at apache-log-file:

    6 : – – [12/Aug/2011:11:48:01 +0200] “GET /aomi/nrg8_linux_history_process.php HTTP/1.0” 200 1 nrg88_task_id=1313142481.1535 nrg88_resptime=0.470 nrg88_storage_usage=27.263 528701

    7 : – – [12/Aug/2011:11:47:01 +0200] “GET /aomi/nrg8_linux_process_pyramid.php HTTP/1.0” 200 16594 nrg88_task_id=1313142421.0537 nrg88_resptime=1.079 nrg88_storage_usage=2.272 nrg88_mysql_questions=18 nrg88_group=B4 1086981

    8 : – – [12/Aug/2011:11:45:01 +0200] “GET /cgi-bin/nrg8_linux_cgi_nmap HTTP/1.0” 200 529 – 155092

    (I cannot demonstrate my complete realtime-monitor due to lack of space and editor capabilities i.e. no graphics.)
    In case you are interested in my details please contact me via email.

    Good luck,

Leave a Reply

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