Logging the elapse time in the web server access log can be very useful for statistics and problem solving. I usually throw it in at the end of the log line (that’s generally compatible with existing log-analysis tools like awstats), and on a keyword=value format so that it’s easy to grep out. There is a small performance cost, though.

The elapse time includes everything - when filtering out log lines with high elapse-time you may typically find mobile clients downloadi ng large files - their local bandwidth being the bottle neck. However, sum up the elapse time and group by the request, and most likely the requests “consuming” the most elapse-time will also be the requests consuming most server resources.

If the bottle neck is on the clients bandwidth side you’d like a high max-connections number. If the bottle neck is on local resources, i.e. CPU cycles, you’d like to keep a low max-connections number, probably not much higher than the number of CPUs available.

Apache

I typically throw something like this in the configuration:

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

Eventually, other things that may be useful to log: vhost, port, X-Forwarded-For:

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" elapsed=%Dus vhost=%v port=%p remoteip=%{X-Forwarded-For}i" combined

Then make sure to use the “combined” log format in the access log:

CustomLog /var/log/apache2/www.example.com-access.log combined

Here is an example command for analyzing the log:

cat /var/log/apache2/*access.log | 
perl -ne '($req)=/ \"([A-Z]* \/[^ ]*) HTTP/; /elapsed=(\d+)us/; $elapsed{$req}+=$1; sub END { for my $k (keys %elapsed) { printf "% 6d %s\n", $elapsed{$k}/1000000, $k; }}' |
sort -nr | less

You might want to tune that regexp if you get a long tail.

Note: apache logs are located under /var/log/httpd/ on RedHat with derivatives.

Nginx

I typically throw something like this into the nginx configuration:

log_format  main  '$remote_addr - $remote_user [$time_local] $request '
                  '"$status" $body_bytes_sent "$http_referer" '
                  '"$http_user_agent" "$http_x_forwarded_for" '
                  '"http-host=$host" "elapsed=${request_time}s" '
                  '"scheme=${scheme}"';

access_log  /var/log/nginx/access.log main;

Here’s an example on how one can do simple statistics on the access log:

perl -ne '($req)=/\] ([[:upper:]]+ \/[^ ]{0,40})/; /elapsed=(\d+(\.\d+)?)s/; $elapsed{$req}+=$1; sub END { for my $k (keys %elapsed) { printf "%6.2f %s\n", $elapsed{$k}, $k; }}' access.log | sort -rn | less

The URL is shortened to fourty characters here, YMMV. If the tail is very long, you’d probably want to adjust the regexp so more requests gets grouped together.