Frequent use of line 0 in debug info reduces effectiveness of Cachegrind #65487
Comments
jonas-schievink
added
A-debuginfo
|
@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. |
|
It looks like setting debug locations for instructions always goes through I don't know where the zeros are introduced though. It might have to do with macros. |
|
And rust/src/librustc_codegen_ssa/mir/mod.rs Lines 97 to 104 in e369d87 I suspect that those |
This comment has been minimized.
This comment has been minimized.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
@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 Now to those On the rustc side, they are generated by the rust/src/librustc_codegen_ssa/mir/mod.rs Lines 106 to 153 in e369d87 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 So idk. Maybe that's where those 0 line numbers are coming from. However, while I'm not 100% sure, it seems that 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? |
|
@est31: the text I showed above was hand-made, combining |
|
I've had a similar problem with some embedded code, for the 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? |
|
@Tiwalun: that's very helpful, thank you. Can you show the commands you used to generate those outputs? |
|
@Tiwalun can you expand on where those 0 line numbers are to be found? I can't find them anywhere in your gist. |
|
@est31: in Three of the entries have a 0 value for |
|
It's interesting that 0xe4 has three entries, with different line/column combinations: The instruction at 0xe4 is a branch, so it seems to correspond to the |
|
The The The |
|
There are three entries for the same instruction: #[entry]
fn main() -> ! {
loop {
delay(1000);
}
}
fn delay(ms: u16) {
ms + 1;
}I got this result from Now it became So somehow the debuginfo leaks over. In the LLVM IR I can't see any usage of anything with column 10 in the main function. It's all only in the delay function. To summarize I'd say there is a bug in LLVM involved. |
jonas-schievink
added
the
A-LLVM
|
Interestingly, I believe I was able to track this down to a regression in nightly-2017-04-26 (with some certainty, I have not been able to compile rustc from back then). From that day, #41508 seems like the most likely culprit. It's rather plausible that one of the many changes in that PR altered how debuginfo contexts were managed in such a way that certain lines get lost in the process. I've also noticed that pretty much all of these 0-lines occur near scope boundaries, seemingly in the middle of drop glue code. I don't have a ton of time to work on this, but I would definitely recommend starting there for anyone that takes a look. |
|
Regarding the way that the 0-lines cause columns to leak over, that likely has to do with the way line/column information is kept track of internally by LLVM. Line and column changes are emitted as |
|
I ran into this issue while looking at the stack trace of a core dump: fn main() {
never_returns("this is the panic message");
}
struct HasDrop(&'static str);
impl Drop for HasDrop {
fn drop(&mut self) { }
}
struct HasDropGlue(HasDrop);
#[no_mangle]
pub fn never_returns(s: &'static str) -> ! {
(move || {
if let Some(s) = condition(s) {
do_panic(&HasDropGlue(HasDrop(s)));
} else {
do_panic(&HasDropGlue(HasDrop("unknown"))); // this line will have a 0 line number
}
})()
}
#[inline(never)]
fn condition(s: &str) -> Option<&str> {
if s.len() == 0 { Some("hello") }
else { None }
}
fn do_panic(h: &HasDropGlue) -> ! {
panic!("{}", h.0.0);
}eg, in lldb (frame 15): $ rustc --crate-name panic_test2 repro.rs -C opt-level=1 -C panic=abort -C debuginfo=1
$ lldb ./panic_test2
(lldb) r
Process 30942 launched: '/tmp/panic_test/panic_test2' (x86_64)
thread 'main' panicked at src/main.rs:29:5:
unknown
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Process 30942 stopped
* thread #1, name = 'panic_test2', stop reason = signal SIGABRT
frame #0: 0x00007ffff7e01a7c libc.so.6`__GI___pthread_kill at pthread_kill.c:44:76
(lldb) bt
* thread #1, name = 'panic_test2', stop reason = signal SIGABRT
...
frame #14: 0x000055555555c5c6 panic_test2`panic_test2::do_panic::h2c0ead66774c0583 at main.rs:29:5
frame #15: 0x000055555555c591 panic_test2`panic_test2::never_returns::_$u7b$$u7b$closure$u7d$$u7d$::h2a38757633d1adfc at main.rs:0:23
frame #16: 0x000055555555c548 panic_test2`never_returns at main.rs:13:5
frame #17: 0x000055555555c522 panic_test2`panic_test2::main::h426c9076b0e597ab at main.rs:2:5
...Which matches what is in the line table: $ llvm-dwarfdump --debug-line ./panic_test2
...
file_names[ 8]:
name: "main.rs"
dir_index: 7
mod_time: 0x00000000
length: 0x00000000
...
Address Line Column File ISA Discriminator Flags
------------------ ------ ------ ------ --- ------------- -------------
...
0x0000000000008587 0 23 8 0 0
0x0000000000008593 0 23 8 0 0 end_sequencerustc generates the correct line numbers for this program: ...
bb2: ; preds = %start
...
; call panic_test2::do_panic
call fastcc void @_ZN11panic_test28do_panic17h2c0ead66774c0583E(ptr noalias noundef nonnull readonly align 8 dereferenceable(16) %_7) #10, !dbg !92
...
bb3: ; preds = %start
...
; call panic_test2::do_panic
call fastcc void @_ZN11panic_test28do_panic17h2c0ead66774c0583E(ptr noalias noundef nonnull readonly align 8 dereferenceable(16) %_11) #10, !dbg !94
...
!85 = distinct !DISubprogram(name: "bad_debug_info", linkageName: "bad_debug_info", scope: !86, file: !80, line: 14, type: !13, scopeLine: 14, flags: DIFlagPrototyped | DIFlagNoReturn, spFlags: DISPFlagLocalToUnit | DISPFlagDefinition | DISPFlagOptimized, unit: !6, templateParams: !14)
!88 = distinct !DILexicalBlock(scope: !85, file: !80, line: 15, column: 39)
!92 = !DILocation(line: 16, column: 13, scope: !88)
!94 = !DILocation(line: 18, column: 13, scope: !85)However, when lowering to machine code, these line numbers are erased and replaced with line 0: ...
.loc 1 0 23 is_stmt 0 # src/main.rs:0:23
leaq 8(%rsp), %rdi
callq panic_test2::do_panic::h2c0ead66774c0583
ud2
...I've filed an upstream issue for this llvm/llvm-project#65667 |
workingjubilee
added
S-blocked
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:
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:
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 functionsyntax_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.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:
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
The text was updated successfully, but these errors were encountered: