[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
Re: [aspectj-dev] Performance Issues when exposing context from Annotations
|
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
>
