Rust-Based Stack Traces Corrupt When Tracy Enabled

[cwfitzgerald]

A real doozy of an issue here. I honestly don't know if this is a rust_tracy_client problem, a backtrace-rs problem, or a tracy problem, I'm starting here as a first line of action.

Clone this repository: https://github.com/cwfitzgerald/tracy-client-stacktrace-issue on a machine running Windows.

---

cargo run returns a stacktrace like normal. This is basically just a program which instantly panics.

Normal Stacktrace

thread 'main' panicked at src\main.rs:5:5:
Hello, world!
stack backtrace:
   0:     0x7ff7e03f65ba - std::backtrace_rs::backtrace::dbghelp64::trace
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\..\..\backtrace\src\backtrace\dbghelp64.rs:99
   1:     0x7ff7e03f65ba - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff7e03f65ba - std::sys_common::backtrace::_print_fmt
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\sys_common\backtrace.rs:68
   3:     0x7ff7e03f65ba - std::sys_common::backtrace::_print::impl$0::fmt
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\sys_common\backtrace.rs:44
   4:     0x7ff7e04048ab - core::fmt::rt::Argument::fmt
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\core\src\fmt\rt.rs:142
   5:     0x7ff7e04048ab - core::fmt::write
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\core\src\fmt\mod.rs:1153
   6:     0x7ff7e03f4a81 - std::io::Write::write_fmt<std::sys::pal::windows::stdio::Stderr>
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\io\mod.rs:1843
   7:     0x7ff7e03f63a6 - std::sys_common::backtrace::print
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\sys_common\backtrace.rs:34
   8:     0x7ff7e03f83df - std::panicking::default_hook::closure$1
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\panicking.rs:272
   9:     0x7ff7e03f8077 - std::panicking::default_hook
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\panicking.rs:292
  10:     0x7ff7e03f891d - std::panicking::rust_panic_with_hook
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\panicking.rs:779
  11:     0x7ff7e03f879b - std::panicking::begin_panic_handler::closure$0
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\panicking.rs:649
  12:     0x7ff7e03f6c49 - std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::closure_env$0,never$>
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\sys_common\backtrace.rs:171
  13:     0x7ff7e03f8496 - std::panicking::begin_panic_handler
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\panicking.rs:645
  14:     0x7ff7e04097f7 - core::panicking::panic_fmt
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\core\src\panicking.rs:72
  15:     0x7ff7e03f12ff - tracy_client_stacktrace::main
                               at F:\Programming\tracy-client-stacktrace\src\main.rs:5
  16:     0x7ff7e03f119b - core::ops::function::FnOnce::call_once<void (*)(),tuple$<> >
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6\library\core\src\ops\function.rs:250
  17:     0x7ff7e03f136e - core::hint::black_box
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6\library\core\src\hint.rs:337
  18:     0x7ff7e03f136e - std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6\library\std\src\sys_common\backtrace.rs:155
  19:     0x7ff7e03f1291 - std::rt::lang_start::closure$0<tuple$<> >
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6\library\std\src\rt.rs:166
  20:     0x7ff7e03f2f42 - std::rt::lang_start_internal
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library\std\src\rt.rs:148
  21:     0x7ff7e03f126a - std::rt::lang_start<tuple$<> >
                               at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6\library\std\src\rt.rs:165
  22:     0x7ff7e03f1319 - main
  23:     0x7ff7e0407ff0 - invoke_main
                               at D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  24:     0x7ff7e0407ff0 - __scrt_common_main_seh
                               at D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  25:     0x7ff8dc9a257d - BaseThreadInitThunk
  26:     0x7ff8dd5caa48 - RtlUserThreadStart
error: process didn't exit successfully: `target\debug\tracy-client-stacktrace.exe` (exit code: 101)

---

cargo run --features enable now turns on tracy_client, then panics. Pulls a completely nonsensical stacktrace.

Nonsense

thread 'main' panicked at src\main.rs:5:5:
Hello, world!
stack backtrace:
   0:     0x7ff615a8703a - <unknown>
   1:     0x7ff615a9532b - <unknown>
   2:     0x7ff615a85501 - <unknown>
   3:     0x7ff615a86e26 - <unknown>
   4:     0x7ff615a88e5f - <unknown>
   5:     0x7ff615a88af7 - <unknown>
   6:     0x7ff615a8939d - <unknown>
   7:     0x7ff615a8921b - <unknown>
   8:     0x7ff615a876c9 - <unknown>
   9:     0x7ff615a88f16 - <unknown>
  10:     0x7ff615abfd67 - <unknown>
  11:     0x7ff615a812e4 - <unknown>
  12:     0x7ff615a811ab - <unknown>
  13:     0x7ff615a8110e - <unknown>
  14:     0x7ff615a81371 - <unknown>
  15:     0x7ff615a839c2 - <unknown>
  16:     0x7ff615a8134a - <unknown>
  17:     0x7ff615a81309 - <unknown>
  18:     0x7ff615abddac - <unknown>
  19:     0x7ff8dc9a257d - BaseThreadInitThunk
  20:     0x7ff8dd5caa48 - RtlUserThreadStar

---

If I run this in the visual studio debugger with Break on All C++ exceptions enabled, visual studio gives a sane backtrace, so the stack itself seems correct.

VS Backtrace

 	KernelBase.dll!RaiseException�()	Unknown
>	vcruntime140.dll!_CxxThrowException(void * pExceptionObject, const _s__ThrowInfo * pThrowInfo) Line 75	C++
 	[Inline Frame] tracy-client-stacktrace.exe!panic_unwind::real_imp::panic() Line 323	Unknown
 	tracy-client-stacktrace.exe!panic_unwind::__rust_start_panic() Line 106	Unknown
 	tracy-client-stacktrace.exe!std::panicking::rust_panic() Line 831	Unknown
 	tracy-client-stacktrace.exe!std::panicking::rust_panic_with_hook() Line 801	Unknown
 	tracy-client-stacktrace.exe!std::panicking::begin_panic_handler::closure$0() Line 658	Unknown
 	tracy-client-stacktrace.exe!std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::closure_env$0,never$>() Line 171	Unknown
 	tracy-client-stacktrace.exe!std::panicking::begin_panic_handler() Line 645	Unknown
 	tracy-client-stacktrace.exe!core::panicking::panic_fmt() Line 72	Unknown
 	tracy-client-stacktrace.exe!tracy_client_stacktrace::main() Line 5	Unknown
 	tracy-client-stacktrace.exe!core::ops::function::FnOnce::call_once<void (*)(),tuple$<>>(void(*)()) Line 250	Unknown
 	[Inline Frame] tracy-client-stacktrace.exe!core::hint::black_box(tuple$<>) Line 155	Unknown
 	tracy-client-stacktrace.exe!std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<>>(void(*)() f) Line 161	Unknown
 	tracy-client-stacktrace.exe!std::rt::lang_start::closure$0<tuple$<>>(std::rt::lang_start::closure_env$0<tuple$<>> *) Line 166	Unknown
 	tracy-client-stacktrace.exe!std::rt::lang_start_internal() Line 148	Unknown
 	tracy-client-stacktrace.exe!std::rt::lang_start<tuple$<>>(void(*)() main, __int64 argc, unsigned char * * argv, unsigned char sigpipe) Line 165	Unknown
 	tracy-client-stacktrace.exe!main�()	Unknown
 	[Inline Frame] tracy-client-stacktrace.exe!invoke_main() Line 78	C++
 	tracy-client-stacktrace.exe!__scrt_common_main_seh() Line 288	C++
 	kernel32.dll!BaseThreadInitThunk()	Unknown
 	ntdll.dll!RtlUserThreadStart�()	Unknown

This happens with all features disabled, only enable. This example uses manual-lifetime, but this happens without.

[nagisa]

Huh, this is annoying. I imagine what happens is that one of the libbacktraces end up getting precedence and that one that ends up getting called is this one. I wonder if we could avoid including the vendored libbacktrace and instead rely on what libstd gives us...

[cwfitzgerald]

I thought backtrace-rs is now not using libbacktace at all - I was wondering if there was some race when using dbghelp

[farnoy]

Don't mean to derail this issue, but is there a way of solving it that also provides Tracy with rusty backtraces, or would that have to be done upstream? Not only are the panic stack traces emitted by Rust wrong, but Tracy's stack traces (when running the profiled process as admin) on Windows are similarly useless.

[cwfitzgerald]

I have a hunch that this is two sides of the same issue- whatever is happening is happening to both tracy's backtraces and rust backtraces

[nagisa]

I'll be making a release based on just-released tracy 0.11 so it would be worthwhile to test if the new version suffers from the same issue. At the same time I can't help but notice that tracy now has all sorts of additional options for stack trace handling (e.g. to use libunwind.) While those options are currently not exposed in any way from the bindings, it would be another worthwhile test to see if using them helps in any way.

[farnoy]

You're quick! I've tested on 0.17.1 and -sys 0.23.0 with tracy 0.11 and it's all the same as before. Both rust's panic output has the wrong call stacks and so does tracy in the stacks it sampled when entering spans.