Repository: rust
Issue: Frequent use of line 0 in debug info reduces effectiveness of Cachegrind
Labels: A-LLVM,A-debuginfo,T-compiler,C-bug,S-waiting-on-LLVM

I frequently use Cachegrind (and Callgrind) to profile rustc and other Rust programs. Cachegrind attributes instruction counts (and possibly cache misses and branch mispredictions) to specific lines of code, like this:
```
      .               /// Maps a string to its interned representation.
320,664 ( 0.27%)      pub fn intern(string: &str) -> Self {
160,332 ( 0.14%)          with_interner(|interner| interner.intern(string))
267,220 ( 0.23%)      }
```
But when profiling rustc with Cachegrind, lots of instruction counts don't get attribute to a particular line, so we end up with output like this:
```
1,555,039 ( 1.33%)  <counts for unidentified lines in /home/njn/.cargo/registry/
src/github.com-1ecc6299db9ec823/hashbrown-0.6.1/src/raw/mod.rs>
```
Often the fraction of executed instructions that don't get attributed to a particular line is 20%, 30%, or higher. That's a lot!

The way Cachegrind works is that the first time an instruction, X, from the binary is executed, Cachegrind gets X's file name and line number from debug info, and X's function name from the symbol table, and creates a (address, filename, fn_name, line_num) cost centre. Every time X is executed the cost centre is incremented appropriately.

The problem with the Rust code's debug info is that there are lots of instructions for which the debug info says the line number is 0. That means Cachegrind can't attribute a line, and all executions of such instructions count towards the "unidentified lines" entry. Notably, these instructions do have a valid filename.

I grabbed some debugging output from Valgrind and matched it up with the binary code, as produced by `objdump -d`. What follows is for the function `syntax_pos::symbol::Interner::intern`. The machine code is on the left, and Valgrind's output for each instruction (its runtime address, filename, and line number) is on the right.
```
0000000001b742a0 <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE>:
 1b742a0:  push   %rbp             # 0x65CF2A0 libsyntax_pos/symbol.rs:976
 1b742a1:  push   %r15             # 0x65CF2A1 libsyntax_pos/symbol.rs:976
 1b742a3:  push   %r14             # 0x65CF2A3 libsyntax_pos/symbol.rs:976
 1b742a5:  push   %r13             # 0x65CF2A5 libsyntax_pos/symbol.rs:976
 1b742a7:  push   %r12             # 0x65CF2A7 libsyntax_pos/symbol.rs:976
 1b742a9:  push   %rbx             # 0x65CF2A9 libsyntax_pos/symbol.rs:976
 1b742aa:  sub    $0x58,%rsp       # 0x65CF2AA libsyntax_pos/symbol.rs:976
 1b742ae:  mov    %rsi,%r13        # 0x65CF2AE libsyntax_pos/symbol.rs:976
 1b742b1:  movabs $0x517cc1b727220a95,%rax
                                   # 0x65CF2B1 libsyntax_pos/symbol.rs:976
 1b742bb:  cmp    $0x8,%rdx        # 0x65CF2BB rustc-hash-1.0.1/src/lib.rs:81
 1b742bf:  jb     1b742e7 <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0x47>
                                   # 0x65CF2BF rustc-hash-1.0.1/src/lib.rs:81
 1b742c1:  lea    -0x8(%rdx),%r8   # 0x65CF2C1 rustc-hash-1.0.1/src/lib.rs:81
 1b742c5:  mov    %r8,%rbp         # 0x65CF2C5 rustc-hash-1.0.1/src/lib.rs:81
 1b742c8:  shr    $0x3,%rbp        # 0x65CF2C8 rustc-hash-1.0.1/src/lib.rs:81
 1b742cc:  add    $0x1,%rbp        # 0x65CF2CC rustc-hash-1.0.1/src/lib.rs:81
 1b742d0:  mov    %ebp,%ecx        # 0x65CF2D0 rustc-hash-1.0.1/src/lib.rs:81
 1b742d2:  and    $0x3,%ecx        # 0x65CF2D2 rustc-hash-1.0.1/src/lib.rs:81
 1b742d5:  cmp    $0x18,%r8        # 0x65CF2D5 rustc-hash-1.0.1/src/lib.rs:81
 1b742d9:  jae    1b742fe <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0x5e>
                                   # 0x65CF2D9 rustc-hash-1.0.1/src/lib.rs:81
 1b742db:  xor    %ebx,%ebx        # 0x65CF2DB rustc-hash-1.0.1/src/lib.rs:0
 1b742dd:  mov    %r13,%rsi        # 0x65CF2DD rustc-hash-1.0.1/src/lib.rs:0
 1b742e0:  test   %rcx,%rcx        # 0x65CF2E0 rustc-hash-1.0.1/src/lib.rs:81
 1b742e3:  jne    1b7434e <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0xae>(0x65CF2E3) -> 1b7434e
                                   # 0x65CF2E3 rustc-hash-1.0.1/src/lib.rs:81
 ...                               # ...
 1b7434e:  xor    %ebp,%ebp        # 0x65CF34E rustc-hash-1.0.1/src/lib.rs:0
 1b74350:  rol    $0x5,%rbx        # 0x65CF350 libcore/num/mod.rs:2461
 1b74354:  xor    (%rsi,%rbp,8),%rbx 
                                   # 0x65CF354 libcore/ops/bit.rs:306
 1b74358:  imul   %rax,%rbx        # 0x65CF358 libcore/num/mod.rs:3096
 1b7435c:  add    $0x1,%rbp        # 0x65CF35C rustc-hash-1.0.1/src/lib.rs:81
 1b74360:  cmp    %rbp,%rcx        # 0x65CF360 rustc-hash-1.0.1/src/lib.rs:81
 1b74363:  jne    1b74350 <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0xb0>
                                   # 0x65CF363 rustc-hash-1.0.1/src/lib.rs:81
 1b74365:  mov    %r8,%rsi         # 0x65CF365 rustc-hash-1.0.1/src/lib.rs:81
 1b74368:  and    $0xfffffffffffffff8,%rsi
                                   # 0x65CF368 rustc-hash-1.0.1/src/lib.rs:81
 1b7436c:  lea    (%rsi,%r13,1),%rcx
                                   # 0x65CF36C rustc-hash-1.0.1/src/lib.rs:81
 1b74370:  add    $0x8,%rcx        # 0x65CF370 rustc-hash-1.0.1/src/lib.rs:81
 1b74374:  sub    %rsi,%r8         # 0x65CF374 rustc-hash-1.0.1/src/lib.rs:81
 1b74377:  cmp    $0x3,%r8         # 0x65CF377 rustc-hash-1.0.1/src/lib.rs:85
 1b7437b:  jbe    1b74392 <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0xf2>
                                   # 0x65CF37B rustc-hash-1.0.1/src/lib.rs:85
 ...                               # ...
 1b74392:  cmp    $0x2,%r8         # 0x65CF392 rustc-hash-1.0.1/src/lib.rs:89
 1b74396:  jae    1b7458b <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0x2eb>
                                   # 0x65CF396 rustc-hash-1.0.1/src/lib.rs:89
 1b7439c:  test   %r8,%r8          # 0x65CF39C rustc-hash-1.0.1/src/lib.rs:93
 1b7439f:  je     1b743af <_ZN10syntax_pos6symbol8Interner6intern17h6c86044010aa5bfcE+0x10f>
                                   # 0x65CF39F rustc-hash-1.0.1/src/lib.rs:93
 1b743a1:  movzbl (%rcx),%ecx      # 0x65CF3A1 rustc-hash-1.0.1/src/lib.rs:94
 1b743a4:  rol    $0x5,%rbx        # 0x65CF3A4 libcore/num/mod.rs:2461
 1b743a8:  xor    %rcx,%rbx        # 0x65CF3A8 libcore/ops/bit.rs:306
 1b743ab:  imul   %rax,%rbx        # 0x65CF3AB libcore/num/mod.rs:3096
 1b743af:  lea    0x30(%rdi),%rcx  # 0x65CF3AF libsyntax_pos/symbol.rs:0
 1b743b3:  mov    %rcx,0x20(%rsp)
                                   # 0x65CF3B3 libsyntax_pos/symbol.rs:0
 1b743b8:  rol    $0x5,%rbx        # 0x65CF3B8 libcore/num/mod.rs:2461
 1b743bc:  xor    $0xff,%rbx       # 0x65CF3BC libcore/ops/bit.rs:306
 1b743c3:  imul   %rax,%rbx        # 0x65CF3C3 libcore/num/mod.rs:3096
 1b743c7:  mov    0x30(%rdi),%rcx
                                   # 0x65CF3C7 hashbrown-0.6.1/src/raw/mod.rs:489
 1b743cb:  mov    0x38(%rdi),%rsi  # 0x65CF3CB hashbrown-0.6.1/src/raw/mod.rs:0
 1b743cf:  mov    %rbx,%rax        # 0x65CF3CF hashbrown-0.6.1/src/raw/mod.rs:0
 1b743d2:  shr    $0x39,%rax       # 0x65CF3D2 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743d6:  movd   %eax,%xmm0       # 0x65CF3D6 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743da:  punpcklbw %xmm0,%xmm0   # 0x65CF3DA hashbrown-0.6.1/src/raw/mod.rs:0
 1b743de:  pshuflw $0xe0,%xmm0,%xmm0
                                   # 0x65CF3DE hashbrown-0.6.1/src/raw/mod.rs:0
 1b743e3:  pshufd $0x0,%xmm0,%xmm1 # 0x65CF3E3 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743e8:  mov    %rdi,0x28(%rsp)  # 0x65CF3E8 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743ed:  mov    0x40(%rdi),%r12  # 0x65CF3ED hashbrown-0.6.1/src/raw/mod.rs:0
 1b743f1:  xor    %ebp,%ebp        # 0x65CF3F1 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743f3:  pcmpeqd %xmm2,%xmm2     # 0x65CF3F3 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743f7:  mov    0x4a9b8a(%rip),%r14        # 201df88 <bcmp@GLIBC_2.2.5>
                                   # 0x65CF3F7 hashbrown-0.6.1/src/raw/mod.rs:0
 1b743fe:  and    %rcx,%rbx        # 0x65CF3FE hashbrown-0.6.1/src/raw/mod.rs:0
 1b74401:  movdqu (%rsi,%rbx,1),%xmm3
                                   # 0x65CF401 libcore/intrinsics.rs:1462
```
The thing to notice is that the majority of the lines have a valid filename and line number. (The filenames jump around a lot due to inlining. That's fine.) But quite a few of them have a line number of zero. There is no obvious pattern to the zeroes; sometimes there are one or two in a sequence, sometimes there are more.

If we trace through these instructions once, here are the filename/linenum pairs that get instructions counted towards them:
```
libsyntax_pos/symbol.rs:976        x 9
rustc-hash-1.0.1/src/lib.rs:81     x 10
rustc-hash-1.0.1/src/lib.rs:0              (0!)
rustc-hash-1.0.1/src/lib.rs:81     x 2
rustc-hash-1.0.1/src/lib.rs:0              (0!)
libcore/num/mod.rs:2461
libcore/ops/bit.rs:306
libcore/num/mod.rs:3096
rustc-hash-1.0.1/src/lib.rs:81     x 8
rustc-hash-1.0.1/src/lib.rs:85     x 2
rustc-hash-1.0.1/src/lib.rs:89     x 2
rustc-hash-1.0.1/src/lib.rs:93     x 2
rustc-hash-1.0.1/src/lib.rs:94
libcore/num/mod.rs:2461
libcore/ops/bit.rs:306
libcore/num/mod.rs:3096
libsyntax_pos/symbol.rs:0          x 2     (0!)
libcore/num/mod.rs:2461
libcore/ops/bit.rs:306
libcore/num/mod.rs:3096
hashbrown-0.6.1/src/raw/mod.rs:489
hashbrown-0.6.1/src/raw/mod.rs:0   x 13    (0!)
libcore/intrinsics.rs:1462
```
47 instructions have a non-zero line number, and 17 have a zero line number.

I haven't seen this problem occur with C and C++ code.

I suspect the problem is that the production of debug info isn't rigorous enough in some fashion, and Cachegrind's requirements might be more onerous than other tools'. (Debug info is often not tested thoroughly.) Sometimes it can be non-obvious exactly which line of code an instruction should be attributed to. In that case, I'm not too fussed so long as it's attributed to something plausible and not zero.

cc @julian-seward1