Profiling your Java code using Spring

Recently I needed to conduct some performance testing. In the process, I needed to time certain pieces of Java code, to better understand where time was being spent. A large portion of this application was already wired together with the Spring Framework. As I have shown previously, when your application is already Spring-enabled it is easy to add additional services to it. I decided to look to Spring yet again to help me with timing my Java method calls.

Like any good software developer I first looked for existing examples. I knew I wanted to use Spring's AOP facility to add a timing aspect to my code without modifying my code directly. I found one web site and one book that were very close to what I needed, and close to each other in implementation details.

The web site I found was a blog posting as well. The author does a good job of laying out most of what needs to be done. There were a couple changes I was going to have to make, but it was a great start.

I also pulled my copy of Pro Spring off the shelf and opened the chapter on AOP. Listing 6-15 for the ProfilingInterceptor Class offers a similar solution to the blog post.

I took most of the implementation for the MethodInterceptor from the Pro Spring version, however I kept the name that appeared in the blog version. I commented out the Argument printing, and converted it from System.out.println to log4j style. The following is my version (borrowed heavily from the previous two sources).

package org.myapp.utils;

import java.lang.reflect.Method;

import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.util.StopWatch;

public class TimingLoggingInterceptor implements MethodInterceptor {
    private final Log logger = LogFactory.getLog(getClass());
    
	public Object invoke(MethodInvocation invocation) throws Throwable {
		StopWatch sw = new StopWatch();
		
		sw.start(invocation.getMethod().getName());
		Object returnValue = invocation.proceed();
		sw.stop();
		
		logMethodCall(invocation,sw.getTotalTimeMillis());
		
		return returnValue;
	}
	
	private void logMethodCall(MethodInvocation invocation, long ms) {
		Method m = invocation.getMethod();
		Object target = invocation.getThis();
		
		StringBuffer msg = new StringBuffer();
		msg.append("Executed Method: ");
		msg.append(target.getClass().getName());
		msg.append('.');
		msg.append(m.getName());
		msg.append(" in (ms): ");
		msg.append(ms);
		logger.info(msg);
	}

}

In hindsight I should maybe have tried to figure out how to use the performance monitoring classes that ship with the Spring Framework (e.g., PerformanceMonitorInterceptor). I was happy with the relative simplicity of the class. The next step was to configure the Spring beans definition file to make sure of this method interceptor. Neither Pro Spring nor the blog post, provided the solution I needed. The blog post was very close, but the the final piece of that example used the DefaultAdvisorAutoProxyCreator to automatically create the proxies. When I tried to use this in my existing application I encountered a StackOverFlowError. As most developers know, a StackOverFlowError tends to occur when you run into infinite recursion. Not knowing what the rest of my application was doing, I hypothesized that possibly somewhere else in the code autoproxing might be occurring. So I decided I needed to explicitly proxy the beans I wished to time.

I then tried to use the BeanNameAutoProxyCreator to create my proxies, without needing to modify other parts of my Spring configuration. This approach also failed. I am not certain why, but I still was not seeing the logging I desired. My only guess is possibly BeanNameAutoProxyCreator might require CGLIB and maybe that was not included in the application at the moment. Deciding I still wanted as little impact as possible to my application, I tried to figure out how to do my proxying without CGLIB. Eventually I determined I needed to use the standard ProxyFactoryBean. To use ProxyFactoryBean to proxy your objects and not need CGLIB, you must proxy a specific set of interfaces that the bean supports.

Assuming you have the following bean definition

    <bean id="MyService" class="org.myapp.services.MyService">
    	<property name="enforceAuthorization" value="true" />
    	<property name="sourceDirectory" value="/opt/myapp" />
    	<property name="backupDirectory" value="/tmp" />
    	<property name="maximum" value="100" />
    </bean>

And this bean supports the org.myapp.services.MyService interface, then we can modify the bean definition to be proxied with our interceptor developed above. The following snippet would completely replace the previous snippet in your bean definition file.

    <bean id="MyServiceTarget" class="org.myapp.services.MyServiceImpl">
        <property name="enforceAuthorization" value="true" />
        <property name="sourceDirectory" value="/opt/myapp" />
        <property name="backupDirectory" value="/tmp" />
        <property name="maximum" value="100" />
    </bean>

    <bean id="timingLogger" class="org.myapp.utils.TimingLoggingInterceptor"/>

    <bean id="timingAdvisor" class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
        <property name="advice" ref="timingLogger"/>
        <property name="patterns">
            <list>
                <value>.*</value>
            </list>
        </property>
    </bean>

    <bean id="MyService" class="org.springframework.aop.framework.ProxyFactoryBean">
        <property name="proxyInterfaces">
            <value>org.myapp.services.MyService</value>
        </property>
        <property name="target"><ref local="MyServiceTarget"/></property>
        <property name="interceptorNames">
            <list>
                <value>timingAdvisor</value>
            </list>
        </property>
    </bean>

An important tip to point out, is needing to rename the original bean to a new name and instead naming your proxy as the original name. This will only work, if all code that expects your bean, expects an instance of the interface it implements, and you include that interface name in the proxy configuration.

Finally, I can start my application, run my tests, and analyze my logs to determine the time spent in the methods I'm interested in.

---- Cris J H