How to make Apache log real scriptname and execution time with mod_rewrite and LogFormat

In our way to improve websites performances, we find one way to make profiling through Apache access log because not only it show us every script called, but it can also tell us the time taken to execute theses scripts.
So we can track Google crawl bot performance on our websites, and slow scripts.
Let's take a look at LogFormat options.

Default LogFormat

By default, Apache log all requests with

"%h %l %u %t \"%r\" %>s %b"

Example :

192.12.1.1 - - [31/Aug/2010:14:53:06 +0200] "GET /index.php HTTP/1.0" 200 3535

%h : Remote host : 192.12.1.1
%l : Remote logname : -
%u : Remote user : -
%t : Time of request : [31/Aug/2010:14:53:06 +0200]
%r : Request : GET /index.php HTTP/1.0
%>s : HTTP status : 200
%b : Size of response : 3535

When you got a lot of rewriting, %r only show the user request (eg : rewrited URL) and if you want to analyse and find what script is slow, it's a pain to apply rewrite rules when parsing logs

Custom LogFormat

One solution is to use %f, %D, %q to add some better and more useful reading in logs

%f show the script file which is called after all rewrite rules are applied
%D show the time taken to execute the script
%q show the query string after all rewrite rules are applied

With a CustomLog format like this (removing remote logname and user since we don't use authentication via Apache)

"%h %t \"%r\" \"%f%q\" %>s %b %D"

To use it, use the code bellow in your vhost file

LogFormat "%h %t \"%r\" \"%f%q\" %>s %b %D" vhost_profile
CustomLog logs/access_log vhost_profile

Then restart httpd, and it every request will be logued like :

192.12.1.1 [31/Aug/2010:16:04:28 +0200] 
"GET /some/complex/rewrite/with-parameter-and-no-script HTTP/1.1"
"/data/htdocs/some/folder/index.php?some=var&putby=rewrite_mod" 200 3535 23351

For comparison with the Default LogFormat :

192.12.1.1 - - [31/Aug/2010:14:53:06 +0200] 
"GET /some/complex/rewrite/with-parameter-and-no-script HTTP/1.1" 200 3535

%h : Remote host : 192.12.1.1
%t : Time of request : [31/Aug/2010:16:04:28 +0200]
%r : Request : GET /some/complex/rewrite/with-parameter-and-no-script HTTP/1.1
%f : Filename : /data/htdocs/some/folder/index.php
%q : Query string : ?some=var&putby=rewrite_mod
%>s : HTTP status : 200
%b : Size of response : 3535
%D : Script execution time : 23351

We now get the time in microseconds taken to execute the page (23351) and the real script called, with the real query string, also it show the URL called when you make a redirect (301, 302, ..) via a Rewrite Rule.

Now we can use a log parser to analyse this.

Resources

Apache 2.2 mod_log documentation : http://httpd.apache.org/docs/2.2/mod/mod_log_config.html