Incorrect line numbers in code using optimized primitive operations

Hi Peter,

The following code does produce line number info:

int i = 5*5
i++
println 1+1
i += 2

Here's the result:

public run()Ljava/lang/Object;
L0
INVOKESTATIC script.$getCallSiteArray ()[Lorg/codehaus/groovy/runtime/callsite/CallSite;
ASTORE 1
INVOKESTATIC org/codehaus/groovy/runtime/BytecodeInterface8.isOrigInt ()Z
IFEQ L1
GETSTATIC script.__$stMC : Z
IFNE L1
INVOKESTATIC org/codehaus/groovy/runtime/BytecodeInterface8.disabledStandardMetaClass ()Z
IFNE L1
GOTO L2
L1
LINENUMBER 1 L1
ALOAD 1
LDC 1
AALOAD
ICONST_5
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
ICONST_5
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.call (Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.intUnbox (Ljava/lang/Object;)I
ISTORE 2
L3
ILOAD 2
POP
L4
LINENUMBER 2 L4
ILOAD 2
DUP
ISTORE 3
ALOAD 1
LDC 2
AALOAD
SWAP
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.call (Ljava/lang/Object;)Ljava/lang/Object;
DUP
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.intUnbox (Ljava/lang/Object;)I
ISTORE 2
POP
ILOAD 3
POP
L5
LINENUMBER 3 L5
ALOAD 1
LDC 3
AALOAD
ALOAD 0
ALOAD 1
LDC 4
AALOAD
ICONST_1
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
ICONST_1
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.call (Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.callCurrent (Lgroovy/lang/GroovyObject;Ljava/lang/Object;)Ljava/lang/Object;
POP
L6
LINENUMBER 4 L6
ALOAD 1
LDC 5
AALOAD
ILOAD 2
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
ICONST_2
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.call (Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
DUP
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.intUnbox (Ljava/lang/Object;)I
ISTORE 2
ARETURN
L7
GOTO L8
L2
LINENUMBER 1 L2
ICONST_5
ICONST_5
IMUL
ISTORE 4
L9
ILOAD 4
POP
L10
LINENUMBER 2 L10
ILOAD 4
DUP
ISTORE 5
ICONST_1
IADD
DUP
ISTORE 4
POP
ILOAD 5
POP
L11
LINENUMBER 3 L11
ALOAD 1
LDC 6
AALOAD
ALOAD 0
ICONST_1
ICONST_1
IADD
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
INVOKEINTERFACE org/codehaus/groovy/runtime/callsite/CallSite.callCurrent (Lgroovy/lang/GroovyObject;Ljava/lang/Object;)Ljava/lang/Object;
POP
L12
LINENUMBER 4 L12
ILOAD 4
ICONST_2
IADD
DUP
ISTORE 4
INVOKESTATIC org/codehaus/groovy/runtime/typehandling/DefaultTypeTransformation.box (I)Ljava/lang/Object;
CHECKCAST java/lang/Integer
ARETURN
L8
ACONST_NULL
ARETURN
LOCALVARIABLE this Lscript; L0 L8 0
LOCALVARIABLE i I L3 L7 2
LOCALVARIABLE i I L9 L8 4
MAXSTACK = 5
MAXLOCALS = 6
}

L1 corresponds to the start label of "slow path" and is correctly linked to line 1 : LINENUMBER 1 L1.
L2 corresponds to the start label of optimized bytecodeand is correctly linked to line 1: LINENUMBER 1 L2.

I'm using master for tests, maybe this has already been fixed, but I'm surprised because there doesn't seem to be differences in source code regarding that part.

Hi Cedric, thanks for looking at the issue. For some reason javap shows only one bytecode instruction per line number, and you have two of them. Is this allowed at all? The JVM (HotSpot 1.6.0_26-b03) seems to ignore the L2 mapping as well.

Yes, either it is not supported by the JVM, or ASM doesn't produce a correct line number table in that situation... I'm investigating, but I can't find explicit documentation about that.

Interestingly, http://java.sun.com/docs/books/jvms/second_edition/html/ClassFile.doc.html

Furthermore, multiple LineNumberTable attributes may together represent a given line of a source file; that is, LineNumberTable attributes need not be one-to-one with source lines.

Can there be a problem with ASM writing just one line number?

I am also having the problem with Groovy 1.8.5. Breakpoints are being missed in very many places in code/large project. Usually we can workaround by putting in a println and then breaking on that, but it is very cumbersome.

Is there are compiler option in 1.8.5 to turn off these optimizations ?

We're constantly getting bug reports to IDEA because of this issue, today already 3 of them. That's quite tiresome.

I'm totally surprised that there has been 0 activity, updates or prioritizing this bug since it was logged last year.

It's like the Groovy maintainers have disappeared, or are focused on Groovy conferences? (sorry subjective but this user is feeling abandoned).

Day to day, using Groovy has become bad joke because you can't debug it, our code coverage tools are useless as well because line #s don't match executed bytecode.

Again, it is in Groovy 1.8.6 which is production. This is NOT just a 2.0 prototype issue.

Peter and Jason, we are aware of the problem, the question is how the bytecode must look to satisfy the debuggers you are using. If you can answer this question, then we can fix the issue quite fast. Also I think almost all 1.8 versions should have that problem since I suspect it is tied to primitive optimizations. I can only suspect and not know, since Cedric already proofed that the information is there, only not picked up by the debugger. primtive optimizations are most likely, since they are the biggest bytecode change since 1.7. To disable them for the groovy command use "--disableopt=all" and for groovyc there is no option to disable them atm.

JDK 1.6 on OS/X, IntelliJ 11.x. But also occurres on STS, Eclipse, JDK 7 on OS/X and other platforms. I hav not used plain jdb in over a decade, and debugger APIs are standard part of JVMs. This should be reproduceable with any language that generates JVM byte code with debug info. No idea on what the byte code should look like, I think most end users would see that as all black box in compilers.

The bytecode could look like the one of this:

boolean optimize = ...
int i;
if (optimize) { //line 1
  i = 5*5
} else {
  i = compute5x5Dynamically()
}
if (optimize) { //line 2
  i++
} else {
  i = incrementDynamically(i)
}

and so on

if we do that JIT will not optimize the code anymore enough. Before going that route it is better to remove the primitive optimizations

Jochen, are you sure? How does one check that? JIT could be smart enough to see that 'optimize' value doesn't change, merge all optimized and non-optimized branches together in two big branches (just like you do now) and then apply all other optimizations. But that's just speculation, I don't know JIT internals.

What do you mean by removing primitive optimizations? I thought this was a major performance improvement of Groovy 1.8 and one of its killer features.

With Hotspot you can never be sure, but my experiments with primitive optimization in the past showed no good results for such cases. It is maybe also related to the code size and the number of jumps it includes. I won't say JIT cannot optimize that as well at some point. But reaching it requires many many more steps than right now. And since a certain threshold has to be met each time, it is questionable if there is still some practical benefit in the end.

And yes, that is a major performance improvement in 1.8 for quite some cases. Actually what we see is a common bug in those debuggers. Because as we have found here already, it is allowed to have multiple line number attributes for the same line of code. The problem is that Java usually doesn't do that. And because Java does not, nobody thought about implementing that "right". But I don't see a way around this bug without giving up either line numbers or the current structure.

It's hard to justify performance optimizations over functionality. imo, being able to use a debugger on Groovy should be first priority and sacred requirement.

I can't emphasize enough how much of a negative impact this bug has when you set a breakpoint in a large Groovy project, spend time setting up program, run it only to find that it ignored your breakpoint and kept running past because of this issue. Using println and assert to cause a breakpoint as a debugging technique is akin to the stone age. Code coverage tools are broken too.

If bytecode experiments are done, perhaps on 2.x would be more appropriate. If bug is found in 1.8.x maybe it's time to roll back those changes until they can be made in a safer way.

I think there is no need to revert the change fully, just a new option to turn it off in groovyc should be enough. But for the time being...

I assume that the debugger falsely works only on one branch, thus if you don't get into that branch, the debugger will not work. Now the question is which one that is. Jason, do you use it for Grails? I am trying to find out if you use the primopts branch or the other one.

Yes I use Groovy with Grails 2.x and dev build of Grails 2.1. Also standalone gooovy outside Grails with same groovyall jar 1.8.6 that is from Grails.

Jochen, have you experimented with putting different branches into different (synthetic) methods? Not sure this really helps but I've seen javac generating duplicate line numbers in different methods, and the debugger stopped on both of those lines.

@Jason, you have the debugging problem in both usages?

@Peter, generating synthetic methods is something I have been thinking about too. But it is not trivial to do, as we sometimes split the primopts block. Switching from one method to the other is then not possible, splitting into many many methods, will reduce the amount of normal methods you can use very much.

Mainly debugging in IntelliJ + JUnit + plain old groovy code

I'm doing Grails development, and this is driving me nuts. This should be a blocker. I've wasted a lot of time wondering why my breakpoints aren't being hit in IDEA. This problem is doing the platform a great disservice. Please address this!

The more I look into that issue the more I have no idea what is actually wrong. I used javap to look at the line number table and it contains 2 entires for each source line, according to fast and slow path. So this looks correct to me. There is also no label/bytecodeline used twice for one line number.

In Java it can happen that you have multiple bytecode areas for the same source line, that is for example if you have a finally block. Since the JSR isntrcution is not to be used anymore you "inline" that block of code at multiple places, causing the creation of multiple disconnected ares in the source code with the same source line. Another example could be a simple for, that has one part for the declaration and checks, and another for the increment, which can be at the end of the loop block.

So the what is wrong? No idea? The most likely answer currently seems to be that we use something the debugger don't expect and handle wrong. In other words a bug in the debugger. Since we don't know what exactly is causing the problem I have no idea on how to solve the issue

Since I did see a normal usage of debugger in Groovy bytecode just a few days ago I am wondering if that is not specific to a certian program. To check this I would need an example for this issue, as small as possible and best out of Grails. Can someone provide that?

Given that there's also GROOVY-4063, where the bytecode also seems correct, I'd agree. Perhaps it's JVM not treating the generated bytecode correctly, maybe some JIT optimizations gone wrong. You can always look into the OpenJDK source, you know

There are plenty of small examples:
http://youtrack.jetbrains.com/issue/IDEA-84538
http://youtrack.jetbrains.com/issue/IDEA-82741
http://youtrack.jetbrains.com/issue/IDEA-77116
http://youtrack.jetbrains.com/issue/IDEA-77107

This isn't Grails specific. We have plain old Groovy unit tests run in IntelliJ + JUnit launcher, if you try to debug them, set breakpoints, the breakpoints do not get hit.

It comes down to groovyc needs to generate bytecode that can be understood/debugged by current versions of JDK (eg 6+). This should not be a mystery in terms of how to test it. (the example is above in original report).

Same behavior in Groovy-Eclipse.

there is actually one very simple possibility I haven't included yet and that is that the groovy compiler simply emits labels with a wrong line number. Peter mentioned GROOVY-4063, but that is about something not working in 1.6 already. That surely is not related to primtive optimizations at all. And it might be, that it is just the same here.

After looking at the bytecode of the example in GROOVY-4063 I actually found an error. It seems we don't generate a line number information for simple method calls in the fast path.

I fixed the issue I found through GROOVY-4063 and I think it fixes this issue here. But since GROOVY-4063 is reported for pre 1.8 I guess it is a different thing there actually. Please reopen if needed