@TimedMethod Aspect Implementation

You want to do some very limited metrics gathering in Java, breaking out a profiler seems like overkill, so how can you approach this?  It’s not a new story, and the code below isn’t ground breaking, a search of the net will get you several similar articles with similar solutions.  I just wrote this up because AOP tools can be a bit finicky, and so I had to dust off my old solution, to get it working again and thought I’d share the update.

The Tried And True Answer

Profiling tools in the Java ecosystem work and are very usable, but they are often involved to set up and get working, and their power can be overwhelming.  If you just want to get a few simple data points like how long a specific method taking to execute, then AOP shines for this.  The advice you want to add it just the timing collection and logging. The join point you want is simply some specified methods.  Using AspectJ and a Java annotation you can do both of these with a very small amount of code.

So first lets create an annotation that we can tag any method with to make indicating the join points trivial.

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

public @interface TimedMethod {

Now lets use AspectJ to write the advice.

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;

import java.util.logging.Logger;

public class MethodTiming {
    private static final Logger LOGGER
            = Logger.getLogger(MethodTiming.class.getName());

    @Around("execution(@TimedMethod * *(..))")
    public Object timed(ProceedingJoinPoint pjp) throws Throwable {
        final long startTimeMillis = System.currentTimeMillis();
        try {
            return pjp.proceed();
        } finally {
            final long endTimeMillis = System.currentTimeMillis();
            LOGGER.info(" " + (endTimeMillis - startTimeMillis) + " ms " +
                    " spent in [" + Thread.currentThread().getName() + "] " +
                    pjp.getTarget().getClass().getName() + "." +
                    pjp.getSignature().getName() + "()"

The code is done.  You now need to get AspectJ set up and then you just mark any method you want timed with the @TimedMethod annotation and the timings for every invocation of the method will spew out in your logs.

Jun 17, 2016 7:42:34 PM com.github.nwillc.timeraspect.examples.Pauser pause_aroundBody1$advice
INFO: > 2000 ms spent in [Test worker] com.github.nwillc.timeraspect.examples.Pauser.pause()

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