Do method profiling ( Basic execution time ) With Spring AOP

Question

I'm looking for a feature or software, who will allow me to easily profile my method execution time and choose what to profile by package filter.

I know, it's profiler 101. I use the TPTP profiler. But I'm not happy with it. To be frank I just don't understand how it works, and when I profile my application (launch the server in profiling mode), it takes forever to do nothing. (well, not what I expect: a simple output of execution time)

So I do the profiling myself with system time (add a line at beginning and at ending of methods). It's not so bad.

My question is : I want to measure system time before and after a method call with Spring AOP, can you give me direction? It's a good / bad idea ? The code base is pretty large, and we don't have many unit tests, can't it be "dangerous" ?

I'm not asking for code, I think I can do it myself with this kind of link : http://static.springsource.org/spring/docs/2.5.x/reference/aop.html

But if you have a nice tutorial ( never done AOP before, just know the concept), I take it.

Answer 1

There is a built in support for that in Spring.

I tried to look for tutorial but surprisingly I have not found one so I will try to explain it here. (EDIT: I added this example to my blog here)

Basically what you need is to extend CustomizableTraceInterceptor class 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;
  }
}

This class wraps around your beans and outputs method call information, including parameters, return values and execution time to a log. By changing writeToLog() method you control where you want to output the data and at what severity.

Now you need some XML to actually select which beans you are going to wrap:

    <!-- Tracing -->

<bean name="traceInterceptor" class="MyTraceInterceptor" dependency-check="none">

    <property name="enterMessage" value="ENTER: $[targetClassShortName].$[methodName]($[arguments])"/>

    <property name="exitMessage"

              value="EXIT: $[targetClassShortName].$[methodName]() : $[invocationTime]ms : $[returnValue]"/>

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

Basically you define the beans you want to wrap with a wildcard in "beanNames" and "order" controls the ordering of wrapping - if you don't have other AOP classes you can remove it. You can also change the format of output if you change enterMessage and exitMessage properties.

That should be enough to get you started. If you need clarifications don't hesitate to ask.

Answer 2

The AOP approach would work but depending on how you're planning to log the information could itself effect performance - just be aware of that, make sure the logging is efficient as possible and make sure your error handling it on-point in your aspect.

You might also want to look as Visual VM - I was impressed by this tool, it's easy to use and was able to provide me with just the information I needed when I last used it.