Bug 41536 - Debug information getting lost in weaver ?
Summary: Debug information getting lost in weaver ?
Status: RESOLVED FIXED
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: 1.1.1   Edit
Hardware: PC Windows XP
: P2 normal (vote)
Target Milestone: ---   Edit
Assignee: Erik Hilsdale CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2003-08-14 08:08 EDT by George Harley CLA
Modified: 2012-04-03 16:18 EDT (History)
1 user (show)

See Also:


Attachments
Fix for missing debug info (3.77 KB, patch)
2003-08-18 08:39 EDT, Andrew Clement CLA
aclement: iplog+
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description George Harley CLA 2003-08-14 08:08:57 EDT
This is being raised in response to a problem highlighted in the users list by 
Oliver Kuntze in two postings on Aug 12th and Aug 14th. 

Using AJDT 1.1.3 with Eclipse 2.1.1, it looks like some debug information for 
local variables in instance methods of Java classes goes amiss when an aspect 
cross-cuts into that class. The observed consequence of this is that when 
stepping though the Java code in the Eclipse debugger perspective all of a Java 
class' instance variables are visible but some or all of the local variables 
declared in a method are not.

Note, the unexpectd behaviour does not appear to be affected by :-
* choice of JVM (tried with IBM 131 and Sun 141)
* AJDT level (tried with 1.1.2 and 1.1.3)
* Eclipse level (tried with 2.1.1 and 2.1.0)


Simple test case follows ...

File 1 : MyClass.java
---------------------

package my.java.classes;

public class MyClass
{
    String instanceString = "abc";
    
    public static void main(String[] args)
    {
        MyClass mc = new MyClass();
        mc.doSomething();
        System.out.println("All done");        
    }

    private void doSomething()
    {
        int localInt = 0;
        String localString = null;
        
        for (int i = 0; i < 3; i++)
        {
            localInt++;
            localString = Integer.toString(localInt);
            System.out.println("localString = " + localString);
        }
    }
}
 
File 2 : MyAspect.java
----------------------

package my.aspects;

public aspect MyAspect
{
    pointcut sayHi() : call(* my.java.classes.MyClass.doSomething(..));
    
    before() : sayHi()
    {
        System.out.println("Hi from MyAspect");
    }
}

Build the above files in an Eclipse AspectJ project and then run in debug mode 
with a breakpoint at the start of the doSomething() method. When the break point 
is reached continue to step through the method and you will see that localInt 
and localString do not show up in the variables view. When the value of 
localString is set in the for loop it appears in the variables view but localInt 
never does. 

Now, comment out the body of MyAspect and rebuild the project. 

When you run and debug the project now you will see that localInt and 
localString are both present in the variables view as expected.
Comment 1 Andrew Clement CLA 2003-08-17 14:08:52 EDT
Thought I'd add a comment before Jim looks at it too much :)

George and me(andy) (and we'll drag in Erik as required) are looking at this.  
Doing some rudimentary comparisons of the localvariabletable for a method have 
revealed something interesting.  Here is the method I was using:

public static void callfoo2(int input1,String input2, Integer input3,String 
input4) {
	int a,b;
	String monkey;
	String elephant  = "custard";
	String discarded  = "not_used";
	a =1;
	b=2;
	System.err.println(input4);
	monkey = "fubar";
	System.err.print(elephant);
	System.err.print(monkey);
	b = b + a;
	System.err.println(a+" "+b);
  }

We have a tool that dumps the LocalVariableTable - If I run 'javac -g' to 
compile the class containing that method and then dump the LVT for the method:
0=input1(I) {0-80}, 
1=input2(Ljava/lang/String;) {0-80}, 
2=input3(Ljava/lang/Integer;) {0-80}, 
3=input4(Ljava/lang/String;) {0-80}, 
4=a(I) {11-79}, 
5=b(I) {14-79}, 
6=monkey(Ljava/lang/String;) {25-79}, 
7=elephant(Ljava/lang/String;) {4-79}, 
8=discarded(Ljava/lang/String;) {8-79}

(That is [slotnumber]=[methodname]([type]) {[startPC]-[endPC]})

If I compile with the JDT compiler, the table is almost identical:
0=input1(I) {0-80}, 
1=input2(Ljava/lang/String;) {0-80}, 
2=input3(Ljava/lang/Integer;) {0-80}, 
3=input4(Ljava/lang/String;) {0-80}, 
4=a(I) {11-80}, 
5=b(I) {14-80}, 
6=monkey(Ljava/lang/String;) {25-80}, 
7=elephant(Ljava/lang/String;) {4-80}, 
8=discarded(Ljava/lang/String;) {8-80}

Now if I compile with ajc from the command line from the current 1.1 release 
(with extra command line options '-g -preserveAllLocals'), I get this (oh dear):
3=input4(Ljava/lang/String;) {17-17}, 
4=a(I) {43-57}, 
5=b(I) {41-70}, 
6=monkey(Ljava/lang/String;) {36-36}, 
7=elephant(Ljava/lang/String;) {28-28}

After a few hours hacking at a fix, my own current version of aspectj produces 
this after 'ajc -g -preserveAllLocals':
0=input1(I) {0-82}, 
1=input2(Ljava/lang/String;) {0-82}, 
2=input3(Ljava/lang/Integer;) {0-82}, 
3=input4(Ljava/lang/String;) {0-82}, 
4=a(I) {11-82}, 
5=b(I) {14-82}, 
6=monkey(Ljava/lang/String;) {25-82}, 
7=elephant(Ljava/lang/String;) {4-82}, 
8=discarded(Ljava/lang/String;) {8-82}

This is almost identical to javac/jdt but the method has grown by two bytes - 
that doesn't seem too serious, at least the ranges for each field are correct 
and we haven't lost any variables.  

Fundamentally, there appears to be a bug in LazyMethodGen where we consider 
the 'range' of a local variable to be from the first localvariableinstruction 
involving it, until the last.  Rather than from the first localvariabletag to 
the last.  So, I have changed:

} else if (targeter instanceof LocalVariableTag) {
  LocalVariableTag lvt = (LocalVariableTag) targeter;
  if (i instanceof LocalVariableInstruction) {
    int index = ((LocalVariableInstruction)i).getIndex();
    if (lvt.getSlot() == index) {
      if (localVariableStarts.get(lvt) == null) {
        localVariableStarts.put(lvt, jh);
      }
      localVariableEnds.put(lvt, jh);
    }
  }
}

to 

} else if (targeter instanceof LocalVariableTag) {
  LocalVariableTag lvt = (LocalVariableTag) targeter;
  if (localVariableStarts.get(lvt) == null) {
    localVariableStarts.put(lvt, jh);
  }
  localVariableEnds.put(lvt, jh);
}

And that makes the ranges correct (at least I think thats my change that caused 
ranges to work, I've got patches all over the weaver right now).  The one thing 
I need to check is that local-local variables within a method (e.g. loop 
iterator variables) don't have a range that goes from their creation to the end 
of the method - they should have a range from their creation until the end of 
their relevant block/scope.

Although that made the ranges correct, I still had to patch BCEL so it 
didn't 'lose' some of our local variables - as per my patch in 39470.  I think 
there is a real problem in the BCEL LocalVariableGen class as it implements 
equals but not hashCode - I'm currently discussing this problem with Erik.

I can imagine that when this defect is finished, we enhance the testsuite with 
our localvariabletable dump utility (from Matthew) and then add some tests to 
verify no debug info is lost.
Comment 2 Andrew Clement CLA 2003-08-18 04:52:02 EDT
It turns out that what I appended yesterday is not the complete fix, I'm 
working on which bits of my heavily modified aspectj are the minimum set to 
make this work.
Comment 3 Andrew Clement CLA 2003-08-18 08:35:29 EDT
Ok.  I've fixed the problem (I think?), the patch is attached.  It consists of 
3 small changes:

- The first is as per the snippet I appended previously.  

- The second is a fix to prevent us nulling out the start/end fields of a 
LocalVariableGen (done in LazyMethodGen).

- The third is a fix to Eriks fix for 39470.  Erik got round the BCEL thing (of 
generating duplicate localvariable entries for parameters) by avoiding 
processing duplicates for a slot - unfortunately there is no guarantee that the 
generated duplicates will be processed *after* the real LocalVariableGens.  So 
my fix for that was to sort the entries by name before processing them - using 
a special comparator that puts anything starting 'arg' at the end of the list - 
that way the generated ones should all be left until last and they should be 
ignored.

The results are:

Compiling Georges example with JDT and then running 'javap -l MyClass' gives:
Local variables for method void doSomething()
   MyClass this  pc=0, length=48, slot=0
   int localInt  pc=2, length=46, slot=1
   java.lang.String localString  pc=4, length=44, slot=2
   int i  pc=6, length=41, slot=3

Compiling with old 'ajc -g -preserveAllLocals':
Local variables for method void doSomething()
   int localInt  pc=9, length=4, slot=1
   java.lang.String localString  pc=16, length=14, slot=2
   int i  pc=39, length=4, slot=3

With my patched aspectj 'ajc -g -preserveAllLocals':
Local variables for method void doSomething()
   MyClass this  pc=0, length=48, slot=0
   int localInt  pc=2, length=46, slot=1
   java.lang.String localString  pc=4, length=44, slot=2
   int i  pc=6, length=42, slot=3

I've also rebuilt AJDT and checked that I can step through in the debugger and 
see the correct output.  Are my fixes are reasonable?  It seems the tests all 
still pass.
Comment 4 Andrew Clement CLA 2003-08-18 08:39:12 EDT
Created attachment 5792 [details]
Fix for missing debug info
Comment 5 Jim Hugunin CLA 2003-08-25 12:50:53 EDT
Erik has taken over reviewing and applying this patch.  I believe he has already
done that and is just waiting for me to give him control over the bug...
Comment 6 Erik Hilsdale CLA 2003-09-09 13:35:55 EDT
fix applied