How to log request processing times in Apache

If you have an apache (2) web server, you probably have an access.log file showing you all kinds of data using the "combined" log format. Let's see how to include processing time into that log file.

By default a line in the combined log looks like this:

Notice the 2 dashes - - just after the IP. The first one stands for "I could not identify the user using ident" and the second one for "no user authentication was performed".

Now, let's face it: you will never identify anyone using ident. Your apache conf probably even doesn't try. That field is a left over from ancient times. So let's replace that first dash with something useful, i-e: the processing time of the request! Note that by doing this we keep the global structure of the file identical and any log processing tool you might be using should not be affected.

So, in your apache2.conf file, look for this line:

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined

And replace it with:

LogFormat "%h %D %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined

(More specifically, we changed the second field from %l to %D)

Now, restart apache and look at your logs! Your log lines should now look like:

 "GET /info-tech/ HTTP/1.1" 200 46482 "http://fplanque.com/info-tech/" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.1.5) Gecko/20091102 Firefox/3.5.5"

96395 is the time in microseconds. In other words, the request took 96 ms to be processed. Note that, depending on whether Apache's Send Buffer fills up or not, this may include the time needed to send the data back to the requesting party, so it depends heavily on the location of the requester, buffer sizes, the route used, MTU sizes, TCP window sizes, etc. all along the way...

You may see significant changes if you request the same URL through different proxies and look at your logs.

Quick tip: one way to filter your logs while you do this:

tail -f /some_path/access.log | grep "GET /info-tech/ HTTP"

Comments from long ago:

Comment from: Matt

thank you!

2010-10-09 00-57

Comment from: Sandeep

This helped a lot. As you say %D includes even network latency etc, how to measure only apache process time of request/response ? coz some times to figure out that its not application or web server taking most of the process time, actually its network who’s the culprit..

thanks,

2011-07-14 15-12