One ElapsedTimeLogger Aspect to Rule Them All

Continuing from my last post, I decided to give a stab at making my aspect reusable in a way that I could apply it universally to any of those instances where I need to time the execution of some process and store the elapsed time in the result. It took a bit of work to get there, and I am sure I am doing it wrong (and DEFINITELY sure there are better ways to accomplish it), but it works… and it’s pretty nifty too.

At first I tried by simply making my result object implement an interface, but this didn’t feel very flexible. Likewise, I couldn’t for the life of me figure out how to construct a joinpoint pattern that matched a return type that implements a specified interface. The only way to make it match would be to have the “timed” methods return the interface, something I didn’t want since it would render the result type useless to the caller. This led me to dig in and read more about annotations and aspects, and I decided on how I wanted to be able to use a custom annotation for it.

public class TimeWaster {
	@TimedMethod(field="elapsedTime")
	public SomeResponse makeLongRequest(){
		for(long i = 0L; i < 200000000L;i++);
		return new SomeResponse("FOO");
	}
}

Basically, I just want to annotate the method being timed, and specify the field to store the elapsed time on the result object. The annotation (of course) was easy enough to make (while remembering to include the whole RetentionPolicy.RUNTIME so I could access it at runtime, I always forget):

@Retention(RetentionPolicy.RUNTIME)
public @interface TimedMethod {
	String field();
}

The heart of the aspect is, naturally, the pointcut specifying the joinpoint I want to match. Basically, match any method call with that has the annotation @TimedMethod:

pointcut makeCall(): execution(@TimedMethod * *(..));

The rest is some quickly hacked together nasty reflection code to find the setter for the field specified and invoke it with the elapsed time. So here's the mess in it's entirety, feel free to critic it as I'd like to know how I could clean it up. ;)

package org.jamescarr;
public aspect ElapsedTimeLogger {
	private static final StopWatch TIMER = new StopWatch();

	pointcut makeCall(): execution(@TimedMethod * *(..));

	Object around():makeCall(){
		TIMER.start();
		Object resp = proceed();
		TIMER.stop();

		Signature sig = thisJoinPointStaticPart.getSignature();
		if (sig instanceof MethodSignature) {
			Method method = ((MethodSignature) sig).getMethod();
			if (methodHasTimedAnnotation(method)) {
				TimedMethod annotation = getTimedMethodAnnotation(method);
				setElapsedTime(resp, annotation, TIMER.getTime());
			}
		}
	return resp;
	}

	private TimedMethod getTimedMethodAnnotation(final Method m) {
		TimedMethod annotation = m.getAnnotation(TimedMethod.class);
		return annotation;
	}
	
	private boolean methodHasTimedAnnotation(final Method m) {
		return m.isAnnotationPresent(TimedMethod.class);
	}

	private void setElapsedTime(Object resp, TimedMethod annotation,
			long elapsedTime) {
		try {
			Method m = getElapsedTimeAssigner(annotation, resp.getClass());
			if (m != null) {
				m.invoke(resp, new Object[] { elapsedTime });
			}
		} catch (Exception e) {
			throw new RuntimeException(e);
		} 
	}

	private Method getElapsedTimeAssigner(TimedMethod annotation, Class clazz) {
		Method m;
		try {
			m = clazz.getMethod("set"+StringUtils.capitalize(annotation.field()),
					new Class[] { long.class });
			return m;
		} catch (SecurityException e) {
			throw new RuntimeException("Target method should be accessible", e);
		} catch (NoSuchMethodException e) {
			throw new RuntimeException("'field' attribute of annotation should specify a field of type long with a provided public setter.",e);
		}
	}
}

Seems like it does the trick. Although it does seem complex (and I wouldn't say it was a good idea if I only had one instance of such a thing going on), it is 100% reusable and saves both the tedious code duplication and the SRP violation of including timing functionality inside of each and every method that requires it. I'll probably refactor it a little, but you get the picture.

As an aside note, I was curious if perhaps my approach would actually increase the elapsed time, so I ran a few unscientific benchmarking tests... on average the aspect approach performed close to the local method approach... and the increase in time was only off by a few milliseconds at best (nothing to die over). Fun stuff.

  • http://blog.jinspired.com William Louth

    Alternatively you could have used (or extended) JXInsight 5.5 AspectJ extension packs (300+) for resource metering, runtime state inspection, contextual tracing…..

    JXInsight 5.5 and AspectJ – Sample Application
    http://blog.jinspired.com/?p=132

    Kind regards,

    William