variable information lost from debug info after combine redundant instructions

[gregbedwell]

Bugzilla Link	37741
Version	trunk
OS	Windows NT
Blocks	llvm/llvm-project#37301
Attachments	output from clang
CC	@dwblaikie,@flametop,@jmorse,@pogo59,@tbosch,@vedantk

Extended Description

I didn't spot this already reported, but as there's been a bit of churn in this area recently, it's possible I missed it.

Versions:

$ clang -v
clang version 7.0.0 (trunk 334224) (llvm/trunk 334232)
Target: x86_64-pc-windows-msvc
Thread model: posix
InstalledDir: e:\build-yy\Release\bin

$ lldb -v
lldb version 7.0.0 (https://git.llvm.org/git/lldb.git/ revision e719823776f7d6c645598845be4ea28c5ddfdd70)
  clang revision 334224
  llvm revision 334232

source level reproducible

$ cat tests\simple_loop_iterator\test.cpp
  struct iterator {

    int index_;
    iterator(int index) : index_(index) {}

    bool operator!=(iterator const &rhs) const { return index_ != rhs.index_; }

    int operator*() { return index_; }

    int operator++() {
      int ret = index_;
      ++index_;
      return ret;
    }
  };

struct item {
  iterator begin() { return iterator(0); }
  iterator end() { return iterator(5); }
};

int main(int argc, char**) {
  item list;
  int total = 0;
  for (volatile auto elem : list)
    total += elem * argc;  // DexWatch('total', 'elem', 'argc')
  return total;
}

// DexExpectWatchValue('elem', '0', '1', '2', '3', '4', on_line=26)
// DexExpectWatchValue('total', '0', '1', '3', '6', on_line=26)
// DexExpectWatchValue('argc', '1', on_line=26)

// DexExpectStepKind('FUNC_EXTERNAL', 0)
// DexExpectStepKind('FUNC_UNKNOWN', 0)
// DexExpectStepKind('UNKNOWN', 0)

DExTer observes that pass 237 affects the debugability:

pass 236/316 = 0/52 (0.0000, 0.0000) [Bit-Tracking Dead Code Elimination on function (main)]
pass 237/316 = 18/52 (0.3462, 0.3462) [Combine redundant instructions on function (main)]
pass 238/316 = 18/52 (0.3462, 0.0000) [Jump Threading on function (main)]​

which comes from the result of evaluating the expression 'total' in the debugger on line 26 always showing a value of 0.

  test.cpp:26 [total] [18/21]
    expected encountered values:
      0

    missing values:
      1 [+6]
      3 [+6]
      6 [+6]

We can observe that debugify-each also sees errors from combine redundant instructions in this case:

$ clang -O2 -mllvm -opt-bisect-limit=236 -emit-llvm tests\simple_loop_iterator\test.cpp -S -o - 2>nul | opt -debugify-each -disable-output -instcombine
WARNING: Missing line 6
WARNING: Missing line 11
WARNING: Missing line 17
WARNING: Missing line 23
WARNING: Missing line 29
ERROR: Missing variable 4
ERROR: Missing variable 6
ERROR: Missing variable 7
ERROR: Missing variable 9
ERROR: Missing variable 10
ERROR: Missing variable 12
ERROR: Missing variable 13
ERROR: Missing variable 15
CheckFunctionDebugify [Combine redundant instructions]: FAIL
CheckFunctionDebugify [Module Verifier]: PASS

I've attached the output from clang in the above command line. My hope is that by fixing the errors reported from debugify we'll be able to verify that the DExTer score improves at the same time.

[gregbedwell]

mentioned in issue llvm/llvm-project#37301

[tbosch]

Here is a simplified example:

int main(int argc, char*) { int total = 0; volatile int elem = 1; total += elem argc; total += elem * argc; return total; }

Compiled with gcc -O3 -g allows to step through all lines a print "total". Compiled with clang -O3 -g leads to an error at the second "total += ...":

(lldb) s Process 2257255 stopped

• thread #​1, name = 'a.out', stop reason = step in frame #​0: 0x000000000040111c a.out`main(argc=1, (null)=0x00007fffffffdc78) at test2.cc:5:9 2 int total = 0; 3 volatile int elem = 1; 4 total += elem argc; -> 5 total += elem argc; 6 return total; 7 } (lldb) print total error: Couldn't materialize: couldn't get the value of variable total: variable not available error: errored out in DoExecute, couldn't PrepareToExecuteJITExpression

All of the following seem to be required:

• argc has to be a function parameter
• elem has to be volatile to prevent constant folding. Making total volatile does not reproduce the bug
• we need at least 2 steps of "total += ..."

Debug info for gcc:

0x00000029: DW_TAG_subprogram DW_AT_name ("main") DW_AT_low_pc (0x0000000000001040) DW_AT_high_pc (0x0000000000001056) DW_AT_frame_base (DW_OP_call_frame_cfa) DW_AT_GNU_all_call_sites (true) DW_AT_sibling (0x00000084)

0x0000004b: DW_TAG_formal_parameter DW_AT_name ("argc") DW_AT_location (DW_OP_reg5 RDI)

0x00000059: DW_TAG_formal_parameter DW_AT_location (DW_OP_reg4 RSI)

0x00000060: DW_TAG_variable DW_AT_name ("total") DW_AT_location (0x00000006: [0x0000000000001040, 0x000000000000104c): DW_OP_lit0, DW_OP_stack_value [0x000000000000104c, 0x0000000000001050): DW_OP_breg0 RAX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_stack_value [0x0000000000001050, 0x0000000000001052): DW_OP_breg0 RAX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_breg1 RDX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_plus, DW_OP_stack_value) DW_AT_unknown_2137 (0x00000000)

0x00000074: DW_TAG_variable DW_AT_name ("elem") DW_AT_location (DW_OP_fbreg -12)

Debug info for clang:

0x0000002a: DW_TAG_subprogram DW_AT_name ("main")

0x00000043: DW_TAG_formal_parameter DW_AT_location (DW_OP_reg5 RDI) DW_AT_name ("argc")

0x00000050: DW_TAG_formal_parameter DW_AT_location (DW_OP_reg4 RSI)

0x00000059: DW_TAG_variable DW_AT_location (DW_OP_fbreg -4) DW_AT_name ("elem")

0x00000067: DW_TAG_variable DW_AT_location (0x00000000: [0x0000000000401110, 0x000000000040111c): DW_OP_consts +0, DW_OP_stack_value [0x0000000000401123, 0x0000000000401124): DW_OP_reg0 RAX) DW_AT_name ("total")

The problem seems to be the differences in the DW_AT_location tag of "total".

[tbosch]

The problem also manifests at -O3. Using that as otherwise the assembly is too different (gcc does not fully inline the iterator at -O2).

Clang's assembly with -O3 (https://godbolt.org/z/asvq5a)

main: # @​main mov dword ptr [rsp - 4], 0 mov eax, dword ptr [rsp - 4] mov dword ptr [rsp - 4], 1 add eax, dword ptr [rsp - 4] mov dword ptr [rsp - 4], 2 add eax, dword ptr [rsp - 4] mov dword ptr [rsp - 4], 3 add eax, dword ptr [rsp - 4] mov dword ptr [rsp - 4], 4 add eax, dword ptr [rsp - 4] imul eax, edi ret

Gcc's assembly with -O3 (https://godbolt.org/z/fde7x1) is a bit longer main: mov dwort ptr [rsp-4], 0 mov eax, dwort ptr [rsp-4] mov dwort ptr [rsp-4], 1 mov edx, dwort ptr [rsp-4] mov dwort ptr [rsp-4], 2 add eax, edx mov edx, dwort ptr [rsp-4] mov dwort ptr [rsp-4], 3 add eax, edx mov edx, dwort ptr [rsp-4] mov dwort ptr [rsp-4], 4 add eax, edx mov edx, dwort ptr [rsp-4] add eax, edx imul eax, edi ret

Clang's debug info for "total":

0x000000b6: DW_TAG_variable DW_AT_location (indexed (0x1) loclist = 0x00000037: [0x000000000040114f, 0x0000000000401150): DW_OP_reg0 RAX) DW_AT_name ("total")

Gcc's debug info for "total":

0x00000186: DW_TAG_variable DW_AT_name ("total") DW_AT_location (0x00000008: [0x0000000000001040, 0x000000000000104c): DW_OP_lit0, DW_OP_stack_value [0x000000000000104c, 0x0000000000001062): DW_OP_breg5 RDI+0, DW_OP_breg0 RAX+0, DW_OP_mul, DW_OP_stack_value [0x0000000000001062, 0x0000000000001082): DW_OP_breg0 RAX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_stack_value [0x0000000000001082, 0x0000000000001084): DW_OP_breg1 RDX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_breg0 RAX+0, DW_OP_breg5 RDI+0, DW_OP_mul, DW_OP_plus, DW_OP_stack_value) DW_AT_unknown_2137 (0x00000000)

Interestingly, removing "argc" from the example (assuming the value is 1) allows clang to print the variable "total" again.

[tbosch]

On current head:

Compiling the example with clang (-O2 -gdwarf-5) does not allow to print "total" during debugging:

(lldb) s Process 2229729 stopped

• thread #​1, name = 'a.out', stop reason = step in frame #​0: 0x0000000000401118 a.out`main() at test2.cc:26:14 23 item list; 24 int total = 0; 25 for (volatile auto elem : list) -> 26 total += elem * argc; // DexWatch('total', 'elem', 'argc') 27 return total; 28 } (lldb) print total error: Couldn't materialize: couldn't get the value of variable total: variable not available error: errored out in DoExecute, couldn't PrepareToExecuteJITExpression

Compiling with gcc (and debugging with lldb) produces better debug information that allows to print "total":

(lldb) s Process 2230300 stopped

• thread #​1, name = 'a.out', stop reason = step in frame #​0: 0x0000555555555049 a.out`main() at test2.cc:26:14 23 item list; 24 int total = 0; 25 for (volatile auto elem : list) -> 26 total += elem * argc; // DexWatch('total', 'elem', 'argc') 27 return total; 28 } (lldb) print total (int) $0 = 0

So gcc seems to do something better here.

[gregbedwell]

post-instcombine dexter trace

[gregbedwell]

pre-instcombine dexter trace

[gregbedwell]

post-instcombine ll file

[gregbedwell]

pre-instcombine ll file

[gregbedwell]

My hope is that by fixing the errors reported from debugify we'll be able to verify that the DExTer score improves at the same time.

I looked at this again with r336339 and found that while I can no longer reproduce the debugify error, unfortunately the actual debug experience is sadly not improved. I should note though, that debugify is still producing a number of "Missing variable" warnings which I suspect are showing the issue.

$ cat tests\simple_loop_iterator\test.cpp
struct iterator {
  int index_;
  iterator(int index) : index_(index) {}
  bool operator!=(iterator const &rhs) const { return index_ != rhs.index_; }
  int operator*() { return index_; }
  int operator++() { return index_++; }
};

template <int BEGIN, int END> struct range {
  iterator begin() const { return iterator(BEGIN); }
  iterator end() const { return iterator(END); }
};

int main(int argc, char **) {
  range<0, 5> list;
  int total = 0;
  for (volatile auto elem : list)
    total += elem * argc; // DexWatch('total', 'elem', 'argc')
  return total;
}

// DexExpectWatchValue('elem', '0', '1', '2', '3', '4', on_line=18)
// DexExpectWatchValue('total', '0', '1', '3', '6', on_line=18)
// DexExpectWatchValue('argc', '1', on_line=18)

// DexExpectStepKind('FUNC_EXTERNAL', 0)
// DexExpectStepKind('FUNC_UNKNOWN', 0)
// DexExpectStepKind('UNKNOWN', 0)

$ py -3 dexter.py test --builder clang --debugger lldb --cflags="-O2 -g -mllvm -opt-bisect-limit=236" --ldflags="-g" -v -- tests\simple_loop_iterator > 236.dexter.output.txt

$ py -3 dexter.py test --builder clang --debugger lldb --cflags="-O2 -g -mllvm -opt-bisect-limit=237" --ldflags="-g" -v -- tests\simple_loop_iterator > 237.dexter.output.txt

$ clang -O2 -g tests\simple_loop_iterator\test.cpp -S -mllvm -opt-bisect-limit=236 -o 236.s 2>nul

$ clang -O2 -g tests\simple_loop_iterator\test.cpp -S -mllvm -opt-bisect-limit=237 -o 237.s 2>nul

$ clang -O2 -g tests\simple_loop_iterator\test.cpp -S -emit-llvm -mllvm -opt-bisect-limit=236 -o 236.ll 2>nul

$ py -3 dexter.py test --builder clang --debugger lldb --cflags="-O2 -g -mllvm -opt-bisect-limit=237" --ldflags="-g" -v -- tests\simple_loop_iterator > 237.dexter.output.txt

$ opt -disable-output -strip-debug -debugify -instcombine -check-debugify 236.ll
WARNING: Missing line 6
WARNING: Missing line 11
WARNING: Missing line 17
WARNING: Missing line 23
WARNING: Missing line 29
WARNING: Missing variable 4
WARNING: Missing variable 6
WARNING: Missing variable 7
WARNING: Missing variable 9
WARNING: Missing variable 10
WARNING: Missing variable 12
WARNING: Missing variable 13
WARNING: Missing variable 15
CheckModuleDebugify: PASS

Mapping these back to the instructions we can see it's lost the variables from almost all of the unrolled mul and add instructions from the ( total += elem * argc; ) line:

: %elem = alloca i32, align 4, !dbg !​11 : %elem.0.elem.0..sroa_cast = bitcast i32 %elem to i8, !dbg !​14 : %elem.0.elem.0. = load volatile i32, i32 %elem, align 4, !dbg !​22, !tbaa !​18 NG: %mul = mul nsw i32 %elem.0.elem.0., %argc, !dbg !​25 : %elem.0.elem.0..1 = load volatile i32, i32 %elem, align 4, !dbg !​30, !tbaa !​18 NG: %mul.1 = mul nsw i32 %elem.0.elem.0..1, %argc, !dbg !​32 NG: %add.1 = add nsw i32 %mul.1, %mul, !dbg !​34 : %elem.0.elem.0..2 = load volatile i32, i32 %elem, align 4, !dbg !​39, !tbaa !​18 NG: %mul.2 = mul nsw i32 %elem.0.elem.0..2, %argc, !dbg !​41 NG: %add.2 = add nsw i32 %mul.2, %add.1, !dbg !​43 : %elem.0.elem.0..3 = load volatile i32, i32 %elem, align 4, !dbg !​48, !tbaa !​18 NG: %mul.3 = mul nsw i32 %elem.0.elem.0..3, %argc, !dbg !​50 NG: %add.3 = add nsw i32 %mul.3, %add.2, !dbg !​52 : %elem.0.elem.0..4 = load volatile i32, i32* %elem, align 4, !dbg !​57, !tbaa !​18 NG: %mul.4 = mul nsw i32 %elem.0.elem.0..4, %argc, !dbg !​59 : %add.4 = add nsw i32 %mul.4, %add.3, !dbg !​61

which translates the following difference in the .s files from before and after the instcombine pass:

$ diff 236.s 237.s | grep DEBUG < #DEBUG_VALUE: main:total <- $eax < #DEBUG_VALUE: main:total <- $edx < #DEBUG_VALUE: main:total <- $eax < #DEBUG_VALUE: main:total <- $edx

I'll attach the output from the above commands shortly.

[gregbedwell]

I don't understand what is different about the clang-cl version. When running instCombine as far as I can tell some dbg.value intrisincs are dropped. It's normal for the debugger to report that the value has been optimized out, isn't it? If lldb reports it as 0 maybe it's a issue with how lldb interprets missing dbg.value vs how Visual Studio does that.

My guess is that it's some difference between the DWARF and Codeview ( https://llvm.org/devmtg/2016-11/Slides/Kleckner-CodeViewInLLVM.pdf ) representations of the information. In terms of the dropped dbg.value intrinsics it shouldn't make a difference. It's mostly there for my reference for comparison later on, and as a note of general interest how the information is treated differently by different consumers (and different DI formats)

[llvmbot]

The next target pass for my project will be the InstCombine. I'll let you know when I have something so you can test it against dexter.

An interesting side note here. With clang-cl and the Visual Studio 2017 debugger the results are slightly different.

I don't understand what is different about the clang-cl version. When running instCombine as far as I can tell some dbg.value intrisincs are dropped. It's normal for the debugger to report that the value has been optimized out, isn't it? If lldb reports it as 0 maybe it's a issue with how lldb interprets missing dbg.value vs how Visual Studio does that.

[gregbedwell]

An interesting side note here. With clang-cl and the Visual Studio 2017 debugger the results are slightly different.

$ clang-cl -v clang version 7.0.0 (trunk 334224) (llvm/trunk 334232) Target: x86_64-pc-windows-msvc Thread model: posix InstalledDir: e:\build-yy\Release\bin

At opt-bisect-limit=236, we get the following trace:

BEGIN

[1, "main", "test.cpp", 22, 1, "BREAKPOINT", "FUNC", {}] [2, "main", "test.cpp", 25, 1, "BREAKPOINT", "FORWARD", {}] [3, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "0", "argc": "1"}] [4, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [5, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "0", "elem": "1", "argc": "1"}] [6, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [7, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "1", "elem": "2", "argc": "1"}] [8, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [9, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "3", "elem": "3", "argc": "1"}] [10, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [11, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "6", "elem": "4", "argc": "1"}] [12, "main", "test.cpp", 27, 1, "BREAKPOINT", "FORWARD", {}]

END (12 steps)

at opt-bisect-limit=237, we now get:

BEGIN

[1, "main", "test.cpp", 22, 1, "BREAKPOINT", "FUNC", {}] [2, "main", "test.cpp", 25, 1, "BREAKPOINT", "FORWARD", {}] [3, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "0", "argc": "identifier \"argc\" is undefined"}] [4, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [5, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "1", "argc": "identifier \"argc\" is undefined"}] [6, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [7, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "2", "argc": "identifier \"argc\" is undefined"}] [8, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [9, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "3", "argc": "identifier \"argc\" is undefined"}] [10, "main", "test.cpp", 25, 1, "BREAKPOINT", "BACKWARD", {}] [11, "main", "test.cpp", 26, 1, "BREAKPOINT", "FORWARD", {"total": "Variable is optimized away and not available.", "elem": "4", "argc": "identifier \"argc\" is undefined"}] [12, "main", "test.cpp", 27, 1, "BREAKPOINT", "FORWARD", {}]

END (12 steps)

[llvmbot]

@llvm/issue-subscribers-debuginfo

Author: Greg Bedwell (gregbedwell)

| | | | --- | --- | | Bugzilla Link | [37741](https://llvm.org/bz37741) | | Version | trunk | | OS | Windows NT | | Blocks | llvm/llvm-project#37301 | | Attachments | [output from clang](https://user-images.githubusercontent.com/40235388/143757612-bd392d84-1bb0-4b87-bf79-fe45e8e7c75e.gz) | | CC | @dwblaikie,@flametop,@jmorse,@pogo59,@tbosch,@vedantk | ## Extended Description I didn't spot this already reported, but as there's been a bit of churn in this area recently, it's possible I missed it. Versions: ~~~~~~~~~~~~~ $ clang -v clang version 7.0.0 (trunk 334224) (llvm/trunk 334232) Target: x86_64-pc-windows-msvc Thread model: posix InstalledDir: e:\build-yy\Release\bin $ lldb -v lldb version 7.0.0 (https://git.llvm.org/git/lldb.git/ revision e719823776f7d6c645598845be4ea28c5ddfdd70) clang revision 334224 llvm revision 334232 ~~~~~~~~~~~~~ source level reproducible ~~~~~~~~~~~~~ $ cat tests\simple_loop_iterator\test.cpp struct iterator { int index_; iterator(int index) : index_(index) {} bool operator!=(iterator const &rhs) const { return index_ != rhs.index_; } int operator*() { return index_; } int operator++() { int ret = index_; ++index_; return ret; } }; struct item { iterator begin() { return iterator(0); } iterator end() { return iterator(5); } }; int main(int argc, char**) { item list; int total = 0; for (volatile auto elem : list) total += elem * argc; // DexWatch('total', 'elem', 'argc') return total; } // DexExpectWatchValue('elem', '0', '1', '2', '3', '4', on_line=26) // DexExpectWatchValue('total', '0', '1', '3', '6', on_line=26) // DexExpectWatchValue('argc', '1', on_line=26) // DexExpectStepKind('FUNC_EXTERNAL', 0) // DexExpectStepKind('FUNC_UNKNOWN', 0) // DexExpectStepKind('UNKNOWN', 0) ~~~~~~~~~~~~~ DExTer observes that pass 237 affects the debugability: ~~~~~~~~~~~~~ pass 236/316 = 0/52 (0.0000, 0.0000) [Bit-Tracking Dead Code Elimination on function (main)] pass 237/316 = 18/52 (0.3462, 0.3462) [Combine redundant instructions on function (main)] pass 238/316 = 18/52 (0.3462, 0.0000) [Jump Threading on function (main)]​ ~~~~~~~~~~~~~ which comes from the result of evaluating the expression 'total' in the debugger on line 26 always showing a value of 0. ~~~~~~~~~~~~~ test.cpp:26 [total] [18/21] expected encountered values: 0 missing values: 1 [+6] 3 [+6] 6 [+6] ~~~~~~~~~~~~~ We can observe that debugify-each also sees errors from combine redundant instructions in this case: ~~~~~~~~~~~~~ $ clang -O2 -mllvm -opt-bisect-limit=236 -emit-llvm tests\simple_loop_iterator\test.cpp -S -o - 2>nul | opt -debugify-each -disable-output -instcombine WARNING: Missing line 6 WARNING: Missing line 11 WARNING: Missing line 17 WARNING: Missing line 23 WARNING: Missing line 29 ERROR: Missing variable 4 ERROR: Missing variable 6 ERROR: Missing variable 7 ERROR: Missing variable 9 ERROR: Missing variable 10 ERROR: Missing variable 12 ERROR: Missing variable 13 ERROR: Missing variable 15 CheckFunctionDebugify [Combine redundant instructions]: FAIL CheckFunctionDebugify [Module Verifier]: PASS ~~~~~~~~~~~~~ I've attached the output from clang in the above command line. My hope is that by fixing the errors reported from debugify we'll be able to verify that the DExTer score improves at the same time.