[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
[aspectj-dev] Performance Issues when exposing context from Annotations
|
Hello,
At first: If I am posting on the wrong list, I am sorry for that. I
didnt got used to mailing lists so far. (yeah computer science young
generation loves fancy Web2.0 communication tools)
I recently started to play around with AspectJ and tried an aspect based
generic logging example, where "log context configuration" (when and
what should be logged) is specified within annotations. While I had no
problems to get the example running, I have done some performance
testing. While its definitly possible that I have messed with some
"opimization guideline", maybe you will find the following test case
interesting.
Log Annotation:
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
@Retention(RetentionPolicy.RUNTIME)
public @interface Log {
String message() default "";
}
Test program:
public class SampleProgram {
public static void main(String[] args) {
System.out.println(System.getProperties());
run();
}
@Log(message="Outer")
public static void run() {
for(int i = 0; i < 1000000; i++) calc();
}
@Log(message="Inner")
public static void calc() {
for(int i = 0; i < 10; i++) Math.exp(i);
}
}
Testaspect 1:
import org.aspectj.lang.reflect.MethodSignature;
public aspect Logging {
public pointcut log(): execution(* *(..)) && @annotation(Log);
public pointcut log2(): log() && !cflowbelow(log());
before(): log() {
Log log = (Log) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Log.class);
log.message();
}
before(): log2() {
System.out.println("[" + System.currentTimeMillis() + "] [S " +
thisJoinPointStaticPart.getSignature().getName() + "]");
}
after() returning: log() {
Log log = (Log) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Log.class);
log.message();
}
after() returning: log2() {
System.out.println("[" + System.currentTimeMillis() + "] [F " +
thisJoinPointStaticPart.getSignature().getName() + "]");
}
}
Testaspect 2:
public aspect Logging2 {
public pointcut log(Log log): execution(* *(..)) && @annotation(log);
public pointcut log2(): log(Log) && !cflowbelow(log(Log));
before(Log log): log(log) {
log.message();
}
before(): log2() {
System.out.println("[" + System.currentTimeMillis() + "] [S " +
thisJoinPointStaticPart.getSignature().getName() + "]");
}
after(Log log) returning: log(log) {
log.message();
}
after() returning: log2() {
System.out.println("[" + System.currentTimeMillis() + "] [F " +
thisJoinPointStaticPart.getSignature().getName() + "]");
}
}
Testcase 1 output: (3 seconds execution time) (JIT on)
{
java.runtime.name=Java(TM) SE Runtime Environment,
java.runtime.version=1.6.0_07-b06,
java.vm.version=10.0-b23,
java.vm.vendor=Sun Microsystems Inc.,
java.vm.name=Java HotSpot(TM) Client VM,
java.vm.specification.version=1.0,
java.class.version=50.0,
java.version=1.6.0_07,
java.specification.version=1.6,
sun.arch.data.model=32,
... and more ...
}
[1259542706359] [S run]
[1259542709390] [F run]
Testcase 2 output: (49 seconds execution time) (JIT on)
{ ... same as above ... }
[1259542981187] [S run]
[1259543029781] [F run]
Testcase without aspects: round about 2 seconds
As far as I have noticed the second example is the "right" way to access
the information of an annotation, but it is more expensive than the
first dynamic access.
I hope that helps somehow and again if this is wrong place or
information provided is useless, I am sorry for wasting your time.
Mit freundlichen Grüßen (Sincerely)
Oliver Hoff