[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
Re: [aspectj-dev] Performance Issues when exposing context from Annotations
|
Hi Oliver,
yes, you are writing to the right mailing list.
3 seconds against 49 is quite shocking, but I can confirm getting 4
seconds against 22 on my machine, which is wrong anyway. I'm using
AspectJ 1.6.6, compile time weaving, inside Eclipse with AJDT.
I also tried rewriting your pointcuts a bit :
public pointcut loggedMethod() : execution(@Log * *(..));
public pointcut log(Log log): loggedMethod() && @annotation(log);
public pointcut log2(): loggedMethod() && !cflowbelow(loggedMethod());
this makes log and log2 two completely different pointcut "hierarchies",
making it easier to test them out one by one.
Also, cflowbelow(log(Log)) could cause a second context extraction (very
useful for the wormhole pattern), that could make things go slower.
However, it did not change the results, still getting 3/4 seconds
against 22/23.
I removed the cflowbelow part completely, just to test only the context
extraction part :
public pointcut loggedMethod() : execution(@Log * *(..));
public pointcut log(Log log): loggedMethod() && @annotation(log);
Dynamic annotation :
before(): loggedMethod() {
Log log = (Log) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Log.class);
log.message();
}
after() returning: loggedMethod() {
Log log = (Log) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Log.class);
log.message();
}
Annotation as parameter :
before(Log log): log(log) {
log.message();
}
after(Log log) returning: log(log) {
log.message();
}
And yes, the first one takes 2/3 seconds, the second one 22/23 seconds.
Raising the number of cycles from 1 milion to 10 milion still results in
20 seconds agains 200 seconds, so a 1:10 ratio anyway.
I checked that both matched correctly, obtained the same number of calls
to advice, checked that "log" was there and no other optimization was
taking place (also sent to output log.message()).
Using javap on SampleProgram I can see that AspectJ weaves these
isntructions :
49: ldc #1; //class tests/SampleProgram
51: ldc #92; //String calc
53: iconst_0
54: anewarray #74; //class java/lang/Class
57: invokevirtual #78; //Method
java/lang/Class.getDeclaredMethod:(Ljava/lang/String;[Ljava/lang/Class;)Ljava/lang/reflect/Method;
60: ldc #71; //class tests/Log
62: invokevirtual #84; //Method
java/lang/reflect/Method.getAnnotation:(Ljava/lang/Class;)Ljava/lang/annotation/Annotation;
65: checkcast #71; //class tests/Log
68: invokevirtual #91; //Method
tests/Intercept.ajc$afterReturning$tests_Intercept$2$74fc38c9:(Ltests/Log;)V
Which, in plain java, are :
Log l =
SampleProgram.class.getDeclaredMethod("calc").getAnnotation(Log.class);
If I change
Log log = (Log) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Log.class);
To
Log log =
SampleProgram.class.getDeclaredMethod("calc").getAnnotation(Log.class);
I obtain 23/24 seconds also with dynamic annotation lookup.
So the problem is the suboptimal way used by AspectJ when weaving
@annotation(log).
I raised the bug https://bugs.eclipse.org/bugs/show_bug.cgi?id=296484 ,
and given you credit for the discovery.
Simone
Oliver Hoff wrote:
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
_______________________________________________
aspectj-dev mailing list
aspectj-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-dev
--
Simone Gianni CEO Semeru s.r.l. Apache Committer
http://www.simonegianni.it/
