Performance logging with aspects

Aspect weaving is very neat way of doing things without cluttering your code. Today I’m looking into easy ways to monitor/profile performance of parts of my code. To do this I would like to be able to easily do something like this:

public void work() {
    StopWatch time = new StopWatch();
    time.start();
    logger.debug("Start working");
    doStuff();
    doSomethingElseMaybe();
    time.stop();
    logger.debug("time spent: " + time);
}

Even if code above might seem as not so intrusive, imagine monitor 10,100, 1000 methods like that? First of all you write same code over and over (and we know that is just…) but also it’s just bloat. I wan’t my code to stay clean!
This is where aspects come to rescue! Perf4j is a nice library that implements these things ‘manually’ or with aspect weaving (it can also parse logs for statistical data used in graphs/charts, and much more).

If using AspectJ compiler is not available (in order to do some really nice stuff you should try it out) or just something that feels wrong to integrate in your Java project there is a more ‘lightweight’ approach using Spring AOP. That, of course if you are using Spring as your LC container. This will be resulting code change:

@Profiled
public void work() {
    doStuff();
    doSomethingElseMaybe();
}

Note that the only thing we need to add to method being monitored is a simple annotation – @Profiled (after we removed old timing and logging code). This might be resulting log when this method executes:

INFO 2014-02-26 18:28:21,051 [AWT-EventQueue-0] org.perf4j.TimingLogger:353 - start[1393435700810] time[241] tag[work]

Now, that tag[work] thing might not be that descriptive, change this by customizing annotation values:

@Profiled(tag = "Time to do this mystical stuff", logFailuresSeparately = true)

then log-row becomes:

INFO 2014-02-26 18:29:21,051 [AWT-EventQueue-0] org.perf4j.TimingLogger:353 - start[1393435700810] time[241] tag[Time to do this mystical stuff.success]

Much better. Time[241] is milliseconds. Note also ‘.success’ in the end of tag, this is the result of using logFailuresSeparately flag, it will differentiate if method ran successfully or not.

Bellow is what is needed (using Maven) in order to activate Spring AOP and perf4j-based performance logging, dependencies first:

<!-- AOP functionality of Perf4J -->
<dependency>
    <groupId>org.perf4j</groupId>
    <artifactId>perf4j</artifactId>
    <version>0.9.16</version>
    <scope>compile</scope>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>1.6.11</version>
</dependency>
<dependency>
    <groupId>commons-jexl</groupId>
    <artifactId>commons-jexl</artifactId>
    <version>1.1</version>
    <scope>runtime</scope>
</dependency>
<dependency>
    <groupId>cglib</groupId>
    <artifactId>cglib</artifactId>
    <version>2.2</version>
</dependency>

These are the actual version by this date (you might check for newer ones though). Then some spring config:

<aop:aspectj-autoproxy/>
<!-- TimingAspect that we want to weave into other beans -->
<bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>

don’t forget namespace and that stuff:

xmlns:aop="http://www.springframework.org/schema/aop"
http://www.springframework.org/schema/aop
http://www.springframework.org/schema/aop/spring-aop-2.0.xsd

There are some drawback when using Spring compared to AspectJ:

• Any objects to be woven must exist as Spring-managed beans declared in the Spring container. This is necessary because, in order to wrap object instances with the required proxies, the Spring container needs to control the lifecycle of your objects.
• Any method being @Profiled MUST be a public method.
• If you have a method on your spring bean that calls another @Profiled method directly, then that method will NOT be timed as you will not be going through the Spring proxy to make the call. Note this is NOT the case when using AspectJ directly. The Spring documentation explains the effect proxies have on AOP-enabled methods.

But if you can live with this, you’re set. That’s all, happy weaving!