Loading ...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.
Tags: apache-tips-and-tricks, apache2
10th November 2008, 20:43
Back to Basics…Making a Case for Analyzing the Web Server Logs…
Sometimes it take a long time to clearly see what you want. I’ve been struggling for months about how do we see where our latency is from in an endtoend manner. This is a major need for the team and not just a curiosity…….
21st July 2009, 05:28
Good article.
Most of the time, we would like to understand the “request processing time” rather than the “response time” (ie) the time taken by the server excluding the network delays.
Is there any way to do that ?
4th August 2009, 23:05
Thanks for the article,
I’ve got the same request than “letflow”:
So far, I’ve just found some alternatives like:
1) “mod-log-firstbyte” (http://code.google.com/p/mod-log-firstbyte/)
2) mod_headers (http://httpd.apache.org/docs/2.2/mod/mod_headers.html):
Add a header, MyHeader, to the response including a timestamp for when the request was received and how long it took to begin serving the request. This header can be used by the client to intuit load on the server or in isolating bottlenecks between the client and the server.
ex: Header add MyHeader “%D %t”
Is there anything else I can use ?
Thank you for any help
5th August 2009, 11:14
@Guedec: I would say mod_headers is a good solution for what you are trying to achieve. I am not aware of other solutions at this time.
17th December 2009, 10:27
Interesting article, thx.
%D measures the time from when the request was received to the time the headers are sent on the wire.
Are you aware of any solution that measures the time from where the request was received to the time the last byte of the response is sent ?
Thank you for any help
17th March 2010, 14:02
“mod-log-firstbyte” (http://code.google.com/p/mod-log-firstbyte/) is the best idea to log php execution time, but the project seems dead since Aug 13, 2006 http://code.google.com/p/mod-log-firstbyte/source/list
Does anybody know another methods to log php execution time?
16th April 2010, 07:54
@Murz: mod-log-firstbyte is complete and does not need to be maintained. I just compiled it for 2.2 and it worked out of the box for me. Its usable in its current state and does what its supposed to do
21st May 2010, 14:55
Is there any tool or software which reads the response time from the apache log and gives the output in gui format (in terms of charts or graphs).
21st May 2010, 17:31
@Sammit not that I’m aware of, but you are right that would be neat.
17th November 2010, 13:27
[...] also found this article on mod_log_config, not sure if you’re using this or another module for logging. I don’t [...]
10th February 2011, 02:34
good one..
thanks for the help.
can u suggest any log parsing tool, that helps to segregated apache logs ?
for eg:
to know the number of Hits. Time delay to respond … etc
I appreciate your work.. It rOcks..
25th July 2011, 01:38
Does the timing logged in %D includes all the db queries timing?
Is kind of weird because I get slow SQLs of like 2 to 7 secs.
But I didn’t get any access_log that have %D which is more than 1million msec.
25th July 2011, 08:37
@hskism: depending on how your page is rendered it should include the backend work also yes. it is the time apache finished the request.
25th July 2011, 10:52
Thanks Marius.
I was using logrep from wtop, and the msec rendered out is actually in Milliseconds!
25th July 2011, 10:56
Thanks Marius.
I was using logrep from wtop, and the msec rendered out is actually in Milliseconds! And I was reading the values reported by wtop all along thinking that it was in microsec! That was why I wonder why I don’t get slow request from Apache since I have slow request in SQL and started to ask you this question. Anyway, problems solved. Thanks again!
15th August 2011, 09:43
[...] Just log the time… http://www.ducea.com/2008/02/06/apache-logs-how-long-does-it-take-to-serve-a-request/ [...]
2nd January 2012, 14:34
[...] How long does it take to serve a request? [...]