Response time logging

[kjkoster]

Dear All,

Once an application is taken into production and it starts to run smoothly from a functional point of view, users generally start complaining about performance. There is always something. :-) I usually enable response time logging early on, so I can get a feel for which servlets and JSP pages are slow and which are fast. At the very least, it gives me the opportunity to say to my client: "yes, I know that the application is slow. The problem seems to be limited to BarServlet and foo.jsp, though". This sounds a whole lot better than: "Gee, is it? I'll have a look if I can find anything".

In Tomcat, you can edit server.xml and change the format used by the AccessLogValve. The AccessLogValve format is documented on the Tomcat (http://tomcat.apache.org/tomcat-6.0-doc/api/org/apache/catalina/valves/AccessLogValve.html) site. If you add a %D to the format string, Tomcat will replace it with the request's response time in milliseconds.

Here is the configuration of my access log valve. For this particular server I generate a separate log file, just for response times. Of course you can just add the %D to the log format of your configuration.

<Valve className="org.apache.catalina.valves.AccessLogValve"
directory="logs" prefix="timing." suffix=".log"
pattern="%t %U %s %D" resolveHosts="false" />

The Apache web server offers the same thing, and the log format pattern also happens to be %D. This is documented on the Apache site (http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats).

Here is the configuration I use in my Apache server. This is basically the default log format, with a %D inserted in a place where I can easily find it using awk(1) (http://nixdoc.net/man-pages/FreeBSD/awk.1.html):
LogFormat "%h %l %u %t \"%r\" %>s %b %D \"%{Referer}i\" \"%{User-Agent}i\"" combinedtime
CustomLog "/var/log/httpd-access.log" combinedtime


Be careful when interpreting the results. The time logged in Apache is in microseconds, where Tomcat logs in milliseconds. I was certainly confused the first time.

I then use Gnuplot (http://www.gnuplot.info/) to generate pretty graphs from the log files. I attached a sample file so you can see what it looks like.

Do you use response time logging for your applications and web servers? If not, in what way do you ensure that your page requests are fast enough?

Also, I would like to know how response time logging is enabled in other application servers, such as JBoss, OC4J and Orion.

Kees Jan

[Barry]

And if you are using Glassfish (V2 or V3) you can also use their internal call flow feature, which can log the flow through your application all the way to the DB and back.
You can read more on that here: https://glassfish.dev.java.net/javaee5/monitoring/callflow/callflow.html

[billmil]

can you post the gnuplot script used to generate this output?

thanks

[kjkoster]

Dear billmil,

I have to look it up. It's been a while since I last used it. I have to warn you, though. It is not exacly user friendly. :-)

Kees Jan

[ericsully]

According to http://www.networkworld.com/community/node/45949#comment-244254 there is a free response time monitoring tool that can be found at http://www.real-user-monitoring.com

[NK83]

Hi Kees

I came to Java-monitor while I was searching for a tool that log processing time for each request in JBoss. :)

Thanks for raising such important issue :)

It is good that the AccessLogValve logs response time. However, how the response time is measured. My insight on this is as follows:

Pattern: %D - Time taken to process the request, in millis. However, this logging is performed at context, host or engine level- it means it does not include the queuing and thread allocation time but after (which means queuing and thread allocation times are not included)
"This Valve may be associated with any Catalina container (Context, Host, or Engine), and will record ALL requests processed by that container." http://tomcat.apache.org/tomcat-5.5-doc/config/valve.html#Access_Log_Valve

Another way could be:

Using Tomcat's RequestInfo class (http://tomcat.apache.org/tomcat-6.0-doc/api/org/apache/coyote/RequestInfo.html): This class contains information about each request. It has a method called updateCounters () which update statistical information about each request (including max, min and average processing time). Again my understanding this method does not include the queuing and thread allocation times as it execute when the service method is called- after the thread allocation?

Please correct me if I'm not accurate?

Another point is, the way response time is logged (in both ways) also includes the DB processing time (when you have a DB server setting behind your App. server). So, the DB processing time should not be accounted in your the App. server processing time? Tomcat may send 1 or more SQL query (depending the application code) to the DB to serve one request. The processing time of these queries should not be counted as part of Tomcat service time. How could one manage to exclude these times?

Pattern: %D - Time taken to process the request, in millis However, this logging is performed at context, host or engine level- it means it does not include the queuing and thread allocation time.
"This Valve may be associated with any Catalina container (Context, Host, or Engine), and will record ALL requests processed by that container." http://tomcat.apache.org/tomcat-5.5-doc/config/valve.html#Access_Log_Valve

Another way could be:

Using Tomcat's RequestInfo class (http://tomcat.apache.org/tomcat-6.0-doc/api/org/apache/coyote/RequestInfo.html): This class contains information about each request. It has a method called updateCounters () which update statistical information about each request (including max, min and average processing time). Again my understanding this method includes the queuing and thread allocation times as it execute when the service method is called- after the thread allocation? Would this method be useful for obtaining service time for each request in your case?

Please correct me if I'm not accurate?

Another point is, The way you capture service time also includes the DB processing time. Tomcat may send 1 or more SQL query (depending the application code) to the DB to serve one request. The processing time of these quires should not be counted as part of Tomcat service time. How did you manage to exclude these times?

Does Java-monitor provide better response time for each request (only processing time on JBoss server once a request arrives the queue until a corresponding response is sent back- without including DB processing time)?

I'm interested in using Java-monitor for JBoss if it does this kind of requesting processing time. :)

I look forward to hearing from you soon

Thanks
N.K.

[kjkoster]

Dear N.K,

You obviously did your homework. :-)

I see the %D logging (if you'll pardon me the jargon) as one step in measuring the entire chain. I use it to determine where to look for performance problems: inside my application or outside it (network infrastructure, client rendering queuing etc.) It essentially tells me what my next step is: 1) %D times are slow or fluctuate heavily --> start using profilers etc to make my code or the database better, or 2) %D times are really short --> start drinking coffee and doing small talk with the sysadmins to find out where the problems are.

Buffering, routing and queuing in the network are all the same problem generally, in the sense that it is not in the application code. Following that train of thought, it makes sense not to include that in the %D times.

Similarly the database. I use response time logging on the database driver as well. Depending on the driver I use built-in time logging or have a small JDBC connection wrapper that logs the times for me. Again, I use it to split the problem in two parts: 1) quick SQL execution times means the problem is inside the Java code. 2) slow JDBC execution times mean I need to talk to the database administrators and start making friends there.

You could repeat this pattern in JavaScript as well, we are seeing more and more of that. I have never done that so far, since the problems I had to deal with were either the application code or badly tuned SQL databases using horrible schema's.

Another factor to consider is that not all database traffic originates from HTTP requests. There will be batches, cron jobs and background tasks that also generate SQL queries that can impact the overall application performance.

This is how I use response time logging, mind. You may have a different way of working.

Does JBoss provide JMX MBeans to expose the measured response times? If so, I can make Java-monitor support that easily. If not, is there a programmatic API for accessing the response time information?

Kees Jan

[NK83]

Thanks Kees for sharing such good insights :)

Yes, I've done a lot of research about this issue and I found many mixing things together.

I like your way of debugging performance issues. The JDBC logging is new to me and I'll find some more details about it. Thanks for the pointer :)

JBoss provides JMX MBeans but for its resources; e.g., memory utilization, connections, threads. In other words, it provides resource-level measures (http://www.blogsoncloud.com/jsp/blogs/using-jboss-jmx-console.jsp)

I'm not also aware about any API that provides response time. If you get to know it would be great if you notify me. I'd also be interested to use Java-Monitor if it can capture processing time for each request processed on JBoss server (without DB processing time)

Thanks
N.K.