How to Log response time and request handler in IHS

Here in this article we will try to log response time and request handler in IBM Http server logs by updating the logformat for IBM HTTP server.

Assuming that we have setup WAS environment with two JVM’s in a clusters environment with frontend IHS Webserver. There are situation where in we would like to know which JVM actually served the request and how much time it took for the response back from Websphere application server to IHS webserver.

Here are the two logging configuration changes that we can add to the log format that is currently active.

1. Logging the JVM that handled the request

During the troubleshooting process, it may help to know which JVM handles a particular request. There are multiple ways of logging the JVM processing a request. Two of the most popular ways are to handle the %{WAS}e environment variable, or to use the JESSIONID cookie.

Using the %{WAS}e environment variable

For requests that are handled with the WebSphere plug-in, the plug-in module creates an environment variable called WAS which contains the server that handled the request. The WAS environment variable is logged in the access logs by adding the following to the LogFormat statement: %{WAS}e.

LogFormat "%h %l %u %t "%r" %>s %b %{WAS}e" common

When the %{WAS}e string is added, the hostname and transport port number of the JVM used to serve the request is logged. For example, “app1.torolab.ibm.com:9091”.

2. Logging response times

Logging the response time for each request is useful when debugging performance or timing issues. By adding %D to the access log format, the server saves the response time in microseconds. For example.

LogFormat "%h %l %u %t "%r" %>s %b %D" common

One microsecond is a millionth of a second. This metric is typically too small to be practical; most people prefer to work with milliseconds instead. ( milliseconds = microseconds / 1000 ).

When using the values logged with %D, keep in mind that these numbers include a network component. The %D format string counts the time until all the response bytes are passed to the TCP layer in the IHS system. If there is a network or configuration issue, the values logged in the access log will be much higher than the actual time used by the WebSphere Commerce JVMs to execute the request and return it to the plug-in component in IHS.

In general %D logging is a good reference of the JVMs performance, if you suspect the numbers are too high compared to the expected JVM performance, you should enable additional monitoring in the JVM and network layers.

Hope you enjoyed reading this article. Thank you.