CodeGenPrepare::placeDbgValues moves llvm.dbg.value without proper analysis

[mveriksson]

Bugzilla Link	31878
Resolution	FIXED
Resolved on	Dec 11, 2019 03:02
Version	trunk
OS	Linux
Blocks	#38102
CC	@cmtice,@echristo,@jmorse,@karka228,@mikaelholmen,@pogo59
Fixed by commit(s)	00e2388

Extended Description

I think CodeGenPrepare::placeDbgValues moves llvm.dbg.value too much
in this example:

Input to CodeGenPrepare. The interesting part is the last call to llvm.dbg.value

*** IR Dump Before CodeGen Prepare ***
; Function Attrs: noinline nounwind
define void @​move(i16 %from.9.par, i16 %to.10.par, i16 %aux.11.par, i16 %n.12.par, [7 x i16]* nocapture %poles.13.par, i16* nocapture %height.14.par) local_unnamed_addr #​1 !dbg !​6 {

tail call void @​llvm.dbg.value(metadata i16 %n.12.par, i64 0, metadata !​15, metadata !​16), !dbg !​17
%_tmp49 = getelementptr i16, i16* %height.14.par, i16 %to.10.par, !dbg !​18
%_tmp55 = mul i16 %to.10.par, 7, !dbg !​18
%_tmp57 = getelementptr [7 x i16], [7 x i16]* %poles.13.par, i16 0, i16 %_tmp55, !dbg !​18
br label %bb0, !dbg !​19

bb0: ; preds = %bb2, %0
%n.12.0 = phi i16 [ %n.12.par, %0 ], [ %_tmp64, %bb2 ]
%aux.11.0 = phi i16 [ %aux.11.par, %0 ], [ %from.9.0, %bb2 ]
%from.9.0 = phi i16 [ %from.9.par, %0 ], [ %aux.11.0, %bb2 ]

tail call void @​llvm.dbg.value(metadata i16 %n.12.0, i64 0, metadata !​15, metadata !​16), !dbg !​17
%_tmp59 = icmp sgt i16 %n.12.0, 1, !dbg !​20
%_tmp64 = add nsw i16 %n.12.0, -1
br i1 %_tmp59, label %bb1, label %bb2, !dbg !​20

bb1: ; preds = %bb0
tail call void @​move(i16 %from.9.0, i16 %aux.11.0, i16 %to.10.par, i16 %_tmp64, [7 x i16]* %poles.13.par, i16* %height.14.par), !dbg !​21
br label %bb2, !dbg !​21

bb2: ; preds = %bb1, %bb0
%_tmp68 = load i16, i16* %_tmp49, align 1, !dbg !​23
%_tmp70 = add i16 %_tmp68, 1, !dbg !​24
store i16 %_tmp70, i16* %_tmp49, align 1, !dbg !​24
%_tmp75 = getelementptr i16, i16* %height.14.par, i16 %from.9.0, !dbg !​24
%_tmp77 = load i16, i16* %_tmp75, align 1, !dbg !​24
%_tmp78 = add i16 %_tmp77, -1, !dbg !​24
store i16 %_tmp78, i16* %_tmp75, align 1, !dbg !​24
%_tmp83 = mul i16 %from.9.0, 7, !dbg !​24
%_tmp85 = getelementptr [7 x i16], [7 x i16]* %poles.13.par, i16 0, i16 %_tmp83, !dbg !​24
%_tmp89 = getelementptr i16, i16* %_tmp85, i16 %_tmp78, !dbg !​24
%_tmp90 = load i16, i16* %_tmp89, align 1, !dbg !​24
%_tmp94 = getelementptr i16, i16* %_tmp57, i16 %_tmp68, !dbg !​24
store i16 %_tmp90, i16* %_tmp94, align 1, !dbg !​24
%_tmp9712 = load i16, i16* %_tmp75, align 1, !dbg !​25
%_tmp99 = getelementptr i16, i16* %_tmp85, i16 %_tmp9712, !dbg !​25
store i16 0, i16* %_tmp99, align 1, !dbg !​25
tail call void @​show([7 x i16]* %poles.13.par, i16* undef), !dbg !​26

;;;;;; Here "n" should get the updated value (n = n - 1).
tail call void @​llvm.dbg.value(metadata i16 %_tmp64, i64 0, metadata !​15, metadata !​16), !dbg !​17
%1 = add i16 %_tmp64, 1, !dbg !​20
%bb0.termcond = icmp sgt i16 %1, 1, !dbg !​20
br i1 %bb0.termcond, label %bb0, label %bb4, !dbg !​27

bb4: ; preds = %bb2
ret void, !dbg !​28
}

!​15 = !DILocalVariable(name: "n", arg: 4, scope: !​6, line: 47, type: !​9)

And here's the output, note how the last llvm.dbg.value has been moved
to %bb0.

*** IR Dump After CodeGen Prepare ***
; Function Attrs: noinline nounwind
define void @​move(i16 %from.9.par, i16 %to.10.par, i16 %aux.11.par, i16 %n.12.par, [7 x i16]* nocapture %poles.13.par, i16* nocapture %height.14.par) local_unnamed_addr #​1 !dbg !​6 {
tail call void @​llvm.dbg.value(metadata i16 %n.12.par, i64 0, metadata !​15, metadata !​16), !dbg !​17
%_tmp49 = getelementptr i16, i16* %height.14.par, i16 %to.10.par, !dbg !​18
%_tmp55 = mul i16 %to.10.par, 7, !dbg !​18
%_tmp57 = getelementptr [7 x i16], [7 x i16]* %poles.13.par, i16 0, i16 %_tmp55, !dbg !​18
br label %bb0, !dbg !​19

bb0: ; preds = %bb2, %0
%n.12.0 = phi i16 [ %n.12.par, %0 ], [ %_tmp64, %bb2 ]
%aux.11.0 = phi i16 [ %aux.11.par, %0 ], [ %from.9.0, %bb2 ]
%from.9.0 = phi i16 [ %from.9.par, %0 ], [ %aux.11.0, %bb2 ]
tail call void @​llvm.dbg.value(metadata i16 %n.12.0, i64 0, metadata !​15, metadata !​16), !dbg !​17
%_tmp59 = icmp sgt i16 %n.12.0, 1, !dbg !​20
%_tmp64 = add nsw i16 %n.12.0, -1

;;;;; Now "n" is updated with its new value already in this block.
tail call void @​llvm.dbg.value(metadata i16 %_tmp64, i64 0, metadata !​15, metadata !​16), !dbg !​17
br i1 %_tmp59, label %bb1, label %bb2, !dbg !​20

bb1: ; preds = %bb0
tail call void @​move(i16 %from.9.0, i16 %aux.11.0, i16 %to.10.par, i16 %_tmp64, [7 x i16]* %poles.13.par, i16* %height.14.par), !dbg !​21
br label %bb2, !dbg !​21

bb2: ; preds = %bb1, %bb0
%_tmp68 = load i16, i16* %_tmp49, align 1, !dbg !​23
%_tmp70 = add i16 %_tmp68, 1, !dbg !​24
store i16 %_tmp70, i16* %_tmp49, align 1, !dbg !​24
%_tmp75 = getelementptr i16, i16* %height.14.par, i16 %from.9.0, !dbg !​24
%_tmp77 = load i16, i16* %_tmp75, align 1, !dbg !​24
%_tmp78 = add i16 %_tmp77, -1, !dbg !​24
store i16 %_tmp78, i16* %_tmp75, align 1, !dbg !​24
%_tmp83 = mul i16 %from.9.0, 7, !dbg !​24
%_tmp85 = getelementptr [7 x i16], [7 x i16]* %poles.13.par, i16 0, i16 %_tmp83, !dbg !​24
%_tmp89 = getelementptr i16, i16* %_tmp85, i16 %_tmp78, !dbg !​24
%_tmp90 = load i16, i16* %_tmp89, align 1, !dbg !​24
%_tmp94 = getelementptr i16, i16* %_tmp57, i16 %_tmp68, !dbg !​24
store i16 %_tmp90, i16* %_tmp94, align 1, !dbg !​24
%_tmp9712 = load i16, i16* %_tmp75, align 1, !dbg !​25
%_tmp99 = getelementptr i16, i16* %_tmp85, i16 %_tmp9712, !dbg !​25
store i16 0, i16* %_tmp99, align 1, !dbg !​25
tail call void @​show([7 x i16]* %poles.13.par, i16* undef), !dbg !​26
%1 = add i16 %_tmp64, 1, !dbg !​20
%bb0.termcond = icmp sgt i16 %1, 1, !dbg !​20
br i1 %bb0.termcond, label %bb0, label %bb4, !dbg !​27

bb4: ; preds = %bb2
ret void, !dbg !​28
}

Running the resulting code in a debugger shows an incorrect value for
the variable n. In this case it would have been better if this call to
llvm.dbg.value had been dropped instead of moved.

I discovered this in a testcase in our out-of-tree target. If you
agree that this looks like a bug I can try to make a reproducer for an
in-tree target.

[mveriksson]

assigned to @jmorse

[pogo59]

If you could verify that your input IR behaves the same for an in-tree
target, and attach a complete IR example, that would be helpful.
Offhand I would guess this is not target-specific but I am not very
familiar with how dbg.value calls are handled.

[mveriksson]

reproducer
llc -O3 -march x86 -o dbgplace.s dbgplace.ll -print-after-all -print-before-all

[mveriksson]

I added example input that shows the issue on x86 when inspecting the -print-after-all log. The final assembler output for x86 looks fine though. Maybe something later in the llc hides the issue?

I don't have a good understanding of the llvm.dbg.value stuff. Maybe the input to CodeGenPrepare is already strange? Is it allowed to have the call to llvm.dbg.value far away from the actual definition? I could not see anything about this in the documentation.

This example has a loop where two values of "n" are live at the same time. Both values are calculated early, but the second value is not valid right where it is calculated. Is this situation allowed?

When I experimented with completely disabling the placeDbgValues() function the compiled code in my out-of-tree back-end gets good debug info. For x86 it did not make a difference (the variable "n" is optimized out in much of the function).

[mveriksson]

I have been thinking a bit more about this problem. Maybe it is
related to "missing" metadata on definition of %_tmp64 in the input to
CodeGenPrepare.

%_tmp64 = add nsw i16 %n.12.0, -1

If this instruction would have had an associated line number, the
debugger would probably point at the correct place when n is
decremented. But as it looks now, the decrement has no line number, so
the debugging experience is confusing.

I tracked the missing metadata back to opt. Below are some snippets
from debugging it in gdb. It looks fine out of GVN, and then the
metadata is gone after SimplifyCFGPass. The transformation in
SimplifyCFG seems good to me; it is merging two "add nsw ... -1", with
different metadata, into a single instruction. Dropping the metadata
seems like the correct thing to do there.

*** IR Dump Before Global Value Numbering ***
...
bb1: ; preds = %bb0
%_tmp64 = add nsw i16 %n.12.0, -1, !dbg !​74 ;;; line 51
tail call void @​move(i16 %from.9.0, i16 %aux.11.0, i16 %to.10.par, i16 %_tmp64, [7 x i16]* %poles.13.par, i16* %height.14.par), !dbg !​74
br label %bb2, !dbg !​74

bb2: ; preds = %bb1, %bb0
...
%_tmp108 = add nsw i16 %n.12.0, -1, !dbg !​80 ;;; line 60
tail call void @​llvm.dbg.value(metadata i16 %_tmp108, i64 0, metadata !​65, metadata !​16), !dbg !​66

!​66 = !DILocation(line: 47, column: 30, scope: !​56)
!​74 = !DILocation(line: 51, column: 9, scope: !​75)
!​80 = !DILocation(line: 60, column: 9, scope: !​81)

*** IR Dump After Global Value Numbering ***
...

bb0.bb2_crit_edge: ; preds = %bb0
%.pre = add nsw i16 %n.12.0, -1, !dbg !​74 ;;; line 60
br label %bb2, !dbg !​73

bb1: ; preds = %bb0
%_tmp64 = add nsw i16 %n.12.0, -1, !dbg !​76 ;;; line 51
tail call void @​move(i16 %from.9.0, i16 %aux.11.0, i16 %to.10.par, i16 %_tmp64, [7 x i16]* %poles.13.par, i16* %height.14.par), !dbg !​76
br label %bb2, !dbg !​76

bb2: ; preds = %bb0.bb2_crit_edge, %bb1
%_tmp108.pre-phi = phi i16 [ %.pre, %bb0.bb2_crit_edge ], [ %_tmp64, %bb1 ], !dbg !​74
...
tail call void @​llvm.dbg.value(metadata i16 %_tmp108.pre-phi, i64 0, metadata !​65, metadata !​16), !dbg !​66

!​66 = !DILocation(line: 47, column: 30, scope: !​56)
!​74 = !DILocation(line: 60, column: 9, scope: !​75)
!​76 = !DILocation(line: 51, column: 9, scope: !​77)

*** IR Dump After Simplify the CFG ***
...
bb0: ; preds = %bb2, %0
%_tmp64 = add nsw i16 %n.12.0, -1
br i1 %_tmp59, label %bb1, label %bb2, !dbg !​73

bb1: ; preds = %bb0
...
br label %bb2, !dbg !​74

bb2: ; preds = %bb0, %bb1
...
tail call void @​llvm.dbg.value(metadata i16 %_tmp64, i64 0, metadata !​65, metadata !​16), !dbg !​66

At this point there is no line number information at all on the "add nsw i16 %n.12.0, -1"!

Maybe PlaceDbgValues does the right thing if the instruction it
moves the dbg.value to has metadata, but if metadata is missing it
would be better to leave the dbg.value, or maybe even remove it?

[mveriksson]

Input to opt
opt -S -lint -O3 -inline-threshold=75 -inlinehint-threshold=10000 -unroll-threshold=0 -o dbg-hanoi.opt.ll dbg-hanoi.ll -print-after-all -print-before-all

[karka228]

Reproducer in gdb (require both foo.c and foo1.c)
Compiling the test program:
clang -g -O3 foo.c foo1.c -o foo

Start gdb:
gdb foo

Reading symbols from foo...done.
(gdb) b foo.c:17
Breakpoint 1 at 0x400571: foo.c:17. (2 locations)
(gdb) run
Starting program: /repo/uabkaka/svn/master/foo
warning: the debug information found in "/lib64/ld-2.19.so" does not match "/lib64/ld-linux-x86-64.so.2" (CRC mismatch).

Breakpoint 1, foo () at foo.c:17
17 usevals(v1, v2); // <--- break here and print v1
(gdb) p v1
$1 = 2
(gdb)

This is false the v1 variable at this point should be 1. The value 1 exist in a register as it is about to be passed to the calls to usevals, but the DEBUG_VALUE of the dead assignment after usevals have erroneously been moved by the CodeGenPrepare pass in llvm (directly before instruction selection).

*** IR Dump After Interleaved Access Pass ***
; Function Attrs: nounwind uwtable
define i32 @​main() local_unnamed_addr #​0 !dbg !​20 {
entry:
%call.i = tail call i32 (...) @​getval() #​3, !dbg !​23
tail call void @​llvm.dbg.value(metadata i32 %call.i, metadata !​11, metadata !DIExpression()) #​3, !dbg !​25
%call1.i = tail call i32 (...) @​getval() #​3, !dbg !​26
tail call void @​llvm.dbg.value(metadata i32 %call1.i, metadata !​13, metadata !DIExpression()) #​3, !dbg !​27
tail call void @​usevals(i32 %call.i, i32 %call1.i) #​3, !dbg !​28
tail call void @​llvm.dbg.value(metadata i32 %call1.i, metadata !​11, metadata !DIExpression()) #​3, !dbg !​25
ret i32 0, !dbg !​29
}
*** IR Dump After CodeGen Prepare ***
; Function Attrs: nounwind uwtable
define i32 @​main() local_unnamed_addr #​0 !dbg !​20 {
entry:
%call.i = tail call i32 (...) @​getval() #​3, !dbg !​23
tail call void @​llvm.dbg.value(metadata i32 %call.i, metadata !​11, metadata !DIExpression()) #​3, !dbg !​25
%call1.i = tail call i32 (...) @​getval() #​3, !dbg !​26
tail call void @​llvm.dbg.value(metadata i32 %call1.i, metadata !​11, metadata !DIExpression()) #​3, !dbg !​25
tail call void @​llvm.dbg.value(metadata i32 %call1.i, metadata !​13, metadata !DIExpression()) #​3, !dbg !​27
tail call void @​usevals(i32 %call.i, i32 %call1.i) #​3, !dbg !​28
ret i32 0, !dbg !​29
}

[karka228]

foo1.c required by the reproducer above (19201)

[jmorse]

I've just stumbled upon this ticket -- it seems I wound up rediscovering this problem in bug 38754, reaching much the same conclusions, that placeDbgValues is damaging debug experience through careless reordering.

I've stuck 38754 in the blocks field to indicate these are related. I'm currently corralling patches to fix this, hopefully with as little regression as possible.

[jmorse]

placeDbgValues was significantly limited in 00e2388, and it looks like the patch is sticking. There's still some work to be done with debug use-before-defs (which are already an error-state), but the vast majority of faulty behaviour should now be fixed.

[jmorse]

mentioned in issue #38102