Let's imagine you want to log the time taken by some annoted methods using a @LogExecTime
annotation.
I first create an annotation LogExecTime
:
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface LogExecTime {
}
Then I define an aspect:
@Component // For Spring AOP
@Aspect
public class LogTimeAspect {
@Around(value = "@annotation(annotation)")
public Object LogExecutionTime(final ProceedingJoinPoint joinPoint, final LogExecTime annotation) throws Throwable {
final long startMillis = System.currentTimeMillis();
try {
System.out.println("Starting timed operation");
final Object retVal = joinPoint.proceed();
return retVal;
} finally {
final long duration = System.currentTimeMillis() - startMillis;
System.out.println("Call to " + joinPoint.getSignature() + " took " + duration + " ms");
}
}
}
I create a class annoted with LogExecTime
:
@Component
public class Operator {
@LogExecTime
public void operate() throws InterruptedException {
System.out.println("Performing operation");
Thread.sleep(1000);
}
}
And a main using Spring AOP:
public class SpringMain {
public static void main(String[] args) throws InterruptedException {
ApplicationContext context = new GenericXmlApplicationContext("applicationContext.xml");
final Operator bean = context.getBean(Operator.class);
bean.operate();
}
}
If I run this class I'm getting the following output on stdout:
Starting timed operation
Performing operation
Call to void testaop.Operator.Operate() took 1044 ms
Now with the magic. As I did use Spring AOP rather than AspectJ weaver, the magic is occurring at run time using proxy-ish mechanisms. So the .class
files are left untouched. For instance if I debug this program and put a breakpoint in operate
you'll see how Spring has performed the magic:
As Spring AOP implementation is non-intrusive and uses the Spring mechanisms you need to add the @Component
annotation and create the object using Spring context rather than plain new
.
AspectJ on the other side will change the .class
files. I tried this project with AspectJ and decompiled the Operator class with jad. Which lead to:
public void operate()
throws InterruptedException
{
JoinPoint joinpoint = Factory.makeJP(ajc$tjp_0, this, this);
operate_aroundBody1$advice(this, joinpoint, LogTimeAspect.aspectOf(), (ProceedingJoinPoint)joinpoint, (LogExecTime)(ajc$anno$0 == null && (ajc$anno$0 = testaop/Operator.getDeclaredMethod("operate", new Class[0]).getAnnotation(testaop/LogExecTime)) == null ? ajc$anno$0 : ajc$anno$0));
}
private static final void operate_aroundBody0(Operator ajc$this, JoinPoint joinpoint)
{
System.out.println("Performing operation");
Thread.sleep(1000L);
}
private static final Object operate_aroundBody1$advice(Operator ajc$this, JoinPoint thisJoinPoint, LogTimeAspect ajc$aspectInstance, ProceedingJoinPoint joinPoint, LogExecTime annotation)
{
long startMillis = System.currentTimeMillis();
Object obj;
System.out.println("Starting timed operation");
ProceedingJoinPoint proceedingjoinpoint = joinPoint;
operate_aroundBody0(ajc$this, proceedingjoinpoint);
Object retVal = null;
obj = retVal;
long duration = System.currentTimeMillis() - startMillis;
System.out.println((new StringBuilder("Call to ")).append(joinPoint.getSignature()).append(" took ").append(duration).append(" ms").toString());
return obj;
Exception exception;
exception;
long duration = System.currentTimeMillis() - startMillis;
System.out.println((new StringBuilder("Call to ")).append(joinPoint.getSignature()).append(" took ").append(duration).append(" ms").toString());
throw exception;
}
private static void ajc$preClinit()
{
Factory factory = new Factory("Operator.java", testaop/Operator);
ajc$tjp_0 = factory.makeSJP("method-execution", factory.makeMethodSig("1", "operate", "testaop.Operator", "", "", "java.lang.InterruptedException", "void"), 5);
}
private static final org.aspectj.lang.JoinPoint.StaticPart ajc$tjp_0; /* synthetic field */
private static Annotation ajc$anno$0; /* synthetic field */
static
{
ajc$preClinit();
}