A simple servlet filter for Java performance logging

There are plenty of fancy tools for performance testing Java web applications but in addition to thorough load and volume testing before an application goes live, sometimes it’s useful just to leave simple perfomance monitoring running full time in a production environment. Monitoring the time the server takes to execute requests on your site can help you spot trends that let you anticipate and deal with problems caused by load, volume, unanticipated usage patterns or simply a database in need of some tuning. A proactive approach to performance tuning can bring big wins in customer satisfaction too, allowing you to pre-empt and avoid issues and keep your site running smoothly for your users.

Fortunately Java Enterprise Edition provides an easy mechanism for intercepting every request on the way in and out of the application in the form of a Servlet filter and it’s really simple to use that to create a performance logger. The basic concept here is to capture the time as a request enters an application, then again as it leaves and log the difference between the two. We can do this in the servlet filter’s doFilter method as follows. I’m using a log4j logger to handle the output but obviously any other logging mechanism would work just as well if you prefer something else:

    long startTime;
    long endTime;
    String path = ((HttpServletRequest) request).getServletPath();

    startTime = System.currentTimeMillis();
    chain.doFilter(request, response);
    endTime = System.currentTimeMillis();

    //Log the servlet path and time taken
    perfLogger.info(path + "," + (endTime - startTime) );

To finish off the code, I’ve added a couple of configuration options for more flexibility. For starters, I prefer to have a little more control over which URLs get logged than the standard servlet url-pattern mechanism allows. For instance, I may want to only log requests containing the word ’search’ anywhere in the path. The standard servlet url-pattern mechanism doesn’t allow this so I’ve added a parameter ‘url-filter’ to allow full regular expression matching. A second parameter ‘log-category’ sets the log4j logging category to use. Wrapping this into a full example servlet filter we get:

package com.actuanceconsulting.perflog;

import java.io.IOException;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;

import org.apache.log4j.Logger;

/**
 * A simple filter to log the time taken to execute a request. Logging is carried
 * out via log4j to give the flexibility to add other data (such as current time)
 * and format the log as required.
 * */

 /*
 * Copyright John Patrick, Actuance Consulting Limited 2010
 * http://www.actuanceconsulting.com
 *
 * This program is free software: you can redistribute it and/or modify
 * it under the terms of the GNU Lesser General Public License as published
 * by the Free Software Foundation, either version 3 of the License, or
 * (at your option) any later version.
 *
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU Lesser General Public License for more details.
 *
 * For a copy of the GNU Lesser General Public License,
 * see <http://www.gnu.org/licenses/>.
 */
public class PerformanceLogFilter implements Filter {

 /**
 * An optional regular expression to use as a filter for the servlet patch.
 * Gives more flexibility than the standard servlet url-filter.
 * All requests are logged if not specified.
 * */
 private static final String URL_FILTER_PARAM = "url-filter";

 /**
 * An optional log4j category to use. The fully qualified class name
 * of the filter will be used if not specified.
 */
 private static final String LOG_CATEGORY_PARAM = "log-category"; 

 private Logger perfLogger;
 private String urlFilter;

 public void init(FilterConfig config) throws ServletException {
    String logCategory = config.getInitParameter(LOG_CATEGORY_PARAM);
    if (logCategory == null) {
       this.getClass().getName();
    }
    perfLogger = Logger.getLogger(logCategory);
    urlFilter = config.getInitParameter(URL_FILTER_PARAM);
 }

 public void doFilter(ServletRequest request, ServletResponse response,
 FilterChain chain) throws IOException, ServletException {

    long startTime;
    long endTime;
    String path = ((HttpServletRequest) request).getServletPath();

    if (urlFilter == null || path.matches(urlFilter)) {
       startTime = System.currentTimeMillis();
       chain.doFilter(request, response);
       endTime = System.currentTimeMillis();

       //Log the servlet path and time taken
       perfLogger.info(path + "," + (endTime - startTime) );
    }
    else {
       chain.doFilter(request, response);            
    }
 }

 public void destroy() {
    //Nothing to see here        
 }

}

To get the filter to run, we need to configure it in the web.xml file as follows:

<filter>
  <filter-name>performance</filter-name>
  <filter-class>com.actuanceconsulting.perflog.PerformanceLogFilter</filter-class>
  <init-param>
    <param-name>url-filter</param-name>
    <param-value>.*search.*</param-value>
  </init-param>
  <init-param>
    <param-name>log-category</param-name>
    <param-value>perflog</param-value>
  </init-param>
</filter>
<filter-mapping>
  <filter-name>performance</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping>

In this case I’ve set my regular expression for the ‘url-filter’ parameter to only match paths containing ’search’. For completeness, here’s the log4j config I used too…

<appender name="PerformanceFileAppender">
  <param name="Threshold" value="DEBUG"/>    
  <param name="File" value="../logs/performance.log"/>
  <param name="Append" value="true"/>
  <layout>
    <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss},%m%n"/>
  </layout>
</appender>

<category name="perflog">
  <priority value="INFO"/>        
  <appender-ref ref="PerformanceFileAppender"/>                
</category>

…and that produces output as shown below. The CSV format of this output allows for easy analysis of the results but obviously you can choose whatever format suits you best.

2010-06-19 11:26:20,/search,81
2010-06-19 11:26:25,/advanced-search-input,66
2010-06-19 11:26:30,/advanced-search,62
2010-06-19 11:26:39,/search,56
2010-06-19 11:26:43,/search,38
2010-06-19 11:26:43,/search,39

And that’s all there is to it. It’s a simple bit of code but it can really add value when run over a period of live operation. Being able to see historical performance and spot trends can be a powerful diagnostic tool.