Frequent use of line 0 in debug info reduces effectiveness of Cachegrind

[nnethercote]

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

[nnethercote]

@michaelwoerister: Do you know anything about this? If you could point to me where debug info is produced in rustc, that would be helpful. Thanks.

[michaelwoerister]

It looks like setting debug locations for instructions always goes through set_debug_location:

rust/src/librustc_codegen_llvm/debuginfo/source_loc.rs

Line 60 in 9ebf478

pub fn set_debug_location(

I don't know where the zeros are introduced though. It might have to do with macros.

[michaelwoerister]

And set_debug_location() is transitively called from set_debug_loc when building LLVM IR from MIR, where the span in question comes from a mir::SourceInfo:

rust/src/librustc_codegen_ssa/mir/mod.rs

Lines 97 to 104 in e369d87

	pub fn set_debug_loc(
	&mut self,
	bx: &mut Bx,
	source_info: mir::SourceInfo
	) {
	let (scope, span) = self.debug_loc(source_info);
	bx.set_source_location(&mut self.debug_context, scope, span);
	}

I suspect that those mir::SourceInfo values already contain the zero lines (but it would be good to verify).

[mati865]

Probably related to #65437?

[est31]

@mati865 that issue is about columns, this issue is about lines. They aren't related.

[mati865]

My bad, didn't pay enough attention.

[est31]

I suspect that those mir::SourceInfo values already contain the zero lines (but it would be good to verify).

@michaelwoerister I've tried verifying it on the playground with a non-trivial rosetta code example and the "show MIR" feature, but it doesn't create any line number zero spans: mir.txt
Grepping that file for ".rs:0" gives no results. When I change the playground to output LLVM IR and search for !DILocation(line: 0, it doesn't show anything either. So I chose to dig a bit further and inspect the LLVM IR. I grepped both for omitted lines via | rg "DILocation" | rg -v line as well as line: 0 but got nothing each time. When I grepped for debuginfo lines (those that start with !) that do contain a file name that isn't <unknown> but don't contain a line number, I only got DIFile and DILexicalBlockFile types (command used (!2 is the <unknown> file): | rg "^!" | rg -v line | rg file | rg -v 'file: !2').

Now to those DILexicalBlockFile types. It seems that they all are mentioned from a DILocation as scope, like the !1227 one below (excerpt):

!1215 = distinct !DISubprogram(name: "copy_nonoverlapping<hashbrown::raw::RawTable<(alloc::string::String, i32)>>", linkageName: "_ZN4core10intrinsics19copy_nonoverlapping17h6368a154fa483cbbE", scope: !1185, file: !1184, line: 1454, type: !1216, scopeLine: 1454, flags: DIFlagPrototyped, spFlags: DISPFlagLocalToUnit | DISPFlagDefinition, unit: !139, templateParams: !1220, retainedNodes: !4)
!1226 = !DILocation(line: 184, column: 22, scope: !1227)
!1227 = !DILexicalBlockFile(scope: !1215, file: !1198, discriminator: 0)
!1230 = !DILocation(line: 184, column: 58, scope: !1227)
!1231 = !DILocation(line: 12, column: 8, scope: !1227)

On the rustc side, they are generated by the LLVMRustDIBuilderCreateLexicalBlockFile function whose only transitive caller is the scope_metadata_for_loc function in this snippet:

rust/src/librustc_codegen_ssa/mir/mod.rs

Lines 106 to 153 in e369d87

	pub fn debug_loc(&self, source_info: mir::SourceInfo) -> (Option<Bx::DIScope>, Span) {
	// Bail out if debug info emission is not enabled.
	match self.debug_context {
	FunctionDebugContext::DebugInfoDisabled |
	FunctionDebugContext::FunctionWithoutDebugInfo => {
	return (self.scopes[source_info.scope].scope_metadata, source_info.span);
	}
	FunctionDebugContext::RegularContext(_) =>{}
	}
	// In order to have a good line stepping behavior in debugger, we overwrite debug
	// locations of macro expansions with that of the outermost expansion site
	// (unless the crate is being compiled with `-Z debug-macros`).
	if !source_info.span.from_expansion() ||
	self.cx.sess().opts.debugging_opts.debug_macros {
	let scope = self.scope_metadata_for_loc(source_info.scope, source_info.span.lo());
	(scope, source_info.span)
	} else {
	// Walk up the macro expansion chain until we reach a non-expanded span.
	// We also stop at the function body level because no line stepping can occur
	// at the level above that.
	let span = syntax_pos::hygiene::walk_chain(source_info.span, self.mir.span.ctxt());
	let scope = self.scope_metadata_for_loc(source_info.scope, span.lo());
	// Use span of the outermost expansion site, while keeping the original lexical scope.
	(scope, span)
	}
	}
	// DILocations inherit source file name from the parent DIScope. Due to macro expansions
	// it may so happen that the current span belongs to a different file than the DIScope
	// corresponding to span's containing source scope. If so, we need to create a DIScope
	// "extension" into that file.
	fn scope_metadata_for_loc(&self, scope_id: mir::SourceScope, pos: BytePos)
	-> Option<Bx::DIScope> {
	let scope_metadata = self.scopes[scope_id].scope_metadata;
	if pos < self.scopes[scope_id].file_start_pos ||
	pos >= self.scopes[scope_id].file_end_pos {
	let sm = self.cx.sess().source_map();
	let defining_crate = self.debug_context.get_ref(DUMMY_SP).defining_crate;
	Some(self.cx.extend_scope_to_file(
	scope_metadata.unwrap(),
	&sm.lookup_char_pos(pos).file,
	defining_crate
	))
	} else {
	scope_metadata
	}
	}

The comments point to macros as the possible cause, but when I get back to @nnethercote 's original report, hashbrown's raw/mod.rs doesn't contain any macro declarations, nor does it contain any major macro invocations beyond one cfg_if, one derive on an error, and a few debug_assert invocations.

So idk. Maybe that's where those 0 line numbers are coming from. However, while I'm not 100% sure, it seems that DILexicalBlockFiles are only used as scope for DILocations that do have line numbers, which would be an argument against DILexicalBlockFile being the culprit. No idea.

I'd have loved to investigate further but I was unable to generate @nnethercote 's output. Which objdump parameters did you use to print the line numbers next to the assembly?

[nnethercote]

@est31: the text I showed above was hand-made, combining objdump -d output with some custom debugging output I inserted into Valgrind. So you won't be able to recreate it, sorry :(

[Tiwalun]

I've had a similar problem with some embedded code, for the thumbv6m-none-eabi target.
I've created a small sample: https://github.com/Tiwalun/rust-debuginfo-test , and uploaded the MIR, LLVM IR, the generated assembly, and the debug information: https://gist.github.com/Tiwalun/840a6792f23e8ab34cbeff2f3a7b04fa .

In my case, the 0 line numbers only appear in the final debug info, the LLVM IR and MIR do not seem to contain them.

Are there rustc / llvm flags to inspect how the debug information is created from the IR?

[nnethercote]

@Tiwalun: that's very helpful, thank you. Can you show the commands you used to generate those outputs?

[est31]

@Tiwalun can you expand on where those 0 line numbers are to be found? I can't find them anywhere in your gist.

[nnethercote]

@est31: in debuginfo_test.dwarfdump there is:

Address            Line   Column File   ISA Discriminator Flags
------------------ ------ ------ ------ --- ------------- -------------
0x00000000000000c0     17      0      1   0             0  is_stmt
0x00000000000000c8     18      4      1   0             0  is_stmt prologue_end
0x00000000000000d4     19      1      1   0             0  is_stmt
0x00000000000000d8     18      4      1   0             0  is_stmt
0x00000000000000e0      0      4      1   0             0 
0x00000000000000e4      0      4      1   0             0  end_sequence
0x00000000000000e4      8      0      1   0             0  is_stmt
0x00000000000000e4     11      4      1   0             0  is_stmt prologue_end
0x00000000000000e6      0      4      1   0             0 
0x00000000000000ea     12      8      1   0             0  is_stmt
0x00000000000000f0     11      4      1   0             0  is_stmt
0x00000000000000f2     11      4      1   0             0  is_stmt end_sequence

Three of the entries have a 0 value for line.