Andy is right with everything he said. Because you seem to be a beginner in AspectJ as well as Java, I have refactored your sample code a bit in order to help you get started. Things I noticed along the way:
- You use a very old AspectJ version 1.6.10. It is from 2010 and not even the latest 1.6 version (which would be 1.6.12). How about using the current AspectJ version 1.8.6?
- I am a clean code guy and noticed that your class names are rather obfuscating what you want to demonstrate with the sample code. So I renamed them:
Test → ApplicationTestAspect → HelperAspectTest → MyAnnotationAspectJTest → MethodInterceptor
- I also changed the
Helper methods' return types so as to return something other than void in order to demonstrate the next issue.
- Your
@Around advice has a return type of void. This way it does not work if the pointcut hits a non-void method. I changed the return type to Object and the code to return the result of proceed() in order to show how this can be done in a more generic way.
- Your
@Around advice always logs the same message. I updated it to log the actual joinpoint info (before and after the proceed() call) so we can see what is happening on the console log.
- As Andy said, obviously you plan to use the annotation in order to match annotated methods with a pointcut. Thus, I changed the retention scope to
RUNTIME.
- Your pointcut targets all method executions including
Application.main and Helper.doItWithout. I changed the pointcut to only target methods either bearing @MyAnnotation or with a substring "Aspect" in their method name.
- You seem to wish to profile method execution times and compare methods with aspects applied to methods not targeted by aspects. Instead of creating lots of
Date instances and calling new Date().getTime() (returns milliseconds) you can just use System.nanoTime() (returns nanoseconds).
- When profiling, you want to measure method execution time, not object creation time. Thus, I changed the code to just create one
Helper instance which is then reused throughout the main method.
- The
Application class does not need an empty default constructor because it will be generated automatically by the JVM.
- In order to get meaningful profiling results you should use a bigger number of repetitions (such as a million). I introduced a constant named
LOOP_COUNT in order to simplify this for all three loops.
- Attention! If you want to measure method execution times you should not print anything in your aspect because then you would also be measuring the time it takes to write something to the console. Thus, I have commented out the printing statements in the aspect. You can still activate them for smaller numbers of repetitions in order to see what is going on.
Refactored code:
package oata;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Target(value = ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface MyAnnotation {}
package oata;
import oata.MyAnnotation;
public class Helper {
public double doItWithout(int i) {
return Math.acos(i);
}
@MyAnnotation
public double doItAnnotated(int i) {
return Math.acos(i);
}
public double doItAspect(int i) {
return Math.acos(i);
}
}
package oata;
public class Application {
private static final int LOOP_COUNT = 100000000;
public static void main(String arg[]) {
Helper helper = new Helper();
System.out.printf(
"Profiling statistics for %,d repetitions%n%n",
LOOP_COUNT
);
long startTime = System.nanoTime();
for (int i = 0; i < LOOP_COUNT; i++)
helper.doItWithout(i);
System.out.printf(
"Method not targeted by aspect:%n %,15d ns%n",
System.nanoTime() - startTime
);
startTime = System.nanoTime();
for (int i = 0; i < LOOP_COUNT; i++)
helper.doItAnnotated(i);
System.out.printf(
"Method targeted by aspect because it is annotated:%n %,15d ns%n",
System.nanoTime() - startTime
);
startTime = System.nanoTime();
for (int i = 0; i < LOOP_COUNT; i++)
helper.doItAspect(i);
System.out.printf(
"Method targeted by aspect because of its name:%n %,15d ns%n",
System.nanoTime() - startTime
);
}
}
package oata.aspect;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
@Aspect
public class MethodInterceptor {
@Around("execution(@oata.MyAnnotation * *(..)) || execution(* *Aspect*(..))")
public Object around(ProceedingJoinPoint jp) throws Throwable {
// System.out.println("BEFORE " + jp);
Object result = jp.proceed();
// System.out.println("AFTER " + jp);
return result;
}
}
Sample console log for 1 repetition with aspect log statements enabled:
Profiling statistics for 1 repetitions
Method not targeted by aspect:
153.893 ns
BEFORE execution(double oata.Helper.doItAnnotated(int))
AFTER execution(double oata.Helper.doItAnnotated(int))
Method targeted by aspect because it is annotated:
3.102.128 ns
BEFORE execution(double oata.Helper.doItAspect(int))
AFTER execution(double oata.Helper.doItAspect(int))
Method targeted by aspect because of its name:
55.295 ns
As you can see here, the results are not very conclusive with just one call per method.
Sample console log for 100,000,000 (a hundred million) repetitions with aspect log statements disabled:
Profiling statistics for 100.000.000 repetitions
Method not targeted by aspect:
843.407.034 ns
Method targeted by aspect because it is annotated:
1.219.571.173 ns
Method targeted by aspect because of its name:
1.175.436.574 ns
Now the result is more conclusive: The method not targeted by any aspect is executed more quickly than the next two methods which have about equal execution time of 1.2 seconds, which was to be expected because the pointcuts used can be determined statically during compilation time (for CTW) or weaving time (for LTW).
