[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
Re: [aspectj-dev] Performance Issues when exposing context from Annotations
|
Both changes are now in (bug fix and new syntax support). And
although annotation binding is now fast, annotation value binding (for
strings) is even faster in this scenario.
A simple benchmark, distilled from the original. CaseThree below is
the new syntax for directly binding annotation value strings
---
import org.aspectj.lang.*;
import org.aspectj.lang.reflect.*;
import java.lang.annotation.*;
@Retention(RetentionPolicy.RUNTIME)
@interface Marker {
String message();
}
public class Perf {
public static void main(String []argv) {
run(true);
run(false);
}
public static void run(boolean warmup) {
long stime = System.currentTimeMillis();
for (int i=0;i<1000000;i++) {
runOne();
}
long etime = System.currentTimeMillis();
long manual = (etime-stime);
stime = System.currentTimeMillis();
for (int i=0;i<1000000;i++) {
runTwo();
}
etime = System.currentTimeMillis();
long woven = (etime-stime);
stime = System.currentTimeMillis();
for (int i=0;i<1000000;i++) {
runThree();
}
etime = System.currentTimeMillis();
long optimal = (etime-stime);
if (!warmup) {
System.out.println("Manually fetching annotation with
getAnnotation(): "+manual+"ms");
System.out.println("Binding annotation with @annotation(Marker):
"+woven+"ms");
System.out.println("Binding annotation value with
@annotation(Marker(message)): "+optimal+"ms");
}
if (woven>manual) {
throw new RuntimeException("woven = "+woven+" manual = "+manual);
}
if (optimal>woven) {
throw new RuntimeException("optimal = "+optimal+" woven = "+woven);
}
}
@Marker(message="string")
public static void runOne() {
}
@Marker(message="string")
public static void runTwo() {
}
@Marker(message="string")
public static void runThree() {
}
}
aspect X {
public static int a,b,c;
// CaseOne: annotation fetching is done in the advice:
pointcut adviceRetrievesAnnotation(): execution(@Marker * runOne(..));
before(): adviceRetrievesAnnotation() {
Marker marker = (Marker) ((MethodSignature)
thisJoinPointStaticPart.getSignature()).getMethod().getAnnotation(Marker.class);
String s = marker.message();
a+=s.length();
}
// CaseTwo: annotation binding is done in the pointcut, advice
retrieves message
pointcut pointcutBindsAnnotation(Marker l): execution(@Marker *
runTwo(..)) && @annotation(l);
before(Marker l): pointcutBindsAnnotation(l) {
String s = l.message();
b+=s.length();
}
// CaseThree: annotation binding directly targets the message value
in the annotation
pointcut pointcutBindsAnnotationValue(String msg):
execution(@Marker * runThree(..)) && @annotation(Marker(msg));
before(String s): pointcutBindsAnnotationValue(s) {
c+=s.length();
}
}
---
Running it:
Manually fetching annotation with getAnnotation(): 645ms
Binding annotation with @annotation(Marker): 445ms
Binding annotation value with @annotation(Marker(message)): 3ms
I must say I've never seen a logging system that specifies the message
to log in the annotation, since normally the method signature is used
as an indication of where the system currently is. There is nothing
wrong with doing that but it goes a little way to explain the missing
optimization as it has never come up before. The logging aspects I've
seen before merely used the annotation as a marker, sometimes
expressing trace levels in it:
@Trace(TraveLevel.DEBUG)
and that kind of case which uses enums was optimized for (for matching
and binding).
If you come up with other scenarios, feel free to raise bugs for them!
cheers,
Andy
2009/11/30 Andy Clement <andrew.clement@xxxxxxxxx>:
> Yes, that is rather sub-optimal isn't it :) I'll look at the bug in a
> bit. Irrespective of that bug, the most absolute optimal way to
> express these pointcuts would probably be this:
>
> public pointcut loggedMethod() : execution(@Log * *(..));
> public pointcut log(String logMessage): loggedMethod() &&
> @annotation(Log(logMessage));
> public pointcut log2(): loggedMethod() && !cflowbelow(loggedMethod());
>
> In the middle one you can see I am binding the string property of the
> annotation directly.
>
> *unfortunately* that binding form isn't supported today (for strings)
> - it is only allowed for annotation values that are enums (see
> http://andrewclement.blogspot.com/2009/02/aspectj-optimized-annotation-value.html
> ). I might try to add support for strings whilst looking at the other
> issue.
>
> Andy
>
>
> 2009/11/30 Simone Gianni <simoneg@xxxxxxxxxx>:
>> 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/
>>
>> _______________________________________________
>> aspectj-dev mailing list
>> aspectj-dev@xxxxxxxxxxx
>> https://dev.eclipse.org/mailman/listinfo/aspectj-dev
>>
>
