HOWTO: Simple profiling with Spring AOP

September 2, 2009 at 8:48 am Leave a comment

As part of its AOP package, Spring has a very nice little utility class called CustomizableTraceInterceptor which can be used to easily profile and debug your application using automatic logging of method invocations, including name of the method, parameters (using toString()), return values and invocation times. It doesn’t replace proper debugger and/or profiler but it can provide you a lot of interesting data with minimal cost. It can be even used in production as it can be turned on/off easily.

So how does it work? It uses Spring AOP capabilities to wrap around beans you choose to add a little code that will output invocation data before the method is called, and will output return values and execution time after it finishes. The best practise it to apply the interceptor on client facing beans – in other words entry points of your server so you can easily monitor what is called, when it’s called and how long did it take.

So how to add it? First thing you need to define a subclass of CustomizableTraceInterceptor like this:


public class MyTraceInterceptor extends CustomizableTraceInterceptor {

  protected void writeToLog(Log logger, String message, Throwable ex) {
    if (ex != null) {
     logger.info(message, ex);
    } else {
     logger.info(message);
    }
 }

 protected boolean isInterceptorEnabled(MethodInvocation invocation, Log logger) {
   return true;
 }
}

By overriding writeToLog() method you control output severity and destination. Overriding isInterceptorEnabled() allows you to finely control when tracing should happen – you could for example decide not to trace methods that start with “foo*”. Simply returning true means trace always.

Now that you have your interceptor defined it’s time to apply it to your beans. Add this to your spring.xml

    <bean name="traceInterceptor" class="MyTraceInterceptor" dependency-check="none">
        <property name="enterMessage" value="ENTER: $&#91;targetClassShortName&#93;.$&#91;methodName&#93;($&#91;arguments&#93;)"/>
        <property name="exitMessage"
                  value="EXIT: $&#91;targetClassShortName&#93;.$&#91;methodName&#93;() : $&#91;invocationTime&#93;ms : $&#91;returnValue&#93;"/>
    </bean>

    <bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator" dependency-check="none">
        <property name="beanNames" value="*RequestListener,*Notifier"/>
        <property name="proxyTargetClass" value="true"/>
        <property name="interceptorNames">
            <list>
                <value>traceInterceptor</value>
            </list>
        </property>

        <property name="order" value="2"/>
    </bean>

First definition instantiates the interceptor and defines format of the trace messages.

Second bean applies the interceptor to your beans using “beanNames” to select the beans with the wild card. If you use “*” it will mean it will wrap all your beans, so you probably want to input something meaningful here.

And that’s it. Rerun your app, call some methods and open up log files. You will see the traces there.

Advertisements

Entry filed under: Java, Open Source, Recipies.

Hit 1k reputation on StackOverflow HOWTO: Suppress EJBTHREE-1337 warning

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Trackback this post  |  Subscribe to the comments via RSS Feed


Calendar

September 2009
S M T W T F S
« Aug   Sep »
 12345
6789101112
13141516171819
20212223242526
27282930  

Most Recent Posts


%d bloggers like this: