148007 – boolean methods with after advice return incorrect result on JRockit under WLS

Bug 148007 - boolean methods with after advice return incorrect result on JRockit under WLS

Summary: boolean methods with after advice return incorrect result on JRockit under WLS

Status:	RESOLVED FIXED

Alias:	None

Product:	AspectJ
Classification:	Tools
Component:	Compiler (show other bugs)
Version:	1.5.1
Hardware:	Macintosh Mac OS X - Carbon (unsup.)

Importance:	P3 normal (vote)
Target Milestone:	---
Assignee:	aspectj inbox
QA Contact:

URL:
Whiteboard:
Keywords:

Depends on:
Blocks:

Reported:	2006-06-21 05:27 EDT by Adrian Colyer
Modified:	2007-07-29 09:20 EDT (History)
CC List:	2 users (show)

See Also:

Attachments
Test setup to replicate issue (201.00 KB, application/octet-stream) 2006-06-21 08:00 EDT, Randy Stearns	no flags	Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Adrian Colyer

2006-06-21 05:27:01 EDT

n 21/06/06, Stearns, Randy <RStearns@knowledgestorm.com> wrote:

    I've been able to create a reproducible test. My (really pared down) aspect:
     
    public aspect LoggingAspect {
     
     pointcut logPointcut() :
      execution (* *.*(..))
      && !within(LoggingAspect);
     
     before() : logPointcut() {
       System.out.println("entering");
     }
     
        after() : logPointcut() {
                System.out.println("exiting");
        }
    }
    As it only appears in JRockit *while running in WebLogic*, I created a test servlet (below)
    As long as there is an after advice, tests 2 and 5 in the servlet return incorrect results.
    If I remove it, everything works. Also, if tests 2 and 5 return Boolean objects, it works.
     
    It appears AJ not like after advice on methods returning primitives.
    Is there a way to bypass them?
     
    Randy
     
     
    package test;
     
    import javax.servlet.ServletException;
    import javax.servlet.http.HttpServlet;
    import javax.servlet.http.HttpServletRequest;
    import javax.servlet.http.HttpServletResponse;
    import java.io.IOException;
    import java.io.PrintWriter;
     
    /**
     * Hello world!
     */
    public class TestServlet extends HttpServlet {
     
        protected void service(HttpServletRequest request, HttpServletResponse response)
                throws ServletException, IOException {
            booleanTest(response);
        }
     
        private void booleanTest(HttpServletResponse response) throws ServletException {
            PrintWriter out = null;
            try {
                out = response.getWriter();
            } catch (IOException ioe) {
                throw new ServletException("Could not get writer.");
            }
     
            out.println("Test 1a. Should be false. Was: " + invert1a());
            out.println("Test 1b. Should be true. Was: " + invert1b());
            out.println("Test 2. Should be false. Was: " + invert2());
            out.println("Test 3. Should be true. Was: " + invert3());
            out.println("Test 4. Should be true. Was: " + invert4());
            out.println("Test 5. Should be false. Was: " + invert5());
        }
     
        private boolean invert1a() {
            return ! true;
        }
     
        private boolean invert1b() {
            return ! false;
        }
     
        private boolean invert2() {
            return ! isTrue();
        }
     
        private boolean invert3() {
            return ! isFalse();
        }
     
        private boolean invert4() {
            boolean temp = isFalse();
            return ! temp;
        }
     
        private boolean invert5() {
            boolean temp = isTrue();
            return ! temp;
        }
     
        private boolean isTrue() {
            return true;
        }
     
        private boolean isFalse() {
            return false;
        }
    }

Comment 1 Adrian Colyer

2006-06-21 05:49:23 EDT

Here's the bytecode generated by ajc for test 2 (invert2):

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 2C 00 00 04 FFFFFFB5 
  Code:
   Stack=2, Locals=2, Args_size=1
   0:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   3:	invokevirtual	#108; //Method LoggingAspect.ajc$before$LoggingAspect$1$9fd5dd97:()V
   6:	aload_0
   7:	invokespecial	#92; //Method isTrue:()Z
   10:	ifeq	17
   13:	iconst_0
   14:	goto	18
   17:	iconst_1
   18:	goto	30
   21:	astore_1
   22:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   25:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   28:	aload_1
   29:	athrow
   30:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   33:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   36:	ireturn
  Exception table:
   from   to  target type
     0    21    21   Class java/lang/Throwable

  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   6      15      0    this       LTestServlet;
  LineNumberTable: 
   line 45: 6

Comment 2 Adrian Colyer

2006-06-21 06:14:10 EDT

Here's an analysis of the bytecode for invert2, it looks to be completely correct to me...

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 2C 00 00 04 FFFFFFB5 
  Code:
   Stack=2, Locals=2, Args_size=1

   // call LoggingAspect.aspectOf(), leaving result on operand stack
   0:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;

   // call the before advice method, and pop the aspect reference from
   // the stack
   3:	invokevirtual	#108; //Method LoggingAspect.ajc$before$LoggingAspect$1$9fd5dd97:()V

   // load a reference to "this" onto the stack
   6:	aload_0

   // call isTrue, pop the "this" reference from the stack, and 
   // push the result (literal 'true') onto the stack
   7:	invokespecial	#92; //Method isTrue:()Z

   // pop the return value from the stack and compare against 0 (false), if matched, goto 17
   10:	ifeq	17

   // we get here if isTrue returned true, push false onto the operand
   / /stack (code is ! isTrue() )...
   13:	iconst_0
   14:	goto	18

   // we get here if isTrue returned false, push true onto the operand
   // stack (code is ! isTrue())
   17:	iconst_1
   18:	goto	30

   // we get here if there is an exception thrown by any of the preceding
   // logic
   // save the thrown exception
   21:	astore_1
   // call aspectOf
   22:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   // invoke the after advice
   25:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   // load the thrown exception
   28:	aload_1
   // and rethrow it
   29:	athrow

   // call LoggingAspect.aspectOf, after this operand stack contains
   // [aspect instance, return value]
   30:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;

   // call the after advice, pops the aspect instance from the stack,
   // leaving the return value
   33:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V

   // return - value will be correct according to the code we compiled
   36:	ireturn


  Exception table:
   from   to  target type
     0    21    21   Class java/lang/Throwable

  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   6      15      0    this       LTestServlet;
  LineNumberTable: 
   line 45: 6

We also need to look at the compiled code for isTrue() of course, to make sure there are no surprises there either...

Comment 3 Adrian Colyer

2006-06-21 06:14:55 EDT

bytecode for isTrue():

private boolean isTrue();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 3E 00 00 05 FFFFFFCF 
  Code:
   Stack=2, Locals=2, Args_size=1
   0:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   3:	invokevirtual	#108; //Method LoggingAspect.ajc$before$LoggingAspect$1$9fd5dd97:()V
   6:	iconst_1
   7:	goto	19
   10:	astore_1
   11:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   14:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   17:	aload_1
   18:	athrow
   19:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   22:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   25:	ireturn
  Exception table:
   from   to  target type
     0    10    10   Class java/lang/Throwable

  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   6      4      0    this       LTestServlet;
  LineNumberTable: 
   line 63: 6

Comment 4 Adrian Colyer

2006-06-21 06:18:33 EDT

Analysis of isTrue() bytecode, also looks to be completely correct:

private boolean isTrue();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 3E 00 00 05 FFFFFFCF 
  Code:
   Stack=2, Locals=2, Args_size=1

   // call LoggingAspect.aspectOf, leaving object ref on stack
   0:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;

   // invoke before advice, popping object ref from stack
   3:	invokevirtual	#108; //Method LoggingAspect.ajc$before$LoggingAspect$1$9fd5dd97:()V

   // load 1 (true) onto stack
   6:	iconst_1
   7:	goto	19

   // we only get here if an exception is thrown in the preceding logic
   // store the thrown exeception
   10:	astore_1
   // call the after advice
   11:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   14:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V
   // put the thrown exception back on the stack
   17:	aload_1
   // and re-throw it
   18:	athrow

   // call LoggingAspect.aspectOf, on return stack is
   // [aspectref, true]
   19:	invokestatic	#105; //Method LoggingAspect.aspectOf:()LLoggingAspect;
   // call the after advice, popping aspectref from stack, stack is now
   // [true]
   22:	invokevirtual	#111; //Method LoggingAspect.ajc$after$LoggingAspect$2$9fd5dd97:()V

   // return true
   25:	ireturn
  Exception table:
   from   to  target type
     0    10    10   Class java/lang/Throwable

  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   6      4      0    this       LTestServlet;
  LineNumberTable: 
   line 63: 6

Comment 5 Adrian Colyer

2006-06-21 06:31:07 EDT

code for a straight javac compile of the same class (no aspects involved):

private boolean isTrue();
  Code:
   Stack=1, Locals=1, Args_size=1
   // load constant 1 (true)
   0:	iconst_1
   // return it!
   1:	ireturn
  LineNumberTable: 
   line 63: 0


private boolean invert2();
  Code:
   Stack=1, Locals=1, Args_size=1
   // push 'this' onto stack
   0:	aload_0
   // call isTrue, after this stack will contain [ true ]
   1:	invokespecial	#26; //Method isTrue:()Z

   // if the return value was not zero (true) then goto 11
   4:	ifne	11

   // we get here if isTrue returned false, push 1 (true)
   7:	iconst_1
   8:	goto	12

   // we get here if isTrue returned true, push 0 (false)
   11:	iconst_0

   // return
   12:	ireturn
  LineNumberTable: 
   line 45: 0

Comment 6 Adrian Colyer

2006-06-21 06:46:22 EDT

Attempting to create an equivalent pure java program to see how that compiles...

// an "aspect" with the appropriate members
public class MyMockAspect {

  public static MyMockAspect aspectOf() {
     return new MyMockAspect();
  }

  public void doBeforeAdvice() {}

  public void doAfterAdvice() {}

}
     

and the relevant parts of "MyTestServlet" (everything else is the same):

    private boolean invert2() {
        try {
            MyMockAspect.aspectOf().doBeforeAdvice();
          return ! isTrue();
        }
        finally {
            MyMockAspect.aspectOf().doAfterAdvice();
        }
    }


    private boolean isTrue() {
        try {
            MyMockAspect.aspectOf().doBeforeAdvice();
            return true;
        }
        finally {
            MyMockAspect.aspectOf().doAfterAdvice();
        }
    }

Comment 7 Adrian Colyer

2006-06-21 06:47:54 EDT

byte code resulting from compiling this with javac:

private boolean invert2();
  Code:
   Stack=1, Locals=3, Args_size=1
   0:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   3:	invokevirtual	#27; //Method MyMockAspect.doBeforeAdvice:()V
   6:	aload_0
   7:	invokespecial	#28; //Method isTrue:()Z
   10:	ifne	17
   13:	iconst_1
   14:	goto	18
   17:	iconst_0
   18:	istore_1
   19:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   22:	invokevirtual	#29; //Method MyMockAspect.doAfterAdvice:()V
   25:	iload_1
   26:	ireturn
   27:	astore_2
   28:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   31:	invokevirtual	#29; //Method MyMockAspect.doAfterAdvice:()V
   34:	aload_2
   35:	athrow
  Exception table:
   from   to  target type
     0    19    27   any
    27    28    27   any
  LineNumberTable: 
   line 46: 0
   line 47: 6
   line 50: 19
   line 51: 25
   line 50: 27
   line 51: 34


private boolean isTrue();
  Code:
   Stack=1, Locals=3, Args_size=1
   0:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   3:	invokevirtual	#27; //Method MyMockAspect.doBeforeAdvice:()V
   6:	iconst_1
   7:	istore_1
   8:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   11:	invokevirtual	#29; //Method MyMockAspect.doAfterAdvice:()V
   14:	iload_1
   15:	ireturn
   16:	astore_2
   17:	invokestatic	#26; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   20:	invokevirtual	#29; //Method MyMockAspect.doAfterAdvice:()V
   23:	aload_2
   24:	athrow
  Exception table:
   from   to  target type
     0     8    16   any
    16    17    16   any
  LineNumberTable: 
   line 70: 0
   line 71: 6
   line 74: 8
   line 75: 14
   line 74: 16
   line 75: 23

Comment 8 Adrian Colyer

2006-06-21 06:52:09 EDT

byte code resulting from compiling with the Eclipse JDT compiler:

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 2C 00 00 04 FFFFFFB7 
  Code:
   Stack=1, Locals=4, Args_size=1
   0:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   3:	invokevirtual	#98; //Method MyMockAspect.doBeforeAdvice:()V
   6:	aload_0
   7:	invokespecial	#101; //Method isTrue:()Z
   10:	ifeq	17
   13:	iconst_0
   14:	goto	18
   17:	iconst_1
   18:	istore_3
   19:	jsr	30
   22:	iload_3
   23:	ireturn
   24:	astore_2
   25:	jsr	30
   28:	aload_2
   29:	athrow
   30:	astore_1
   31:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   34:	invokevirtual	#104; //Method MyMockAspect.doAfterAdvice:()V
   37:	ret	1
  Exception table:
   from   to  target type
     0    22    24   any
  LineNumberTable: 
   line 46: 0
   line 47: 6
   line 49: 24
   line 51: 28
   line 49: 30
   line 50: 31
   line 51: 37
  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   0      39      0    this       LMyTestServlet;


private boolean isTrue();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 44 00 00 06 5D 
  Code:
   Stack=1, Locals=3, Args_size=1
   0:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   3:	invokevirtual	#98; //Method MyMockAspect.doBeforeAdvice:()V
   6:	jsr	17
   9:	iconst_1
   10:	ireturn
   11:	astore_2
   12:	jsr	17
   15:	aload_2
   16:	athrow
   17:	astore_1
   18:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   21:	invokevirtual	#104; //Method MyMockAspect.doAfterAdvice:()V
   24:	ret	1
  Exception table:
   from   to  target type
     0     9    11   any
  LineNumberTable: 
   line 70: 0
   line 71: 6
   line 73: 11
   line 75: 15
   line 73: 17
   line 74: 18
   line 75: 24
  LocalVariableTable: 
   Start  Length  Slot  Name   Signature
   0      26      0    this       LMyTestServlet;

Comment 9 Adrian Colyer

2006-06-21 07:31:58 EDT

the most instructive here is to compare the code that javac generates for e.g. isTrue() with the code that ajc created.

I'll reorder the instructions slightly to ease the comparison

javac                         ajc
====================================================
invokestatic aspectOf         invokestatic aspectOf
invokevirtual before_advice   invokevirtual before_advice
iconst_1                      iconst_1
istore_1                      -
invokestatic aspectOf         invokestatic aspectOf
invokevirtual after_advice    invokevirtual after_advice
iload_1                       -
ireturn                       ireturn
// finally block
astore_2                      astore_1
invokestatic aspectOf         invokestatic aspectOf
invokevirtual after_advice    invokevirtual after_advice
aload_2                       aload_1
athrow                        athrow

here you can see that javac surrunds the after advice dispatch in the main body with an astore/load pair, whereas ajc does not.

Comment 10 Adrian Colyer

2006-06-21 07:49:41 EDT

my conclusions until we get details of exact JRockit and WLS versions etc...:

This is a JRockit bug triggered by optimisations performed when JRockit is running under WLS. The bug is not often seen in the wild, because aspectj is generating a perfectly legal bytecode pattern, but one that is different to that produced by javac.

Note that using the jdt compiling with the -inlineJSR flag *also* produces the store/load pairs:

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 2C 00 00 04 FFFFFFB7 
  Code:
   Stack=1, Locals=3, Args_size=1
   0:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   3:	invokevirtual	#98; //Method MyMockAspect.doBeforeAdvice:()V
   6:	aload_0
   7:	invokespecial	#101; //Method isTrue:()Z
   10:	ifeq	17
   13:	iconst_0
   14:	goto	18
   17:	iconst_1
   18:	istore_2
   19:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   22:	invokevirtual	#104; //Method MyMockAspect.doAfterAdvice:()V
   25:	iload_2
   26:	ireturn
   27:	astore_1
   28:	invokestatic	#95; //Method MyMockAspect.aspectOf:()LMyMockAspect;
   31:	invokevirtual	#104; //Method MyMockAspect.doAfterAdvice:()V
   34:	aload_1
   35:	athrow

Since these pairs seem uneccessary from a reading of the JVM spec., but both compilers do it (jdt tries to mirror javac of course), if we could get ajc to do the same it would probably help to avoid triggering bugs of this nature in JVMs in the future...

Comment 11 Randy Stearns

2006-06-21 08:00:30 EDT

Created attachment 44988 [details]
Test setup to replicate issue

Web test executed on Weblogic 8.1 sp4. Startup notice: 
<Jun 21, 2006 6:47:20 AM EDT> <Info> <WebLogicServer> <BEA-000377> <Starting WebLogic Server with BEA WebLogic JRockit(TM) 1.4.2_05 JVM R24.4.0-1 
Version ari-38120-20041118-1131-win-ia32 from BEA Systems, Inc.>
<Jun 21, 2006 6:47:21 AM EDT> <Info> <Configuration Management> <BEA-150016> <This server is being started as the administration server.>
<Jun 21, 2006 6:47:21 AM EDT> <Info> <Management> <BEA-141107> <Version: WebLogic Server 8.1 SP4  Mon Nov 29 16:21:29 PST 2004 471647

Comment 12 Randy Stearns

2006-06-21 08:04:21 EDT

I am now able to duplicate the problem outside WLS. The UnitTest is in the test setup zip file.

Comment 13 Randy Stearns

2006-06-21 08:21:46 EDT

Compiled using AspectJ 1.5.0 release. Works as expected when WLS running Sun JVM. Also works using JRockit if the methods return an Object (Boolean) rather than a primitive. e.g. return new Boolean(! isTrue());
Let me know if I can assist further.

Comment 14 Adrian Colyer

2006-06-21 08:44:09 EDT

fantastic, thank you. I've downloaded the jrockit 1.4.2_08 vm and am able to
reproduce this failure in the AspectJ test suite using it. That's a big step
forward towards a solution...

Comment 15 Adrian Colyer

2006-06-21 09:40:56 EDT

Now that I can reproduce locally, I've been able to narrow this down further.
The bare minimum aspect you need to reproduce the bug is:

public aspect LoggingAspect {

 after() returning : execution(* invert2(..)) {}

}

The byte codes that upset the latest JRockit VM (1.4.2_08) are:

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=2, Locals=1, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  goto    15
   15:  invokestatic    #82; //Method
test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   18:  invokevirtual   #85; //Method
test/LoggingAspect.ajc$afterReturning$test
_LoggingAspect$1$188fbb36:()V
   21:  ireturn
  LocalVariableTable:
   Start  Length  Slot  Name   Signature
   0      15      0    this       Ltest/BooleanUnitTest;
  LineNumberTable:
   line 38: 0

Comment 16 Adrian Colyer

2006-06-21 09:50:51 EDT

If I change the compiler temporarily to force in the extra store / load instructions as shown in the following generated code, it *still fails*! So I have to reject the store/load hypothesis for now..

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=1, Locals=2, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  goto    15
   15:  istore_1
   16:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   19:  invokevirtual   #85; //Method test/LoggingAspect.ajc$afterReturning$test
_LoggingAspect$1$188fbb36:()V
   22:  iload_1
   23:  ireturn
  LocalVariableTable:
   Start  Length  Slot  Name   Signature
   0      15      0    this       Ltest/BooleanUnitTest;
  LineNumberTable:
   line 38: 0

Comment 17 Adrian Colyer

2006-06-21 09:58:17 EDT

This very similar bytecode (missing one goto) compiled without any aspects from the source code

private boolean invert2() {
  boolean ret = ! isTrue();
  LoggingAspect.aspectOf().after();
  return ret;
}

works without any problem.

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 5C
  Code:
   Stack=1, Locals=2, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  istore_1
   13:  invokestatic    #76; //Method purejava/LoggingAspect.aspectOf:()Lpurejav
a/LoggingAspect;
   16:  invokevirtual   #79; //Method purejava/LoggingAspect.after:()V
   19:  iload_1
   20:  ireturn
  LineNumberTable:
   line 38: 0
   line 39: 13
   line 40: 19
  LocalVariableTable:
   Start  Length  Slot  Name   Signature
   0      21      0    this       Lpurejava/BooleanUnitTest;
   13      8      1    ret       Z

So there are two possible hypothesis left: the extra goto is confusing JRockit, or there's something in the difference between the aspectOf and after() methods in my "hand written" aspect and the same methods in the ajc compiled aspect that is upsetting JRockit.

Comment 18 Adrian Colyer

2006-06-21 10:29:31 EDT

ok, next piece of evidence. I changed my "hand written" aspect to have identical names to the ajc compiled aspect.

This let me generate with straight javac the following byte code:

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=1, Locals=2, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  istore_1
   13:  invokestatic    #76; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   16:  invokevirtual   #79; //Method test/LoggingAspect.ajc$afterReturning$test
_LoggingAspect$1$188fbb36:()V
   19:  iload_1
   20:  ireturn
  LineNumberTable:
   line 38: 0
   line 39: 13
   line 40: 19
  LocalVariableTable:
   Start  Length  Slot  Name   Signature
   0      21      0    this       Ltest/BooleanUnitTest;
   13      8      1    ret       Z

this is *identical* to the ajc compiled with aspects code, bar the additional goto instruction. The test still passes with this code.

Furthermore, it then enabled me to replace the LoggingAspect.class file from my "simulated" aspect with the "real" LoggingAspect.class file as compiled from aspect source by ajc. The test *still* passed - eliminating any difference caused by the aspect methods that are invoked.

So... the *only* difference between the working and failing code is that extraneous goto. This *should* be harmless - it is definitely a JRockit bug, I can say that categorically at this point. 

Now to see if I can get rid of that unwanted goto and prove the point beyond all doubt...

[apologies to those on cc for the volume of comments on this bug]

Comment 19 Adrian Colyer

2006-06-21 10:40:47 EDT

conclusive proof. Changing the compiler to eliminate that goto causes the test to pass - I can even remove the store/load pair that I added earlier and we are still in the clear.

So this is a very bad JRockit bug, whereby having a goto instruction in which the target of the goto is simply the next instruction causes JRockit to do terrible things.

AspectJ is adding that goto because a method body may have several return statements, so each return statement is replaced by a goto that jumps to the after returning advice dispatch. An optimisation whereby we don't add this goto if there is only one return and it is the last statement in the method (i.e. it would just be a goto-next-instruction goto) could be added that would help in this case. Then I need to do further experimentation to see how  JRockit handles the case of multiple return statements...

Comment 20 Adrian Colyer

2006-06-21 11:34:26 EDT

I've properly implemented an optimisation that prevents generation of a goto for after returning advice when the target is the next instruction. This passes all tests in the suite, *and* makes the test pass on JRockit.

Changing the advice from after returning back to plain after advice still hits the bug though, so I need to look at that code path now.

Comment 21 Adrian Colyer

2006-06-21 11:54:34 EDT

after advice is implemented as "weaveAfterThrowing(); weaveAfterReturning();"

when weaving "throwing" before "returning" like this JRockit fails. Here's the bytecode: 

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=2, Locals=2, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  goto    24
   15:  astore_1
   16:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   19:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   22:  aload_1
   23:  athrow
   24:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   27:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   30:  ireturn
  Exception table:
   from   to  target type
     0    15    15   Class java/lang/Throwable

As an experiment if I swap the order, JRockit has no trouble...
weaving "returning" before "throwing" (works):

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=2, Locals=2, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  nop
   13:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   16:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   19:  ireturn
   20:  astore_1
   21:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   24:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   27:  aload_1
   28:  athrow
  Exception table:
   from   to  target type
     0    20    20   Class java/lang/Throwable

Comment 22 Adrian Colyer

2006-06-21 11:59:15 EDT

(note of course that the order swap is not an acceptable solution, it would mean that an exception throw by the after advice body would cause the after advice body to run a second time...)

Comment 23 Adrian Colyer

2006-06-21 12:54:39 EDT

I think I've nailed it... I've got the compiler to generate this:

private boolean invert2();
  org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8
   00 00 00 25 00 00 03 58
  Code:
   Stack=1, Locals=3, Args_size=1
   0:   aload_0
   1:   invokespecial   #70; //Method isTrue:()Z
   4:   ifeq    11
   7:   iconst_0
   8:   goto    12
   11:  iconst_1
   12:  istore_2
   13:  goto    25
   16:  astore_1
   17:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   20:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   23:  aload_1
   24:  athrow
   25:  invokestatic    #82; //Method test/LoggingAspect.aspectOf:()Ltest/Loggin
gAspect;
   28:  invokevirtual   #85; //Method test/LoggingAspect.ajc$after$test_LoggingA
spect$1$9fd5dd97:()V
   31:  iload_2
   32:  ireturn
  Exception table:
   from   to  target type
     0    16    16   Class java/lang/Throwable

this implementation avoids gotos where it can, and stores the return value before branching when a branch is needed. The return value is restored before
returning. I believe this works around all known variations of the JRockit bug.

time to run the full suite again...

Comment 24 Adrian Colyer

2006-06-22 00:51:56 EDT

fix committed. This does two things: 
1) avoids generating a goto that merely branches to the next instruction (replaces  the return in question with a nop instead)
2) stores the return value on the top of the stack into a temp var before branching to the after advice dispatch, and restores it later before returning

The code produced by ajc when weaving after [returning] advice is now closer to what would be produced by javac for similar code written by hand, hopefully lessening the chance of triggering other vm bugs in the future.

From the evidence I would suggest that the JRockit bug is that the (top of the?) stack is getting corrupted on a goto under certain conditions. The VM spec. is very clear that a goto does *not* change the stack.

I'm going to keep this report open as now that I have committed working code, I want to refactor it a little since the current code here is looking a little tired now...

Comment 25 Adrian Colyer

2006-06-22 02:28:21 EDT

Refactoring complete - weaveAfterReturning is now nice and clean, easy to follow. Note that other methods in BcelShadow - esp. e.g. weaveAroundInline could do with the same treatment, we should continue to refactor and tidy up the code base as we have to open up different areas for maintenance and enhancements...

Will close this report when fix is available in a build. Will also raise bug against JRockit and post bug number here when I have it.

Comment 26 Adrian Colyer

2006-06-22 06:08:17 EDT

JRockit issue number is CR283379 (there is no publicly visible issue database for JRockit, but BEA support will understand this number).

Comment 27 Marcus

2006-06-23 06:26:38 EDT

Thanks to the excellent bug report and repro, I tracked the problem down in 15 minutes and have submitted a one line fix to the JRockit code - the next time we ship public bits it will be included.  I'll file this as a request for a patch for 8.1 as well.

Now let the other VM vendors try to beat that turnaround time ;) 

Regards,
Marcus Lagergren

Comment 28 Adrian Colyer

2006-06-23 13:42:55 EDT

Now that's service :) thanks.

Comment 29 Adrian Colyer

2006-06-26 05:21:13 EDT

fix now available in latest build for download.

Comment 30 Randy Stearns

2006-07-05 08:27:58 EDT

Adrian,

Kudo to you for the expeditiousness of the fix, and to BEA for the prompt attention, as well.

Randy

Comment 31 Eclipse Webmaster

2007-07-29 09:20:24 EDT

Changing OS from Mac OS to Mac OS X as per bug 185991