Shorten backtraces for queries in ICEs

[chenyukang]

r? @jyn514
Fixes #107910

[jyn514]

Can you please add a test case that this works? You can force a panic with -Z treat-err-as-bug.

[Nilstrieb]

This touches the query system by adding a call to it, so
@bors try @rust-timer queue

[bors]

⌛ Trying commit 1e80402 with merge 8a09f0bf71c4a2e3329eda090794d214addf3b2b...

[Zoxc]

This should not use __rust_begin_short_backtrace as that affect proper backtraces and also doesn't work for delayed bugs which uses Backtrace. This should also not be done by default, but by opt-in.

[jyn514]

@Zoxc What do you mean by "proper backtraces"? Why not do this by default? The only time I can imagine the query internals being useful is for people working on the query system itself, which is a very small minority of the people working on the compiler.

[Nilstrieb]

It can sometimes be useful to see where a query was exactly called from. While the query backtrace does contain the calling query name, it doesn't contain more precise information about the location of the call to the query.

[Zoxc]

What do you mean by "proper backtraces"?

I meant backtraces generated with RUST_BACKTRACE=1.

The query internals isn't that useful for people not working on the query system, but the actual backtrace still is useful to see why a specific query was called.

[Nilstrieb]

Ideally we'd hide all the query internals from tcx.x to fn x ✨

[chenyukang]

I think the default short log makes debugging easier:

[jyn514]

Ideally we'd hide all the query internals from tcx.x to fn x ✨

That's exactly what this PR is trying to do. @chenyukang can you post an example of the shortened backtrace for the new test you added? I think having a concrete example will make it more clear what this does.

[chenyukang]

RUST_BACKTRACE=1 rustc +dev src/lib.rs -Z treat-err-as-bug=1  > ./short.log 2>&1

short.log

RUST_BACKTRACE=full rustc +dev src/lib.rs -Z treat-err-as-bug=1  > ./full.log 2>&1

full.log

[Nilstrieb]

Your example doesn't really exercise the query system, can you show an example of something deep within it instead? Like a trait bound error

[chenyukang]

Your example doesn't really exercise the query system, can you show an example of something deep within it instead? Like a trait bound error

I just run the wrong command, re-uploaded new log files.

[jyn514]

@chenyukang I think you're missing a call to rust_end_short_backtrace, this is excluding all frames before get_query which isn't correct.

[chenyukang]

@jyn514 yes, we should only exclude the frames of queries.
I will take a look tomorrow, need some sleep 😁

[chenyukang]

hmm, interesting, I read the code and try some sample code, __rust_begin_short_backtrace and __rust_end_short_backtrace do not work as I thought.

Actually __rust_end_short_backtrace is called at the end(inner most) of backtrace:

rust/library/std/src/panicking.rs

Line 579 in 39f2657

crate::sys_common::backtrace::__rust_end_short_backtrace(move || {

then __rust_begin_short_backtrace is the starting point of the backtrace, here is the logic:

rust/library/std/src/sys_common/backtrace.rs

Lines 72 to 93 in f37f854

	backtrace_rs::resolve_frame_unsynchronized(frame, |symbol| {
	hit = true;
	if print_fmt == PrintFmt::Short {
	if let Some(sym) = symbol.name().and_then(|s| s.as_str()) {
	if start && sym.contains("__rust_begin_short_backtrace") {
	stop = true;
	return;
	}
	if sym.contains("__rust_end_short_backtrace") {
	start = true;
	return;
	}
	}
	}
	if start {
	res = bt_fmt.frame().symbol(frame, symbol);
	}
	});
	if stop {
	return false;
	}

this means we can not use these two functions to remove a middle part of backtrace frames, instead, we can only set the starting point.

I used this sample program to verify it:

#[inline(never)]
fn __rust_begin_short_backtrace<T, F: FnOnce() -> T>(f: F) -> T {
    let result = f();

    // prevent this frame from being tail-call optimised away
    std::hint::black_box(result)
}

#[inline(never)]
fn __rust_end_short_backtrace<T, F: FnOnce() -> T>(f: F) -> T {
    let result = f();

    // prevent this frame from being tail-call optimised away
    std::hint::black_box(result)
}


fn first() {
    println!("first ...");
    second();
}

fn second() {
    println!("second ..");
    third();
}

fn third() {
    println!("third ...");
    __rust_end_short_backtrace(|| fourth());
}

fn fourth() {
    println!("fourth ..");
    fifth();
}

fn fifth() {
    println!("fifth ...");
    __rust_begin_short_backtrace(|| sixth());
}

fn sixth() {
    println!("sixth ..");
    seven();
}

fn seven() {
    println!("seven");
    panic!("debug now");
}


fn main() {
    first();
}

[jyn514]

ah, that's unfortunate. can we modify that logic to support our use case without breaking existing backtraces? maybe by setting start = false when we hit begin_backtrace instead of stop = true?

[rustbot]

Hey! It looks like you've submitted a new PR for the library teams!

If this PR contains changes to any rust-lang/rust public library APIs then please comment with @rustbot label +T-libs-api -T-libs to tag it appropriately. If this PR contains changes to any unstable APIs please edit the PR description to add a link to the relevant API Change Proposal or create one if you haven't already. If you're unsure where your change falls no worries, just leave it as is and the reviewer will take a look and make a decision to forward on if necessary.

Examples of T-libs-api changes:

• Stabilizing library features
• Introducing insta-stable changes such as new implementations of existing stable traits on existing stable types
• Introducing new or changing existing unstable library APIs (excluding permanently unstable features / features without a tracking issue)
• Changing public documentation in ways that create new stability guarantees
• Changing observable runtime behavior of library APIs

[cjgillot]

@bors r+

[bors]

📌 Commit d8f91e8 has been approved by cjgillot

It is now in the queue for this repository.

[raoulstrackx]

This fails on the SGX platform with:

/home/jenkins/workspace/rust-sgx-ci/rust/build/x86_64-unknown-linux-gnu/stage1/bin/rustc: error while loading shared libraries: librustc_driver-b910c833a504f4dd.so: cannot open shared object file: No such file or directory

I'm confused why we get that error. You can ignore the SGX platform for this test as well.

[bjorn3]

Can you please emit some kind of marker to indicate that frames have been omitted? This is just plain confusing. For example

Suggested change

	4: short_ice_remove_middle_frames::second
	[some frames omitted]
	4: short_ice_remove_middle_frames::second

or

Suggested change

	4: short_ice_remove_middle_frames::second
	[2 frames omitted]
	4: short_ice_remove_middle_frames::second

[chenyukang]

I made a change: ddacb2d

Found out we need to update https://github.com/rust-lang/backtrace-rs.git to add an API to emit the message.

Maybe we can enhance it in another PR?

[jyn514]

Could you open an issue for adding the "N frame omitted" line, please?

[chenyukang]

Sure, I will create an issue, then make a PR for backtrace-rs first, then another follow-up PR for it.

[bors]

☔ The latest upstream changes (presumably #108062) made this pull request unmergeable. Please resolve the merge conflicts.

[chenyukang]

@rustbot ready
Hope we can merge it this time 😂

[jyn514]

@bors r=cjgillot rollup=iffy

[bors]

📌 Commit c3394b3 has been approved by cjgillot

It is now in the queue for this repository.

[bors]

⌛ Testing commit c3394b3 with merge 77c836e...

[bors]

☀️ Test successful - checks-actions
Approved by: cjgillot
Pushing 77c836e to master...

[rust-timer]

Finished benchmarking commit (77c836e): comparison URL.

Overall result: ❌✅ regressions and improvements - ACTION NEEDED

Next Steps: If you can justify the regressions found in this perf run, please indicate this with @rustbot label: +perf-regression-triaged along with sufficient written justification. If you cannot justify the regressions please open an issue or create a new PR that fixes the regressions, add a comment linking to the newly created issue or PR, and then add the perf-regression-triaged label to this PR.

@rustbot label: +perf-regression
cc @rust-lang/wg-compiler-performance

Instruction count

This is a highly reliable metric that was used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	0.3%	[0.2%, 0.4%]	3
Regressions ❌ (secondary)	0.4%	[0.2%, 0.6%]	10
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-0.2%	[-0.3%, -0.2%]	3
All ❌✅ (primary)	0.3%	[0.2%, 0.4%]	3

Max RSS (memory usage)

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	-	-	0
Regressions ❌ (secondary)	2.7%	[2.1%, 3.4%]	2
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-1.4%	[-1.4%, -1.4%]	2
All ❌✅ (primary)	-	-	0

Cycles

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	-	-	0
Regressions ❌ (secondary)	3.0%	[2.5%, 3.9%]	3
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	-	-	0

Binary size

This benchmark run did not return any relevant results for this metric.

Bootstrap: 642.167s -> 641.625s (-0.08%)

[jyn514]

The perf regression was expected and deemed acceptable: #108938 (review)