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:
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:
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.
Is there an equivalent to %D or %T which shows the total request time in milliseconds instead of microseconds or seconds?
The rest of our systems (DB and app servers) usually log request times in milliseconds. Is there a way to log Apache's request time in milliseconds so that all of our servers log using the same unit of time?
EDIT: I want to know the total number of milliseconds that a request takes. I can see the documentation for setting the timestamp - which is not what I am looking for.
This question appears to be off-topic. The users who voted to close gave this specific reason:
"Questions must demonstrate a minimal understanding of the problem being solved. Try including attempted solutions, why they didn't work, and the expected results. See How can I ask better questions on Server Fault? for further guidance." – Jenny D, Rex, MichelZ, Wesley
@jenny - I don't see anything in that documentation that tells me how to do what I asked. But I can see how you are confused because "time" is ambiguous. – nimblegorillaApr 17 '14 at 16:33
Michael - how do I divide %D by 1000 in the log file? I didn't realize it was possible to do math expressions. – nimblegorillaApr 17 '14 at 18:34
1
You do it with your log analysis tools after the logs are written. If you can't do that, then you write a script to convert the logs before sending your analysis tools on them. If neither of those are acceptable, you're going to have to write a patch for apache (or hire someone to write one) or give up. – yoonixApr 17 '14 at 19:41
shareimprove this answeranswered Apr 17 '14 at 15:56kalikid02131913
That only tells me the timestamp in milliseconds, but I am looking for the measurement of the amount of time the request took. – nimblegorillaApr 17 '14 at 16:33
You can't time requests as a log output as far as I know. What you may need to do is handle that in your application code, and log that from your app separately. – kalikid021Apr 17 '14 at 17:19
5
I'm already using %D to time the requests in microseconds so it is definitely possible. You can also use %T for time in seconds. The only thing I can't find is a way to log in milliseconds. – nimblegorillaApr 17 '14 at 18:33
