Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

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?

share|improve this question
    
It is sort of weird that where the status code should be (200) your example log line has '262' which I've never seen as a status code, and also the same number you said you were seeing in the headers. –  polynomial Aug 21 '11 at 14:58
    
"womble" changed the post, The original line was: [IP-ADDRESS] 525151 - - [21/Aug/2011:14:19:53 +0200] "GET /images/site/slide-1.png HTTP/1.1" 200 423285 "http://[DOMAIN]/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.112 Safari/535.1" –  Søren Haagerup Aug 22 '11 at 9:13

1 Answer 1

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
share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.