[aspectj-dev] Performance Issues when exposing context from Annotations

[Oliver Hoff <oliver@xxxxxxxx>]

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