Update to Profiling Your Code with Spring

In a previous post, I described how to do some simple Timing for using Spring 1.x and the ProxyFactoryBean. I acknowledged that there might have been a way to take advantage of an existing Spring class instead of writing my own. I spent some time this last weekend, working on how to use the existing Spring class and also how to take advantage of the new Spring 2.0 XML Schema-based configuration.

There are really two separate items. Let me first handle the simpler of the two. You can replace the TimingLoggingInterceptor from the previous blog post with the Spring PerformanceMonitorInterceptor class.

Here is the previous Spring definition using TimingLoggingInterceptor.

<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>

Here is the new Spring definition using he Spring PerformanceMonitorInterceptor class.

<bean id="timingLogger" class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor"/>

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

In addition to this change you must configure a log4 property. So if you do not already have a log4j.properties file, you'll need to create one. If you already have one, you simply need to change the logging level for the PerformanceMonitorInterceptor class to the TRACE level. Here is an extremely simple log4j.properties that can be put in the root of your CLASSPATH if you do not already have one.

log4j.rootLogger=WARN, stdout

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p: %m%n

log4j.logger.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE

If you do not set the logging level for PerformanceMonitorInterceptor to TRACE then you will not get any output. However, if do set it correctly, you should see output similar to the following (depending on your log4j ConversionPattern):

2007-08-20 17:45:32,697 TRACE: StopWatch 'org.myapp.services.MyService.find': running time (millis) = 25
2007-08-20 17:45:42,674 TRACE: StopWatch 'org.myapp.services.MyService.save': running time (millis) = 16
2007-08-20 17:45:42,953 TRACE: StopWatch 'org.myapp.services.MyService.update': running time (millis) = 11

I then wanted to go a bit further and attempt to use the Spring 2.0 XML Schema-based configuration for my AOP work. In addition to the Schema-based changes, Spring 2.0 includes AspectJ style pointcut expressions.

Spring is very good at providing an incredible online reference manual, extremely verbose javadocs and even sample applications demonstrating most of the Spring framework. However, I still was unable to figure out from all those resources, exactly what I needed to do. In time, after consulting those resources plus a few Googled websites, I began to glean some idea of what was going on. Personally, I ran into two points of failing to understand how things really worked.

First, I couldn't understand how to relate the new <aop:config> and <aop:advisor> tags with the ProxyFactoryBean I had used before. After reading section 6.3 several times, I started to understand. With ProxyFactoryBean you would explicitly declare the interfaces you wanted to proxy, using the <aop:config> and <aop:advisor> tags you would automatically proxy every interface of every object in the bean container. This seemed both useful and scary at the same time. I mean, I didn't want a proxy class object created for EVERY bean in my container, but automatically detecting the interfaces my bean objects implemented did seem like it could lead to simpler configuration. While I was contemplating this problem I ran into my second difficulty. But first let me show you the configuration snippet.

<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>

<bean id="timingAdvice" class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor"/>

<aop:config>
    <aop:advisor pointcut="execution(* org.myapp.services.MyService.*(..))"
                 advice-ref="timingAdvice"/>
</aop:config>

Even after I thought I had everything set up right, things were not working. It took me a long time to determine that my pointcut expression was incorrect (the one above is correct). It was through this process, however, that I discovered the answer to my first fear. Only beans that match the pointcut, will be proxied. This worked, initially to my disadvantage because until I got the pointcut right, nothing was ever getting timed and logged.

So, the biggest challenge with the new Spring 2.0 syntax, compared the the previous ProxyFactoryBean will be to write a pointcut expression for your situation. In the above example, the pointcut will match any method in the org.myapp.services.MyService interface. If a bean does not implement the org.myapp.services.MyService interface, then no proxy will be created.

One more very minor point, I needed to include the AspectJ aspectjweaver.jar file in the group of libraries my application used. This ships with the Spring 2.0 distribution that includes dependencies in the lib/aspectj directory.

---- Cris J H