The Apache Web Server is succeeding on many platforms even as frontend to forward requests to backend systems implemented in various programming languages. When you are experiencing problems with your web services it may be helpful to know how long backend systems require to send back replies.

This article illustrates how to configure the Apache Server 2.x to write out the real precessing time of HTTP(s) requests.

Standard Log Configuration

The following except of an Apache configuration file shows the default settings regarding the logging configuration.

# define contents of a log file entry
# the name of this 'template' is 'combined'
LogFormat "%h %l %u %t "%r" %>s %b "%{Referer}i" "%{User-Agent}i"" combined
 
# utilize the previous definition to write the access.log
CustomLog ${APACHE_LOG_DIR}/access.log combined
 

When looking at the access.log you will find entries like this.

127.0.0.1 - - [05/Feb/2012:14:56:04 +0100] "GET / HTTP/1.1" 200 461 "-" "curl/7.21.6 (x86_64-pc-linux-gnu) libcurl/7.21.6 OpenSSL/1.0.0e zlib/1.2.3.4 libidn/1.22 librtmp/2.3"
127.0.0.1 - - [05/Feb/2012:14:56:15 +0100] "GET /index.html HTTP/1.1" 200 461 "-" "curl/7.21.6 (x86_64-pc-linux-gnu) libcurl/7.21.6 OpenSSL/1.0.0e zlib/1.2.3.4 libidn/1.22 librtmp/2.3"
 

To get an idea what is contained in this king of log file you should take a look at the documentation of the Apache Server. However, the processing time is not contained. To fix this we have to customize the rule how logging entries are written to files.

Customize the Configuration

The following example illustrates how to create a new rule / template for writing log files.

# define a custom template for writing log file entries
LogFormat "%h %D %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i"" mycombined
 
# tell apache what templates to utilize when writing the access log
CustomLog ${APACHE_LOG_DIR}/access.log mycombined
 

This will result in the following log entries after restarting the Apache Web Server.

127.0.0.1 1078 - [05/Feb/2012:15:05:49 +0100] "GET / HTTP/1.1" 200 461 "-" "curl/7.21.6 (x86_64-pc-linux-gnu) libcurl/7.21.6 OpenSSL/1.0.0e zlib/1.2.3.4 libidn/1.22 librtmp/2.3"
127.0.0.1 655 - [05/Feb/2012:15:05:53 +0100] "GET /index.html HTTP/1.1" 200 461 "-" "curl/7.21.6 (x86_64-pc-linux-gnu) libcurl/7.21.6 OpenSSL/1.0.0e zlib/1.2.3.4 libidn/1.22 librtmp/2.3"
 

The second entry in each line represents the processing time in microseconds! Within the previous example this are 1078 µs and 655 µs.

Related resources:

• Apache 2.0 Manual – LogFormat
• Apache 2.2 Manual – LogFormat

Incoming search terms:

• apache log processing time