Apache Logs: how long does it take to serve a request?
Apache is one complex piece of software, that contains many features most people are normally not using. You can do so many things with apache outside of the default configurations, and I am not going to discuss today about an external module, but about the plain old mod_log_config.
Normally most people will use for apache logging the combined LogFormat, and will not even think there will be other possible additions to that. This normally looks like:
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
and it contains most of the information we would like to see in the logs. Still there are many other information we can include here just see below for the full list.
What I would like to show here is how we can add a new parameter to the apache log and have apache log the time spent to serve the request. We just have to add %T and we will have the time taken to serve the request, in seconds!. Unfortunately the fact that this is represented in seconds will not be very useful for most peoples, as we will aim to serve most of the requests in less than ONE second. Apache 2 introduced a new log value %D (not available on apache 1.3) that is logging the time spent to serve the request but in microseconds (10-6) instead of seconds.
Considering that we are running apache2.0.x we can add to the logging format: %T/%D and this will effectively show us both values, with a quick look on the seconds (%T) and then with the real number in microseconds (10-6). For this our logformat line will become:
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" **%T/%D**" combined
Now we can create a script to interpret those newly added values, and show some nice statistics… Here is how a log entry will look like:
[31/Jan/2008:14:19:07 +0000] "GET / HTTP/1.1" 200 7918 "" "Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.11) Gecko/20061201 Firefox/2.0.0.11 (Ubuntu-feisty)" **0/95491**
Still, I want to outline that these values are not the values taken by the server to generate the page (I mean to interpret a php script and show the output), but the time taken to ‘serve’ the page. You might see big times for slow internet users. For ex. I had the php sample page shown above, generated in 0.0847 seconds, while in the logs it will show 0.095491 and this because it was a small page and the connection fast. Basically you will add extra the time to establish a tcp connection and to transfer the data from the server to the client.
I hope you found this article interesting. Even if you will not develop a complex statistics based on it, it can be a quick overview to see if you are serving the pages fast, or most of your clients get the pages very slow. There are many other logging related parameters in apache2 and here is the full list for apache2.2 mod_log_config module:
%% The percent sign
%a Remote IP-address
%A Local IP-address
%B Size of response in bytes, excluding HTTP headers.
%b Size of response in bytes, excluding HTTP headers. In CLF format, i.e. a '-' rather than a 0 when no bytes are sent.
%{Foobar}C The contents of cookie Foobar in the request sent to the server.
%D The time taken to serve the request, in microseconds.
%{FOOBAR}e The contents of the environment variable FOOBAR
%f Filename
%h Remote host
%H The request protocol
%{Foobar}i The contents of Foobar: header line(s) in the request sent to the server.
%l Remote logname (from identd, if supplied). This will return a dash unless mod_ident is present and IdentityCheck is set On.
%m The request method
%{Foobar}n The contents of note Foobar from another module.
%{Foobar}o The contents of Foobar: header line(s) in the reply.
%p The canonical port of the server serving the request
%P The process ID of the child that serviced the request.
%{format}P The process ID or thread id of the child that serviced the request. Valid formats are pid, tid, and hextid. hextid requires APR 1.2.0 or higher.
%q The query string (prepended with a ? if a query string exists, otherwise an empty string)
%r First line of request
%s Status. For requests that got internally redirected, this is the status of the *original* request --- %>s for the last.
%t Time the request was received (standard english format)
%{format}t The time, in the form given by format, which should be in strftime(3) format. (potentially localized)
%T The time taken to serve the request, in seconds.
%u Remote user (from auth; may be bogus if return status (%s) is 401)
%U The URL path requested, not including any query string.
%v The canonical ServerName of the server serving the request.
%V The server name according to the UseCanonicalName setting.
%X Connection status when response is completed:
X = connection aborted before the response completed.
+ = connection may be kept alive after the response is sent.
- = connection will be closed after the response is sent.
(This directive was %c in late versions of Apache 1.3, but this conflicted with the historical ssl %{var}c syntax.)
%I Bytes received, including request and headers, cannot be zero. You need to enable mod_logio to use this.
%O Bytes sent, including headers, cannot be zero. You need to enable mod_logio to use this.