Using AOP for Measuring Elapsed Time
December 27th, 2007 by James CarrRecently I’ve been knee deep in some legacy code doing a fair bit of refactoring, and one of the patterns I keep coming across is processes that need their elapsed time measured. You know what I’m talking about… a procedural mess shock full of primitive obsession all over, something like the following (except imagine that the for loop is some time intensive process):
public class TimeWaster {
public SomeResponse makeLongRequest(){
long start = System.currentTimeMillis();
for(long i = 0L; i < 200000000L;i++);
SomeResponse resp = new SomeResponse("FOO");
long end = System.currentTimeMillis();
resp.setElapsedTime(end - start);
return resp;
}
}
Of course, the knee jerk response will be to hide the primitive long values manipulated all over behind some kind of abstraction, such as:
private static final StopWatch TIMER = new StopWatch();
public SomeResponse makeLongRequest(){
TIMER.start();
for(long i = 0L; i < 200000000L;i++);
SomeResponse resp = new SomeResponse("FOO");
TIMER.stop();
resp.setElapsedTime(TIMER.getTime());
return resp;
}
A little better… but there’s still something fishy here… why does my class (despite the fact I selected the random name of timewaster) need to know about a timer? It has two roles now… generating the SomeResponse (again, remember the for loop is an assumed time intensive process of generating SomeResponse) and timing the time it takes to generate that response.
To solve this problem, we can move the timing process to an aspect, measuring the execution of the makeLongRequest using an around advice, which allows us to invoke the target method as well as modify any input and output values before returning (this is also ideal for contraint checking). So to begin, and especially since aspects can be a little tricky, we construct a very simple aspect… containing only a pointcut and a sysout in an after advice (which is called after the method finishes):
public aspect TimeWasterTimer {
pointcut makeCall(): call(SomeResponse TimeWaster.makeLongRequest());
after(): makeCall(){
System.out.println("Pointcut worked..");
}
}
I run the tests and see that yep…. that worked. So, to start small, we’ll make an around advice that simply returns the return value and run the tests to make sure they pass.
public aspect TimeWasterTimer {
pointcut makeCall(): call(SomeResponse TimeWaster.makeLongRequest());
SomeResponse around():makeCall(){
SomeResponse resp = proceed();
return resp;
}
}
Tests pass, so let’s remove the timing code completely and run tests.
public class TimeWaster {
public SomeResponse makeLongRequest(){
for(long i = 0L; i < 200000000L;i++);
return new SomeResponse("FOO");
}
}
Now all of our tests related to elapsed time fail… perfect. Now to finish things off, we simply move the timing code to the aspect and set the elapsed time on the response before it’s returned.
public aspect TimeWasterTimer {
private static final StopWatch TIMER = new StopWatch();
pointcut makeCall(): call(SomeResponse TimeWaster.makeLongRequest());
SomeResponse around():makeCall(){
TIMER.start();
SomeResponse resp = proceed();
TIMER.stop();
resp.setElapsedTime(TIMER.getTime());
return resp;
}
}
Rerun tests, and everything is green. Sweet! 
In this case, we were able to split out the responsibility of measuring execution time to a separate module by using an Aspect, allowing for a better separation of concerns. We could take this a step further an make it generic enough to be used in all cases that elapsed time is measured, perhaps by having an interface for classes that record elapsed time and a pointcut with some complex joinpoint matching magic. I’d also be interested in any alternative solutions others have come up with to solve this problem (I know Spring AOP is another way of tackling it).
Stay turned for more posts on Aspect Oriented Programming. 
