Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Prevent __rust_begin_short_backtrace frames from being tail-call optimised away #75048

Merged
merged 1 commit into from
Aug 8, 2020

Conversation

eggyal
Copy link
Contributor

@eggyal eggyal commented Aug 2, 2020

I've stumbled across some situations where there (unexpectedly) was no __rust_begin_short_backtrace frame on the stack during unwinding.

On closer examination, it appeared that the calls to that function had been tail-call optimised away.

This PR follows @bjorn3's suggestion on Zulip, by adding calls to black_box that hint to rustc not to perform TCO.

Fixes #47429

@rust-highfive
Copy link
Collaborator

r? @dtolnay

(rust_highfive has picked a reviewer for you, use r? to override)

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 2, 2020
@Mark-Simulacrum
Copy link
Member

Do we have evidence this actually fixes things? I would prefer to see this land alongside a UI test or so that actually verifies that we're seeing the behavior we expect here.

Alternatively, it may be that the right fix isn't in removing TCO from the short backtrace function but reworking how we determine where to start/stop short backtraces.

@eggyal
Copy link
Contributor Author

eggyal commented Aug 2, 2020

It has certainly fixed the lack of __rust_begin_short_backtrace frame that I was running up against—but that was in a custom unwind routine so perhaps not the easiest way to test. Just thinking aloud: what would be an appropriate UI test? Checking that the output when panicking with RUST_BACKTRACE=1 stops before catch_unwind?

@eggyal
Copy link
Contributor Author

eggyal commented Aug 2, 2020

An idea for an alternative approach could be to store the stack pointer somewhere (thread-local?), and compare against that when unwinding.

@Mark-Simulacrum
Copy link
Member

For testing I think the best thing is probably to use a unit test in library/std/src/backtrace.rs that asserts a given number of frames and a start/stop frame when getting a short backtrace. We might need to extract the actual formatting invocation to do so, though, into a separate function not tied to panicking in particular.

I don't think we need thread locals to get good results. I experimented a bit locally, and was able to get things down to this:

thread 'main' panicked at 'Test', /home/mark/Build/rust/library/std/src/panicking.rs:457:65
stack backtrace:
   0: std::panicking::begin_panic
             at ./Build/rust/library/std/src/panicking.rs:456
   1: t::bar
             at ./t.rs:6
   2: t::main
             at ./t.rs:2
   3: core::ops::function::FnOnce::call_once
             at ./Build/rust/library/core/src/ops/function.rs:233
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

And with nightly:

thread 'main' panicked at 'Test', t.rs:6:5
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at library/std/src/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at library/std/src/sys_common/backtrace.rs:59
   4: core::fmt::write
             at library/core/src/fmt/mod.rs:1117
   5: std::io::Write::write_fmt
             at library/std/src/io/mod.rs:1510
   6: std::sys_common::backtrace::_print
             at library/std/src/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at library/std/src/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at library/std/src/panicking.rs:198
   9: std::panicking::default_hook
             at library/std/src/panicking.rs:217
  10: std::panicking::rust_panic_with_hook
             at library/std/src/panicking.rs:526
  11: std::panicking::begin_panic
             at /rustc/cfc572cae2d1fc381cce476b5c787fd7221af98c/library/std/src/panicking.rs:456
  12: t::bar
             at ./t.rs:6
  13: t::main
             at ./t.rs:2
  14: std::rt::lang_start::{{closure}}
             at /rustc/cfc572cae2d1fc381cce476b5c787fd7221af98c/library/std/src/rt.rs:67
  15: std::rt::lang_start_internal::{{closure}}
             at library/std/src/rt.rs:52
  16: std::panicking::try::do_call
             at library/std/src/panicking.rs:348
  17: std::panicking::try
             at library/std/src/panicking.rs:325
  18: std::panic::catch_unwind
             at library/std/src/panic.rs:394
  19: std::rt::lang_start_internal
             at library/std/src/rt.rs:51
  20: std::rt::lang_start
             at /rustc/cfc572cae2d1fc381cce476b5c787fd7221af98c/library/std/src/rt.rs:67
  21: main
  22: __libc_start_main
  23: _start
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

@erikdesjardins
Copy link
Contributor

This likely fixes #47429

@eggyal eggyal force-pushed the force-no-tco-start-backtrace-frame branch from cd53efc to 88b9aab Compare August 4, 2020 14:12
@Mark-Simulacrum
Copy link
Member

I think we should try to add a UI test for this. My guess is we can do that with a run-fail test, like this one https://github.com/rust-lang/rust/blob/master/src/test/ui/test-panic-abort.rs

@eggyal
Copy link
Contributor Author

eggyal commented Aug 4, 2020

I think we should try to add a UI test for this. My guess is we can do that with a run-fail test, like this one https://github.com/rust-lang/rust/blob/master/src/test/ui/test-panic-abort.rs

Agreed, I'll add one now.

@Mark-Simulacrum
Copy link
Member

This looks great. Could you squash the commits into just the one to clean up git history a bit?

I suspect that this PR might cause problems if there's cases or platforms where our mini-functions get elided regardless of the black box, but we can iron out the kinks in nightly -- I don't think we'll find them by just looking in this PR, and it's small enough that I am comfortable just landing it.

r=me with commits squashed

@eggyal eggyal force-pushed the force-no-tco-start-backtrace-frame branch from bebe4a6 to 18d4ba3 Compare August 4, 2020 21:18
@eggyal
Copy link
Contributor Author

eggyal commented Aug 4, 2020

Sure, force-pushed a squash. Had thought bors would do that when merging.

@Mark-Simulacrum
Copy link
Member

@bors r+ rollup=iffy -- not sure if the added test will have the exact same output on other platforms

@bors
Copy link
Contributor

bors commented Aug 4, 2020

📌 Commit 18d4ba34907e7d0b9fc142a9d9a9c5bbdae4279f has been approved by Mark-Simulacrum

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 4, 2020
@bors
Copy link
Contributor

bors commented Aug 4, 2020

⌛ Testing commit 18d4ba34907e7d0b9fc142a9d9a9c5bbdae4279f with merge cca2c20c8b6cd0a71346bf7f85feb3c6291bd60d...

@bors
Copy link
Contributor

bors commented Aug 4, 2020

💔 Test failed - checks-actions

@bors bors added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels Aug 4, 2020
@bjorn3
Copy link
Member

bjorn3 commented Aug 4, 2020

spurious network error

@rust-log-analyzer
Copy link
Collaborator

The job i686-gnu of your PR failed (pretty log, raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @rust-lang/infra. (Feature Requests)

@Mark-Simulacrum
Copy link
Member

@bors retry

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 4, 2020
@bors
Copy link
Contributor

bors commented Aug 4, 2020

⌛ Testing commit 18d4ba34907e7d0b9fc142a9d9a9c5bbdae4279f with merge c70a4d6c76d010b569fa4d16b2ffb7eced04bc52...

@eggyal eggyal force-pushed the force-no-tco-start-backtrace-frame branch from 97c8f93 to 5792840 Compare August 7, 2020 18:31
@eggyal
Copy link
Contributor Author

eggyal commented Aug 7, 2020

@Mark-Simulacrum could we give this another crack please? I spotted an error before bors got a chance to retry.

@Mark-Simulacrum
Copy link
Member

@bors r+

@bors
Copy link
Contributor

bors commented Aug 7, 2020

📌 Commit 5792840 has been approved by Mark-Simulacrum

@bors
Copy link
Contributor

bors commented Aug 8, 2020

⌛ Testing commit 5792840 with merge f3a9de9...

@bors
Copy link
Contributor

bors commented Aug 8, 2020

☀️ Test successful - checks-actions, checks-azure
Approved by: Mark-Simulacrum
Pushing f3a9de9 to master...

@bors bors added the merged-by-bors This PR was explicitly merged by bors. label Aug 8, 2020
@bors bors merged commit f3a9de9 into rust-lang:master Aug 8, 2020
@eggyal eggyal deleted the force-no-tco-start-backtrace-frame branch August 8, 2020 01:49
@rust-highfive
Copy link
Collaborator

📣 Toolstate changed by #75048!

Tested on commit f3a9de9.
Direct link to PR: #75048

💔 miri on windows: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung).
💔 miri on linux: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung).

rust-highfive added a commit to rust-lang-nursery/rust-toolstate that referenced this pull request Aug 8, 2020
Tested on commit rust-lang/rust@f3a9de9.
Direct link to PR: <rust-lang/rust#75048>

💔 miri on windows: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung).
💔 miri on linux: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung).
@ecstatic-morse
Copy link
Contributor

This PR resulted in moderate regressions in instruction counts. The increase is mostly concentrated in very small benchmarks with little generated code, and seems to be caused by some additional codegen query invocations.

Is there any way to mitigate this? This is more impactful for superficial benchmarks than for actual users, so I don't think it necessitates a revert if the regressions are unavoidable.

@Mark-Simulacrum
Copy link
Member

My guess is no -- we're probably just paying the cost of having one more function to codegen. I suspect any fix (e.g., trying to locate the inlined call frame manually or so) is going to be more expensive than the current tiny regressions.

@eggyal
Copy link
Contributor Author

eggyal commented Aug 17, 2020

We could limit the effect of this PR to debug builds only? Enforcing short backtraces in release is unlikely to be a requirement?

@bjorn3
Copy link
Member

bjorn3 commented Aug 17, 2020

Libstd is always compiled without debug assertions. The optimization level of your program doesn't matter. You are always using the same compiled libstd.

@Mark-Simulacrum Mark-Simulacrum added the relnotes Marks issues that should be documented in the release notes of the next release. label Sep 3, 2020
@jyn514 jyn514 added the A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows label Sep 15, 2020
netbsd-srcmastr pushed a commit to NetBSD/pkgsrc that referenced this pull request Nov 13, 2020
Pkgsrc changes:
 * Remove patches now integrated upstream, many related to SunOS / Illumos.
 * The LLVM fix for powerpc is also now integrated upstream.
 * Adapt those patches where the source has moved or parts are integrated.
 * The randomness patches no longer applies, and I could not find
   where those files went...
 * Provide a separate bootstrap for NetBSD/powerpc 9.0, since apparently
   the C++ ABI is different from 8.0.  Yes, this appears to be specific to
   the NetBSD powerpc ports.

Upstream changes:

Version 1.47.0 (2020-10-08)
==========================

Language
--------
- [Closures will now warn when not used.][74869]

Compiler
--------
- [Stabilized the `-C control-flow-guard` codegen option][73893], which enables
  [Control Flow Guard][1.47.0-cfg] for Windows platforms, and is ignored on
  other platforms.
- [Upgraded to LLVM 11.][73526]
- [Added tier 3\* support for the `thumbv4t-none-eabi` target.][74419]
- [Upgrade the FreeBSD toolchain to version 11.4][75204]
- [`RUST_BACKTRACE`'s output is now more compact.][75048]

\* Refer to Rust's [platform support page][forge-platform-support] for more
information on Rust's tiered platform support.

Libraries
---------
- [`CStr` now implements `Index<RangeFrom<usize>>`.][74021]
- [Traits in `std`/`core` are now implemented for arrays of any length, not just
  those of length less than 33.][74060]
- [`ops::RangeFull` and `ops::Range` now implement Default.][73197]
- [`panic::Location` now implements `Copy`, `Clone`, `Eq`, `Hash`, `Ord`,
  `PartialEq`, and `PartialOrd`.][73583]

Stabilized APIs
---------------
- [`Ident::new_raw`]
- [`Range::is_empty`]
- [`RangeInclusive::is_empty`]
- [`Result::as_deref`]
- [`Result::as_deref_mut`]
- [`Vec::leak`]
- [`pointer::offset_from`]
- [`f32::TAU`]
- [`f64::TAU`]

The following previously stable APIs have now been made const.

- [The `new` method for all `NonZero` integers.][73858]
- [The `checked_add`,`checked_sub`,`checked_mul`,`checked_neg`, `checked_shl`,
  `checked_shr`, `saturating_add`, `saturating_sub`, and `saturating_mul`
  methods for all integers.][73858]
- [The `checked_abs`, `saturating_abs`, `saturating_neg`, and `signum`  for all
  signed integers.][73858]
- [The `is_ascii_alphabetic`, `is_ascii_uppercase`, `is_ascii_lowercase`,
  `is_ascii_alphanumeric`, `is_ascii_digit`, `is_ascii_hexdigit`,
  `is_ascii_punctuation`, `is_ascii_graphic`, `is_ascii_whitespace`, and
  `is_ascii_control` methods for `char` and `u8`.][73858]

Cargo
-----
- [`build-dependencies` are now built with opt-level 0 by default.][cargo/8500]
  You can override this by setting the following in your `Cargo.toml`.
  ```toml
  [profile.release.build-override]
  opt-level = 3
  ```
- [`cargo-help` will now display man pages for commands rather just the
  `--help` text.][cargo/8456]
- [`cargo-metadata` now emits a `test` field indicating if a target has
  tests enabled.][cargo/8478]
- [`workspace.default-members` now respects `workspace.exclude`.][cargo/8485]
- [`cargo-publish` will now use an alternative registry by default if it's the
  only registry specified in `package.publish`.][cargo/8571]

Misc
----
- [Added a help button beside Rustdoc's searchbar that explains rustdoc's
  type based search.][75366]
- [Added the Ayu theme to rustdoc.][71237]

Compatibility Notes
-------------------
- [Bumped the minimum supported Emscripten version to 1.39.20.][75716]
- [Fixed a regression parsing `{} && false` in tail expressions.][74650]
- [Added changes to how proc-macros are expanded in `macro_rules!` that should
  help to preserve more span information.][73084] These changes may cause
  compiliation errors if your macro was unhygenic or didn't correctly handle
  `Delimiter::None`.
- [Moved support for the CloudABI target to tier 3.][75568]
- [`linux-gnu` targets now require minimum kernel 2.6.32 and glibc 2.11.][74163]

Internal Only
--------
- [Improved default settings for bootstrapping in `x.py`.][73964]
  You can read details about this change in the ["Changes to `x.py`
  defaults"](https://blog.rust-lang.org/inside-rust/2020/08/30/changes-to-x-py-defaults.html)
  post on the Inside Rust blog.

- [Added the `rustc-docs` component.][75560] This allows you to install
  and read the documentation for the compiler internal APIs. (Currently only
  available for `x86_64-unknown-linux-gnu`.)

[1.47.0-cfg]: https://docs.microsoft.com/en-us/windows/win32/secbp/control-flow-guard
[76980]: rust-lang/rust#76980
[75048]: rust-lang/rust#75048
[74163]: rust-lang/rust#74163
[71237]: rust-lang/rust#71237
[74869]: rust-lang/rust#74869
[73858]: rust-lang/rust#73858
[75716]: rust-lang/rust#75716
[75908]: rust-lang/rust#75908
[75516]: rust-lang/rust#75516
[75560]: rust-lang/rust#75560
[75568]: rust-lang/rust#75568
[75366]: rust-lang/rust#75366
[75204]: rust-lang/rust#75204
[74650]: rust-lang/rust#74650
[74419]: rust-lang/rust#74419
[73964]: rust-lang/rust#73964
[74021]: rust-lang/rust#74021
[74060]: rust-lang/rust#74060
[73893]: rust-lang/rust#73893
[73526]: rust-lang/rust#73526
[73583]: rust-lang/rust#73583
[73084]: rust-lang/rust#73084
[73197]: rust-lang/rust#73197
[72488]: rust-lang/rust#72488
[cargo/8456]: rust-lang/cargo#8456
[cargo/8478]: rust-lang/cargo#8478
[cargo/8485]: rust-lang/cargo#8485
[cargo/8500]: rust-lang/cargo#8500
[cargo/8571]: rust-lang/cargo#8571
[`Ident::new_raw`]:  https://doc.rust-lang.org/nightly/proc_macro/struct.Ident.html#method.new_raw
[`Range::is_empty`]: https://doc.rust-lang.org/nightly/std/ops/struct.Range.html#method.is_empty
[`RangeInclusive::is_empty`]: https://doc.rust-lang.org/nightly/std/ops/struct.RangeInclusive.html#method.is_empty
[`Result::as_deref_mut`]: https://doc.rust-lang.org/nightly/std/result/enum.Result.html#method.as_deref_mut
[`Result::as_deref`]: https://doc.rust-lang.org/nightly/std/result/enum.Result.html#method.as_deref
[`TypeId::of`]: https://doc.rust-lang.org/nightly/std/any/struct.TypeId.html#method.of
[`Vec::leak`]: https://doc.rust-lang.org/nightly/std/vec/struct.Vec.html#method.leak
[`f32::TAU`]: https://doc.rust-lang.org/nightly/std/f32/consts/constant.TAU.html
[`f64::TAU`]: https://doc.rust-lang.org/nightly/std/f64/consts/constant.TAU.html
[`pointer::offset_from`]: https://doc.rust-lang.org/nightly/std/primitive.pointer.html#method.offset_from
wesleywiser added a commit to wesleywiser/rust that referenced this pull request Jul 29, 2021
On `x86_64-pc-windows-msvc`, we often get backtraces which look like
this:

```
10:     0x7ff77e0e9be5 - std::panicking::rust_panic_with_hook
11:     0x7ff77e0e11b4 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c
12:     0x7ff77e0e116f - std::sys_common::backtrace::__rust_end_short_backtrace::h61c7ecb1b55338ae
13:     0x7ff77e0f89dd - std::panicking::begin_panic::h8e60ef9f82a41805
14:     0x7ff77e0e108c - d
15:     0x7ff77e0e1069 - c
16:     0x7ff77e0e1059 - b
17:     0x7ff77e0e1049 - a
18:     0x7ff77e0e1039 - core::ptr::drop_in_place<std::rt::lang_start<()>::{{closure}}>::h1bfcd14d5e15ba81
19:     0x7ff77e0e1186 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c
20:     0x7ff77e0e100c - std::rt::lang_start::{{closure}}::ha054184bbf9921e3
```

Notice that `__rust_begin_short_backtrace` appears on frame 11 before
`__rust_end_short_backtrace` on frame 12. This is because in typical
release binaries without debug symbols, dbghelp.dll, which we use to walk
and symbolize the stack, does not know where CGU internal functions
start or end and so the closure invoked by `__rust_end_short_backtrace`
is incorrectly described as `__rust_begin_short_backtrace` because it
happens to be near that symbol.

While that can obviously change, this has been happening quite
consistently since rust-lang#75048. Since this is a very small change to the std
and the change makes sense by itself, I think this is worth doing.

This doesn't completely resolve the situation for release binaries on
Windows, since without debug symbols, the stack printed can still show
incorrect symbol names (this is why the test uses `#[no_mangle]`) but it
does slightly improve the situation in that you see the same backtrace
you would see with `RUST_BACKTRACE=full` or in a debugger (without the
uninteresting bits at the top and bottom).
JohnTitor added a commit to JohnTitor/rust that referenced this pull request Jul 30, 2021
…ktraces_windows_optimized, r=dtolnay

[backtraces]: look for the `begin` symbol only after seeing `end`

On `x86_64-pc-windows-msvc`, we often get backtraces which look like
    this:

    ```
    10:     0x7ff77e0e9be5 - std::panicking::rust_panic_with_hook
    11:     0x7ff77e0e11b4 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c
    12:     0x7ff77e0e116f - std::sys_common::backtrace::__rust_end_short_backtrace::h61c7ecb1b55338ae
    13:     0x7ff77e0f89dd - std::panicking::begin_panic::h8e60ef9f82a41805
    14:     0x7ff77e0e108c - d
    15:     0x7ff77e0e1069 - c
    16:     0x7ff77e0e1059 - b
    17:     0x7ff77e0e1049 - a
    18:     0x7ff77e0e1039 - core::ptr::drop_in_place<std::rt::lang_start<()>::{{closure}}>::h1bfcd14d5e15ba81
    19:     0x7ff77e0e1186 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c
    20:     0x7ff77e0e100c - std::rt::lang_start::{{closure}}::ha054184bbf9921e3
    ```

Notice that `__rust_begin_short_backtrace` appears on frame 11 before
    `__rust_end_short_backtrace` on frame 12. This is because in typical
    release binaries without debug symbols, dbghelp.dll, which we use to walk
    and symbolize the stack, does not know where CGU internal functions
    start or end and so the closure invoked by `__rust_end_short_backtrace`
    is incorrectly described as `__rust_begin_short_backtrace` because it
    happens to be near that symbol.

While that can obviously change, this has been happening quite
    consistently since rust-lang#75048. Since this is a very small change to the std
    and the change makes sense by itself, I think this is worth doing.

This doesn't completely resolve the situation for release binaries on
    Windows, since without debug symbols, the stack printed can still show
    incorrect symbol names (this is why the test uses `#[no_mangle]`) but it
    does slightly improve the situation in that you see the same backtrace
    you would see with `RUST_BACKTRACE=full` or in a debugger (without the
    uninteresting bits at the top and bottom).

Fixes part of rust-lang#87481
@cuviper cuviper added this to the 1.47.0 milestone May 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows merged-by-bors This PR was explicitly merged by bors. relnotes Marks issues that should be documented in the release notes of the next release. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Short backtrace have regressed