Web-server – Apache loading time in microseconds – difference between header and log

apache-2.2performance-monitoringweb-server

I recently followed this guide to obtain performance measurement of siteload on a web server.

To log the time it takes for Apache to process a request add this to your apache configuration file:

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

%D means you’ll see the time it took Apache to process the request in the access log. The time is measured in microseconds.

To make it even easier to debug page load times, add this to your configuration file:

Header set X-Request-Received: %t
Header set X-Request-Processing-Time: %D

Remember to enable mod_headers first by executing a2enmod headers.
Now you should see these headers in the response:

X-Request-Received t=1286995673038485
X-Request-Processing-Time D=251

I used exactly the code above (with header defined in .htaccess) but get for example "525151" in the log and "262" in the header for the same request. In general there seems to be orders of magnitude in difference between the numbers

192.0.2.1 525151 - - [21/Aug/2011:14:19:53 +0200] "GET /images/site/slide-1.png HTTP/1.1" 262 423285 "http://example.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.112 Safari/535.1"

vs.

X-Request-Processing-Time:D=262
X-Request-Received:t=1313929193502879

How can I fix this?

Best Answer

Can you verify that your LogFormat name 'combined' matches what your CustomLog variable is using. I tested this on OS X and aside from the minor difference you'd expect between reading the variable when writing back the headers and when logging (after sending all the data back to the client) they are very close:

/etc/apache2# grep LogF httpd.conf
    LogFormat "%h %l %u %t \"%r\" %>s %b %t %D" common

/etc/apache2# grep CustomL httpd.conf
    # a CustomLog directive (see below).
    CustomLog "/private/var/log/apache2/access_log" common


# wget -qqO /dev/null -S http://localhost/
...
  X-Request-Received: t=1314588821970347
  X-Request-Processing-Time: D=336

/private/var/log/apache2# tail access_log 
::1 - - [28/Aug/2011:20:33:41 -0700] "GET / HTTP/1.0" 200 44 [28/Aug/2011:20:33:41 -0700] 587
Related Topic