This post appeared originally in our sysadvent series and has been moved here following the discontinuation of the sysadvent microsite

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 forty characters here, YMMV. If the tail is very long, you’d probably want to adjust the regexp so more requests get grouped together.

Tobias Brox

Senior Systems Consultant at Redpill Linpro

Tobias started working as a developer when he finished his degree at The University of Tromsø. He joined Redpill Linpro as a system administrator a decade ago, and have embraced working with our customers, and maintaining/improving our internal tools.

Thoughts on the CrowdStrike Outage

Unless you’ve been living under a rock, you probably know that last Friday a global crash of computer systems caused by ‘CrowdStrike’ led to widespread chaos and mayhem: flights were cancelled, shops closed their doors, even some hospitals and pharmacies were affected. When things like this happen, I first have a smug feeling “this would never happen at our place”, then I start thinking. Could it?

Broken Software Updates

Our department do take responsibility for keeping quite a lot ... [continue reading]

Alarms made right

Published on June 27, 2024

Just-Make-toolbox

Published on March 22, 2024