Debug Info: gdb breakpoint not properly set in partially unrolled loop

[zakkak]

Describe the issue

Compiling a loop with debug info enabled and setting a breakpoint inside the loop doesn't set the breakpoint properly if the loop gets unrolled.

For instance compiling the following Java program:

public class Main {
    public static void main(String[] args) {
        for (int i = 1; i < 100000; i++) {
            System.out.println("Hello World i=" + i);
        }
    }
}

and setting the breakpoint at line 4 results in gdb breaking the execution only for the first print, the rest of the program continues uninterrupted.

Inspecting the generated code we observe that the first iteration is moved out of the loop while the rest iterations are executed in a loop. When setting the breakpoint, however, gdb sets it only in the first iteration (i.e. not inside the actual loop):

(gdb) info b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x000000000040600e in Main::main(java.lang.String[] *) at Main.java:4

As a result after continuing execution the breakpoint is never hit again.

Steps to reproduce the issue

cat > Main.java <<EOF
public class Main {
    public static void main(String[] args) {
        for (int i = 1; i < 100000; i++) {
            System.out.println("Hello World i=" + i);
        }
    }
}
EOF
javac Main.java
native-image -g Main
gdb main -ex "b Main.java:4" -ex "run" -ex "continue"

The application reaches completion while it should stop in the second print.

Describe GraalVM and your environment:

• GraalVM version: CE 22.0.0.2
• JDK major version: 17
• OS: Fedora 35
• Architecture: AMD64

More details
The corresponding disassembly looks like this:

   // Unrolled 1st iteration
   0x406000 <Main::main(java.lang.String[] *)>:	sub    $0x38,%rsp
   0x406004 <Main::main(java.lang.String[] *)+4>:	cmp    0x8(%r15),%rsp
   0x406008 <Main::main(java.lang.String[] *)+8>:	jbe    0x40625a <Main::main(java.lang.String[] *)+602>
=> 0x40600e <Main::main(java.lang.String[] *)+14>:	mov    $0xe,%rdi
   0x406015 <Main::main(java.lang.String[] *)+21>:	mov    $0x1,%esi
   0x40601a <Main::main(java.lang.String[] *)+26>:	call   0x5327b0 <java.lang.StringConcatHelper::mix(long, int)>
   0x40601f <Main::main(java.lang.String[] *)+31>:	nop
   0x406020 <Main::main(java.lang.String[] *)+32>:	mov    %eax,%edi
   0x406022 <Main::main(java.lang.String[] *)+34>:	mov    %rax,%rcx
   0x406025 <Main::main(java.lang.String[] *)+37>:	sar    $0x20,%rcx
   0x406029 <Main::main(java.lang.String[] *)+41>:	mov    %ecx,%ecx
   0x40602b <Main::main(java.lang.String[] *)+43>:	movsbl %cl,%ecx
   0x40602e <Main::main(java.lang.String[] *)+46>:	mov    %edi,%edx
   0x406030 <Main::main(java.lang.String[] *)+48>:	shl    %cl,%edx
   0x406032 <Main::main(java.lang.String[] *)+50>:	test   %edx,%edx
   0x406034 <Main::main(java.lang.String[] *)+52>:	jl     0x406260 <Main::main(java.lang.String[] *)+608>
   0x40603a <Main::main(java.lang.String[] *)+58>:	movabs $0x3640a0,%rbx
   0x406044 <Main::main(java.lang.String[] *)+68>:	lea    (%r14,%rbx,1),%rbx
   0x406048 <Main::main(java.lang.String[] *)+72>:	mov    %rbx,0x20(%rsp)
   0x40604d <Main::main(java.lang.String[] *)+77>:	mov    %rbx,%rdi
   0x406050 <Main::main(java.lang.String[] *)+80>:	mov    0x28(%r15),%rsi
   0x406054 <Main::main(java.lang.String[] *)+84>:	mov    0x20(%r15),%rcx
   0x406058 <Main::main(java.lang.String[] *)+88>:	sub    %r14,%rdi
   0x40605b <Main::main(java.lang.String[] *)+91>:	mov    %edx,%ebp
   0x40605d <Main::main(java.lang.String[] *)+93>:	lea    0x17(%rbp),%rbp
   0x406061 <Main::main(java.lang.String[] *)+97>:	and    $0xfffffffffffffff8,%rbp
   0x406065 <Main::main(java.lang.String[] *)+101>:	cmp    $0x20000,%rbp
   0x40606c <Main::main(java.lang.String[] *)+108>:	jae    0x406233 <Main::main(java.lang.String[] *)+563>
   0x406072 <Main::main(java.lang.String[] *)+114>:	mov    %rsi,%r8
   0x406075 <Main::main(java.lang.String[] *)+117>:	add    %rbp,%r8
   0x406078 <Main::main(java.lang.String[] *)+120>:	cmp    %rcx,%r8
   0x40607b <Main::main(java.lang.String[] *)+123>:	ja     0x406233 <Main::main(java.lang.String[] *)+563>
   0x406081 <Main::main(java.lang.String[] *)+129>:	mov    %r8,0x28(%r15)
   0x406085 <Main::main(java.lang.String[] *)+133>:	prefetchnta 0xc0(%rsi,%rbp,1)
   0x40608d <Main::main(java.lang.String[] *)+141>:	prefetchnta 0x100(%rsi,%rbp,1)
   0x406095 <Main::main(java.lang.String[] *)+149>:	prefetchnta 0x140(%rsi,%rbp,1)
   0x40609d <Main::main(java.lang.String[] *)+157>:	prefetchnta 0x180(%rsi,%rbp,1)
   0x4060a5 <Main::main(java.lang.String[] *)+165>:	mov    %edx,0xc(%rsi)
   0x4060a8 <Main::main(java.lang.String[] *)+168>:	mov    %rdi,(%rsi)
   0x4060ab <Main::main(java.lang.String[] *)+171>:	movl   $0x0,0x8(%rsi)
   0x4060b2 <Main::main(java.lang.String[] *)+178>:	movabs $0x4db5d8,%rbp
   0x4060bc <Main::main(java.lang.String[] *)+188>:	lea    (%r14,%rbp,1),%rbp
   0x4060c0 <Main::main(java.lang.String[] *)+192>:	mov    %rbp,0x18(%rsp)
   0x4060c5 <Main::main(java.lang.String[] *)+197>:	movabs $0x25b678,%r8
   0x4060cf <Main::main(java.lang.String[] *)+207>:	lea    (%r14,%r8,1),%r8
   0x4060d3 <Main::main(java.lang.String[] *)+211>:	mov    %r8,0x10(%rsp)
   0x4060d8 <Main::main(java.lang.String[] *)+216>:	mov    %rax,%rdi
   0x4060db <Main::main(java.lang.String[] *)+219>:	mov    %rsi,%rax
   0x4060de <Main::main(java.lang.String[] *)+222>:	mov    $0x1,%edx
   0x4060e3 <Main::main(java.lang.String[] *)+227>:	mov    %r8,%rcx
   0x4060e6 <Main::main(java.lang.String[] *)+230>:	mov    %rax,0x8(%rsp)
   0x4060eb <Main::main(java.lang.String[] *)+235>:	call   0x532ef0 <java.lang.StringConcatHelper::prepend(long, byte [] *, int, java.lang.String *)>
   0x4060f0 <Main::main(java.lang.String[] *)+240>:	nop
   0x4060f1 <Main::main(java.lang.String[] *)+241>:	mov    0x8(%rsp),%rdi
   0x4060f6 <Main::main(java.lang.String[] *)+246>:	mov    %rax,%rsi
   0x4060f9 <Main::main(java.lang.String[] *)+249>:	call   0x532880 <java.lang.StringConcatHelper::newString(byte [] *, long)>
   0x4060fe <Main::main(java.lang.String[] *)+254>:	nop
   0x4060ff <Main::main(java.lang.String[] *)+255>:	mov    0x18(%rsp),%rdi
   0x406104 <Main::main(java.lang.String[] *)+260>:	mov    %rax,%rsi
   0x406107 <Main::main(java.lang.String[] *)+263>:	call   0x4f7bd0 <java.io.PrintStream::writeln(java.lang.String *)>
   0x40610c <Main::main(java.lang.String[] *)+268>:	nop
   0x40610d <Main::main(java.lang.String[] *)+269>:	mov    $0x2,%eax
   0x406112 <Main::main(java.lang.String[] *)+274>:	jmp    0x4061f3 <Main::main(java.lang.String[] *)+499>
   0x406117 <Main::main(java.lang.String[] *)+279>:	nopw   0x0(%rax,%rax,1)

   // Loop start
   0x406120 <Main::main(java.lang.String[] *)+288>:	mov    $0xe,%rdi
   0x406127 <Main::main(java.lang.String[] *)+295>:	mov    %eax,%esi
   0x406129 <Main::main(java.lang.String[] *)+297>:	mov    %eax,0x2c(%rsp)
   0x40612d <Main::main(java.lang.String[] *)+301>:	call   0x5327b0 <java.lang.StringConcatHelper::mix(long, int)>
   0x406132 <Main::main(java.lang.String[] *)+306>:	nop
   0x406133 <Main::main(java.lang.String[] *)+307>:	mov    %eax,%edi
   0x406135 <Main::main(java.lang.String[] *)+309>:	mov    %rax,%rcx
   0x406138 <Main::main(java.lang.String[] *)+312>:	sar    $0x20,%rcx
   0x40613c <Main::main(java.lang.String[] *)+316>:	mov    %ecx,%ecx
   0x40613e <Main::main(java.lang.String[] *)+318>:	movsbl %cl,%ecx
   0x406141 <Main::main(java.lang.String[] *)+321>:	mov    %edi,%edx
   0x406143 <Main::main(java.lang.String[] *)+323>:	shl    %cl,%edx
   0x406145 <Main::main(java.lang.String[] *)+325>:	test   %edx,%edx
   0x406147 <Main::main(java.lang.String[] *)+327>:	jl     0x406274 <Main::main(java.lang.String[] *)+628>
   0x40614d <Main::main(java.lang.String[] *)+333>:	mov    0x20(%rsp),%rbx
   0x406152 <Main::main(java.lang.String[] *)+338>:	mov    0x28(%r15),%rdi
   0x406156 <Main::main(java.lang.String[] *)+342>:	mov    0x20(%r15),%rsi
   0x40615a <Main::main(java.lang.String[] *)+346>:	sub    %r14,%rbx
   0x40615d <Main::main(java.lang.String[] *)+349>:	mov    %edx,%ecx
   0x40615f <Main::main(java.lang.String[] *)+351>:	lea    0x17(%rcx),%rcx
   0x406163 <Main::main(java.lang.String[] *)+355>:	and    $0xfffffffffffffff8,%rcx
   0x406167 <Main::main(java.lang.String[] *)+359>:	cmp    $0x20000,%rcx
   0x40616e <Main::main(java.lang.String[] *)+366>:	jae    0x406204 <Main::main(java.lang.String[] *)+516>
   0x406174 <Main::main(java.lang.String[] *)+372>:	mov    %rdi,%rbp
   0x406177 <Main::main(java.lang.String[] *)+375>:	add    %rcx,%rbp
   0x40617a <Main::main(java.lang.String[] *)+378>:	cmp    %rsi,%rbp
   0x40617d <Main::main(java.lang.String[] *)+381>:	ja     0x406204 <Main::main(java.lang.String[] *)+516>
   0x406183 <Main::main(java.lang.String[] *)+387>:	mov    %rbp,0x28(%r15)
   0x406187 <Main::main(java.lang.String[] *)+391>:	prefetchnta 0xc0(%rdi,%rcx,1)
   0x40618f <Main::main(java.lang.String[] *)+399>:	prefetchnta 0x100(%rdi,%rcx,1)
   0x406197 <Main::main(java.lang.String[] *)+407>:	prefetchnta 0x140(%rdi,%rcx,1)
   0x40619f <Main::main(java.lang.String[] *)+415>:	prefetchnta 0x180(%rdi,%rcx,1)
   0x4061a7 <Main::main(java.lang.String[] *)+423>:	mov    %edx,0xc(%rdi)
   0x4061aa <Main::main(java.lang.String[] *)+426>:	mov    %rbx,(%rdi)
   0x4061ad <Main::main(java.lang.String[] *)+429>:	movl   $0x0,0x8(%rdi)
   0x4061b4 <Main::main(java.lang.String[] *)+436>:	mov    %rdi,%rbx
   0x4061b7 <Main::main(java.lang.String[] *)+439>:	mov    %rax,%rdi
   0x4061ba <Main::main(java.lang.String[] *)+442>:	mov    %rbx,%rsi
   0x4061bd <Main::main(java.lang.String[] *)+445>:	mov    0x2c(%rsp),%edx
   0x4061c1 <Main::main(java.lang.String[] *)+449>:	mov    0x10(%rsp),%rcx
   0x4061c6 <Main::main(java.lang.String[] *)+454>:	mov    %rbx,0x8(%rsp)
   0x4061cb <Main::main(java.lang.String[] *)+459>:	call   0x532ef0 <java.lang.StringConcatHelper::prepend(long, byte [] *, int, java.lang.String *)>
   0x4061d0 <Main::main(java.lang.String[] *)+464>:	nop
   0x4061d1 <Main::main(java.lang.String[] *)+465>:	mov    0x8(%rsp),%rdi
   0x4061d6 <Main::main(java.lang.String[] *)+470>:	mov    %rax,%rsi
   0x4061d9 <Main::main(java.lang.String[] *)+473>:	call   0x532880 <java.lang.StringConcatHelper::newString(byte [] *, long)>
   0x4061de <Main::main(java.lang.String[] *)+478>:	nop
   0x4061df <Main::main(java.lang.String[] *)+479>:	mov    0x18(%rsp),%rdi
   0x4061e4 <Main::main(java.lang.String[] *)+484>:	mov    %rax,%rsi
   0x4061e7 <Main::main(java.lang.String[] *)+487>:	call   0x4f7bd0 <java.io.PrintStream::writeln(java.lang.String *)>
   0x4061ec <Main::main(java.lang.String[] *)+492>:	nop
   0x4061ed <Main::main(java.lang.String[] *)+493>:	mov    0x2c(%rsp),%eax
   0x4061f1 <Main::main(java.lang.String[] *)+497>:	inc    %eax
   0x4061f3 <Main::main(java.lang.String[] *)+499>:	cmp    $0x186a0,%eax
   0x4061f9 <Main::main(java.lang.String[] *)+505>:	jge    0x406223 <Main::main(java.lang.String[] *)+547>
   0x4061ff <Main::main(java.lang.String[] *)+511>:	jmp    0x406120 <Main::main(java.lang.String[] *)+288>
   // Back Branch

[zakkak]

Passing -H:-OmitInlinedMethodDebugLineInfo works around this issue. So it appears that the "rolled" parts of the loop show up as parts of an inlined method.

Indeed inspecting the backtrace reported by gdb when the first breakpoint is hit and when the second (and the rest) are hit gives:

Thread 1 "main.inline" hit Breakpoint 1, Main::main(java.lang.String[] *) () at Main.java:4
4	            System.out.println("Hello World i=" + i);
(gdb) bt
#0  Main::main(java.lang.String[] *) () at Main.java:4
#1  0x0000000000411192 in com.oracle.svm.core.JavaMainWrapper::runCore () at com/oracle/svm/core/JavaMainWrapper.java:149
#2  com.oracle.svm.core.JavaMainWrapper::run(int, org.graalvm.nativeimage.c.type.CCharPointerPointer *) () at com/oracle/svm/core/JavaMainWrapper.java:185
#3  0x000000000043615d in com.oracle.svm.core.code.IsolateEnterStub::JavaMainWrapper_run_5087f5482cc9a6abc971913ece43acb471d2631b(int, org.graalvm.nativeimage.c.type.CCharPointerPointer *) () at com/oracle/svm/core/JavaMainWrapper.java:279
(gdb) c
Continuing.

Thread 1 "main.inline" hit Breakpoint 1, jdk.internal.misc.Unsafe::allocateUninitializedArray () at Main.java:4
4	            System.out.println("Hello World i=" + i);
(gdb) bt
#0  jdk.internal.misc.Unsafe::allocateUninitializedArray () at Main.java:4
#1  Main::main(java.lang.String[] *) () at Main.java:4
#2  0x0000000000411192 in com.oracle.svm.core.JavaMainWrapper::runCore () at com/oracle/svm/core/JavaMainWrapper.java:149
#3  com.oracle.svm.core.JavaMainWrapper::run(int, org.graalvm.nativeimage.c.type.CCharPointerPointer *) () at com/oracle/svm/core/JavaMainWrapper.java:185
#4  0x000000000043615d in com.oracle.svm.core.code.IsolateEnterStub::JavaMainWrapper_run_5087f5482cc9a6abc971913ece43acb471d2631b(int, org.graalvm.nativeimage.c.type.CCharPointerPointer *) () at com/oracle/svm/core/JavaMainWrapper.java:279
(gdb)

which shows that the breakpoint was set in the inlined code of jdk.internal.misc.Unsafe::allocateUninitializedArray() which is invoked by StringConcatHelper which is invoked due to the string concatenation we are performing before printing.

Removing the concatenation makes things even more weird from the user's perspective. Running without -H:-OmitInlinedMethodDebugLineInfo doesn't even allow the user to set a breakpoint at Main.java:4 because main gets inlined as well. Adding -H:-OmitInlinedMethodDebugLineInfo allows the user to set the breakpoint and works as expected.

Given that when using -H:+OmitInlinedMethodDebugLineInfo it is expected to be missing a significant part of debug info I am not sure whether this is worth "fixing" or not. @olpaw @adinn WDYT?

[adinn]

@zakkak I believe this can be fixed.

At present flag the debug info generator responds to flag -H:+OmitInlinedMethodDebugLineInfo by omitting to generate any line information for 'leaf' code ranges that are associated with inlined code. This is done in the map filter method applied to the stream of SourcePosition values derived from the compilation result

Unfortunately, this simply means that those ranges are no longer associated with any file and line. When the loop body contains a call or something else like an allocation that gets translated to inline code then a line break point in the loop body may not hit anything. Depending on how the loop gets peeled, it may hit an initial one or more breaks but miss other breaks.

What the generator ought to do is emit information for the inline range but remap it's file and line to the point in the top level method where the call it sits under was inlined and remap its method to the top level method. There is no need to worry about generating multiple inline ranges with the same file and line as they get merged by the consumer of the line info stream.

This problem has been avoided in the new version of the generator I am working on in my local vars branch. That version drives generation off a tree that includes a single top level caller node for the full range of the underlying inline tree. When inline info is omitted a location (line info) record is generated for the top level caller node only.

So, while it is possible to fix this it is not really necessary so long as we get the local vars patch in in time for the next release.

[zakkak]

Further investigating this I found another issue that persists even when using -H:-OmitInlinedMethodDebugLineInfo (and is reproducible using 22.2-dev with the provided Java program in this issue).

It appears that gdb when provided with line info mapping multiple addresses to a line drops some of them to avoid breaking multiple times (in the same iteration) on the same line. In GraalVM's case this however ends up placing a breakpoint only in the unrolled iteration of the loop, thus not breaking in every iteration as expected.

For optimized code, the compiler can scatter one source line
across disjoint ranges of PC values, even when no duplicate
functions or inline functions are involved. For example,
'for (;;)' inside a non-template, non-inline, and non-ctor-or-dtor
function can result in two PC ranges. In this case, we don't
want to set a breakpoint on the first PC of each range. To filter
such cases, we use containing blocks -- for each PC found
above, we see if there are other PCs that are in the same
block. If yes, the other PCs are filtered out.

Source: https://github.com/bminor/binutils-gdb/blob/5f437feef427049cf6f29defae42d82207e26191/gdb/linespec.c#L2095-L2103

22.0.0.2

In 22.0.0.2 we get away with this because we inline code and the inlined code comes in different DIEs than the main DIE, so gdb still sets a breakpoint on the first matching address in the main DIE but also to other two addresses in inlined DIEs.

 (gdb) b Main.java:4
Breakpoint 1 at 0x40600e: Main.java:4. (3 locations)
(gdb) info b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   <MULTIPLE>         
1.1                         y   0x000000000040600e in Main::main(java.lang.String[] *) at Main.java:4
1.2                         y   0x000000000040601e in jdk.internal.misc.Unsafe::allocateUninitializedArray at Main.java:4
1.3                         y   0x0000000000406131 in jdk.internal.misc.Unsafe::allocateUninitializedArray at Main.java:4

So we get a breakpoint in 0x40600e, 0x40601e, and 0x406131, inspecting the debuginfo with objdump --dwarf=info main we see that these addresses correspond to the following 3 DIEs:

...
 <1><29e77d>: Abbrev Number: 12 (DW_TAG_subprogram)
    <29e77e>   DW_AT_low_pc      : 0x406000
    <29e786>   DW_AT_high_pc     : 0x40628c
    <29e78e>   DW_AT_external    : 1
    <29e78f>   DW_AT_specification: <0x29e73d>  // main
...
 <2><29e798>: Abbrev Number: 31 (DW_TAG_inlined_subroutine)
    <29e799>   DW_AT_abstract_origin: <0x4357b2>  // allocateUninitializedArray
    <29e79d>   DW_AT_low_pc      : 0x40601e
    <29e7a5>   DW_AT_high_pc     : 0x406034
    <29e7ad>   DW_AT_call_file   : 0x1
    <29e7b1>   DW_AT_call_line   : 0x4
...
 <2><29eb82>: Abbrev Number: 31 (DW_TAG_inlined_subroutine)
    <29eb83>   DW_AT_abstract_origin: <0x4357b2>  // allocateUninitializedArray
    <29eb87>   DW_AT_low_pc      : 0x406131
    <29eb8f>   DW_AT_high_pc     : 0x406139
    <29eb97>   DW_AT_call_file   : 0x1
    <29eb9b>   DW_AT_call_line   : 0x4

Inspecting the decoded line info with objdump --dwarf=decodedline main | grep "Main.java .* 4 " we see however that there are more than 3 mappings from Main.java:4 to addresses:

Main.java                                      4            0x40600e               x
Main.java                                      4            0x40601e               x
Main.java                                      4            0x4060c9       1       x
Main.java                                      4            0x4060dc               x
Main.java                                      4            0x406120               x
Main.java                                      4            0x40612b               x
Main.java                                      4            0x406131               x
Main.java                                      4            0x4061b7       1       x

22.2-dev6e56ec841912c7497bb523f086de8c3be0c03221

After 22.0.0.2 (this is reproducible in 22.1-dev as well), we see a similar amount of mappings from Main.java:4 to addresses:

Main.java                                      4            0x40600e               x
Main.java                                      4            0x4060c5               x
Main.java                                      4            0x4060d8               x
Main.java                                      4            0x4060de               x
Main.java                                      4            0x4060eb               x
Main.java                                      4            0x406120               x
Main.java                                      4            0x40612d               x
Main.java                                      4            0x4061b7       1       x
Main.java                                      4            0x4061cb               x

But, setting a breakpoint to line 4 of Main.java results in a single breakpoint on a single PC:

(gdb) b Main.java:4
Breakpoint 1 at 0x40600e: file Main.java, line 4.
(gdb) info b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x000000000040600e in Main::main(java.lang.String[] *) at Main.java:4

Inspecting the DIEs of the generated binary and looking for ranges containing the above addresses we see that they all fall in the main DIE:

 <1><40b345>: Abbrev Number: 12 (DW_TAG_subprogram)
    <40b346>   DW_AT_low_pc      : 0x406000
    <40b34e>   DW_AT_high_pc     : 0x40628c
    <40b356>   DW_AT_external    : 1
    <40b357>   DW_AT_specification: <0x40b305>

which explains why gdb only sets a breakpoint to the first of them.

So this leaves us with the following open questions:

1. How can we differentiate unrolled peeled addresses from the rest of the addresses matching the same line so that we can set a breakpoint to them? My understanding is that we would need to create different DIEs for the unrolled parts of the loop and the rolled one. Having a quick look through the DWARF spec didn't help me find a way to achieve this. I will keep looking and possibly check what gcc does in such cases.
2. Do we really want gdb to set a breakpoint for the first address of each inlined method in a loop? This might lead in gdb breaking multiple times in the same iteration (because we have multiple inlined methods in that place). Think something like foo(bar(baz()))) appearing in line Main.java:4 and all three methods getting inlined, should gdb place three breakpoints, one for each of them, and break 3 times in each iteration?
3. Does the way that GraalVM unrolls peels these loops make sense?