Simplified backtraces (#12305)

# Objective Remove Bevy internals from backtraces ## Solution Executors insert `__rust_begin_short_backtrace` into the callstack before running a system. <details> <summary>Example current output</summary> ``` thread 'Compute Task Pool (3)' panicked at src/main.rs:7:33: Foo stack backtrace: 0: rust_begin_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:647:5 1: core::panicking::panic_fmt at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panicking.rs:72:14 2: foo::main::{{closure}} at ./src/main.rs:7:33 3: core::ops::function::impls::<impl core::ops::function::FnMut<A> for &mut F>::call_mut at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:294:13 4: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run::call_inner at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:661:21 5: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:664:17 6: <bevy_ecs::system::function_system::FunctionSystem<Marker,F> as bevy_ecs::system::system::System>::run_unsafe at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:504:19 7: bevy_ecs::schedule::executor::multi_threaded::ExecutorState::spawn_system_task::{{closure}}::{{closure}} at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs:621:26 8: core::ops::function::FnOnce::call_once at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:250:5 9: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9 10: std::panicking::try::do_call at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40 11: __rust_try 12: std::panicking::try at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19 13: std::panic::catch_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14 14: bevy_ecs::schedule::executor::multi_threaded::ExecutorState::spawn_system_task::{{closure}} at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs:614:23 15: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::future::future::Future>::poll at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:297:9 16: <futures_lite::future::CatchUnwind<F> as core::future::future::Future>::poll::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:588:42 17: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9 18: std::panicking::try::do_call at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40 19: __rust_try 20: std::panicking::try at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19 21: std::panic::catch_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14 22: <futures_lite::future::CatchUnwind<F> as core::future::future::Future>::poll at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:588:9 23: async_executor::Executor::spawn::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:158:20 24: async_task::raw::RawTask<F,T,S,M>::run::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/raw.rs:550:21 25: core::ops::function::FnOnce::call_once at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:250:5 26: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9 27: std::panicking::try::do_call at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40 28: __rust_try 29: std::panicking::try at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19 30: std::panic::catch_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14 31: async_task::raw::RawTask<F,T,S,M>::run at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/raw.rs:549:23 32: async_task::runnable::Runnable<M>::run at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/runnable.rs:781:18 33: async_executor::Executor::run::{{closure}}::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:254:21 34: <futures_lite::future::Or<F1,F2> as core::future::future::Future>::poll at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:449:33 35: async_executor::Executor::run::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:261:32 36: futures_lite::future::block_on::{{closure}} at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:99:19 37: std:🧵:local::LocalKey<T>::try_with at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:286:16 38: std:🧵:local::LocalKey<T>::with at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:262:9 39: futures_lite::future::block_on at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:78:5 40: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}}::{{closure}}::{{closure}} at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:180:37 41: std::panicking::try::do_call at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40 42: __rust_try 43: std::panicking::try at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19 44: std::panic::catch_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14 45: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}}::{{closure}} at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:174:43 46: std:🧵:local::LocalKey<T>::try_with at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:286:16 47: std:🧵:local::LocalKey<T>::with at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:262:9 48: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}} at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:167:25 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. Encountered a panic in system `foo::main::{{closure}}`! Encountered a panic in system `bevy_app::main_schedule::Main::run_main`! get on your knees and beg mommy for forgiveness you pervert~ 💖 ``` </details> <details> <summary>Example output with this PR</summary> ``` Panic at src/main.rs:7:33: Foo stack backtrace: 0: rust_begin_unwind at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:647:5 1: core::panicking::panic_fmt at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panicking.rs:72:14 2: foo::main::{{closure}} at ./src/main.rs:7:59 3: core::ops::function::impls::<impl core::ops::function::FnMut<A> for &mut F>::call_mut at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:294:13 4: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run::call_inner at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:661:21 5: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:664:17 6: <bevy_ecs::system::function_system::FunctionSystem<Marker,F> as bevy_ecs::system::system::System>::run_unsafe at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:504:19 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. Encountered a panic in system `foo::main::{{closure}}`! Encountered a panic in system `bevy_app::main_schedule::Main::run_main`! ``` </details> Full backtraces (`RUST_BACKTRACE=full`) are unchanged. ## Alternative solutions Write a custom panic hook. This could potentially let use exclude a few more callstack frames but requires a dependency on `backtrace` and is incompatible with user-provided panic hooks. --- ## Changelog - Backtraces now exclude many Bevy internals (unless `RUST_BACKTRACE=full` is used) --------- Co-authored-by: James Liu <contact@jamessliu.com>
2024-11-10 15:14:50 +00:00 · 2024-03-10 13:18:59 +01:00 · 2024-03-10 13:18:59 +01:00 · aea9b4a9e4
commit aea9b4a9e4
parent bc4d8bbb93
5 changed files with 84 additions and 17 deletions
--- a/crates/bevy_ecs/src/schedule/executor/mod.rs
+++ b/crates/bevy_ecs/src/schedule/executor/mod.rs
@ -119,3 +119,54 @@ pub(super) fn is_apply_deferred(system: &BoxedSystem) -> bool {
    // deref to use `System::type_id` instead of `Any::type_id`
    system.as_ref().type_id() == apply_deferred.system_type_id()
 }
+
+/// These functions hide the bottom of the callstack from `RUST_BACKTRACE=1` (assuming the default panic handler is used).
+/// The full callstack will still be visible with `RUST_BACKTRACE=full`.
+/// They are specialized for `System::run` & co instead of being generic over closures because this avoids an
+/// extra frame in the backtrace.
+///
+/// This is reliant on undocumented behavior in Rust's default panic handler, which checks the call stack for symbols
+/// containing the string `__rust_begin_short_backtrace` in their mangled name.
+mod __rust_begin_short_backtrace {
+    use std::hint::black_box;
+
+    use crate::{
+        system::{ReadOnlySystem, System},
+        world::{unsafe_world_cell::UnsafeWorldCell, World},
+    };
+
+    /// # Safety
+    /// See `System::run_unsafe`.
+    #[inline(never)]
+    pub(super) unsafe fn run_unsafe(
+        system: &mut dyn System<In = (), Out = ()>,
+        world: UnsafeWorldCell,
+    ) {
+        system.run_unsafe((), world);
+        black_box(());
+    }
+
+    /// # Safety
+    /// See `ReadOnlySystem::run_unsafe`.
+    #[inline(never)]
+    pub(super) unsafe fn readonly_run_unsafe<O: 'static>(
+        system: &mut dyn ReadOnlySystem<In = (), Out = O>,
+        world: UnsafeWorldCell,
+    ) -> O {
+        black_box(system.run_unsafe((), world))
+    }
+
+    #[inline(never)]
+    pub(super) fn run(system: &mut dyn System<In = (), Out = ()>, world: &mut World) {
+        system.run((), world);
+        black_box(());
+    }
+
+    #[inline(never)]
+    pub(super) fn readonly_run<O: 'static>(
+        system: &mut dyn ReadOnlySystem<In = (), Out = O>,
+        world: &mut World,
+    ) -> O {
+        black_box(system.run((), world))
+    }
+}
--- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs
+++ b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs
@ -24,6 +24,8 @@ use crate::{

 use crate as bevy_ecs;

+use super::__rust_begin_short_backtrace;
+
 /// Borrowed data used by the [`MultiThreadedExecutor`].
 struct Environment<'env, 'sys> {
    executor: &'env MultiThreadedExecutor,
@ -618,7 +620,12 @@ impl ExecutorState {
                // - The caller ensures that we have permission to
                // access the world data used by the system.
                // - `update_archetype_component_access` has been called.
-                unsafe { system.run_unsafe((), context.environment.world_cell) };
+                unsafe {
+                    __rust_begin_short_backtrace::run_unsafe(
+                        &mut **system,
+                        context.environment.world_cell,
+                    );
+                };
            }));
            context.system_completed(system_index, res, system);
        };
@ -668,7 +675,7 @@ impl ExecutorState {
                let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                    #[cfg(feature = "trace")]
                    let _span = system_span.enter();
-                    system.run((), world);
+                    __rust_begin_short_backtrace::run(&mut **system, world);
                }));
                context.system_completed(system_index, res, system);
            };
@ -780,7 +787,7 @@ unsafe fn evaluate_and_fold_conditions(
        .map(|condition| {
            // SAFETY: The caller ensures that `world` has permission to
            // access any data required by the condition.
-            unsafe { condition.run_unsafe((), world) }
+            unsafe { __rust_begin_short_backtrace::readonly_run_unsafe(&mut **condition, world) }
        })
        .fold(true, |acc, res| acc && res)
 }
--- a/crates/bevy_ecs/src/schedule/executor/simple.rs
+++ b/crates/bevy_ecs/src/schedule/executor/simple.rs
@ -10,6 +10,8 @@ use crate::{
    world::World,
 };

+use super::__rust_begin_short_backtrace;
+
 /// A variant of [`SingleThreadedExecutor`](crate::schedule::SingleThreadedExecutor) that calls
 /// [`apply_deferred`](crate::system::System::apply_deferred) immediately after running each system.
 #[derive(Default)]
@ -93,7 +95,7 @@ impl SystemExecutor for SimpleExecutor {
            }

            let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
-                system.run((), world);
+                __rust_begin_short_backtrace::run(&mut **system, world);
            }));
            if let Err(payload) = res {
                eprintln!("Encountered a panic in system `{}`!", &*system.name());
@ -126,7 +128,7 @@ fn evaluate_and_fold_conditions(conditions: &mut [BoxedCondition], world: &mut W
    #[allow(clippy::unnecessary_fold)]
    conditions
        .iter_mut()
-        .map(|condition| condition.run((), world))
+        .map(|condition| __rust_begin_short_backtrace::readonly_run(&mut **condition, world))
        .fold(true, |acc, res| acc && res)
 }

--- a/crates/bevy_ecs/src/schedule/executor/single_threaded.rs
+++ b/crates/bevy_ecs/src/schedule/executor/single_threaded.rs
@ -8,6 +8,8 @@ use crate::{
    world::World,
 };

+use super::__rust_begin_short_backtrace;
+
 /// Runs the schedule using a single thread.
 ///
 /// Useful if you're dealing with a single-threaded environment, saving your threads for
@ -101,14 +103,14 @@ impl SystemExecutor for SingleThreadedExecutor {

            let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                if system.is_exclusive() {
-                    system.run((), world);
+                    __rust_begin_short_backtrace::run(&mut **system, world);
                } else {
                    // Use run_unsafe to avoid immediately applying deferred buffers
                    let world = world.as_unsafe_world_cell();
                    system.update_archetype_component_access(world);
                    // SAFETY: We have exclusive, single-threaded access to the world and
                    // update_archetype_component_access is being called immediately before this.
-                    unsafe { system.run_unsafe((), world) };
+                    unsafe { __rust_begin_short_backtrace::run_unsafe(&mut **system, world) };
                }
            }));
            if let Err(payload) = res {
@ -158,6 +160,6 @@ fn evaluate_and_fold_conditions(conditions: &mut [BoxedCondition], world: &mut W
    #[allow(clippy::unnecessary_fold)]
    conditions
        .iter_mut()
-        .map(|condition| condition.run((), world))
+        .map(|condition| __rust_begin_short_backtrace::readonly_run(&mut **condition, world))
        .fold(true, |acc, res| acc && res)
 }
--- a/crates/bevy_render/src/pipelined_rendering.rs
+++ b/crates/bevy_render/src/pipelined_rendering.rs
@ -1,6 +1,6 @@
 use async_channel::{Receiver, Sender};

-use bevy_app::{App, AppLabel, Main, Plugin, SubApp};
+use bevy_app::{App, AppExit, AppLabel, Main, Plugin, SubApp};
 use bevy_ecs::{
    schedule::MainThreadExecutor,
    system::Resource,
@ -45,10 +45,11 @@ impl RenderAppChannels {
    }

    /// Receive the `render_app` from the rendering thread.
-    pub async fn recv(&mut self) -> SubApp {
-        let render_app = self.render_to_app_receiver.recv().await.unwrap();
+    /// Return `None` if the render thread has panicked.
+    pub async fn recv(&mut self) -> Option<SubApp> {
+        let render_app = self.render_to_app_receiver.recv().await.ok()?;
        self.render_app_in_render_thread = false;
-        render_app
+        Some(render_app)
    }
 }

@ -180,16 +181,20 @@ fn update_rendering(app_world: &mut World, _sub_app: &mut App) {
        world.resource_scope(|world, mut render_channels: Mut<RenderAppChannels>| {
            // we use a scope here to run any main thread tasks that the render world still needs to run
            // while we wait for the render world to be received.
-            let mut render_app = ComputeTaskPool::get()
+            if let Some(mut render_app) = ComputeTaskPool::get()
                .scope_with_executor(true, Some(&*main_thread_executor.0), |s| {
                    s.spawn(async { render_channels.recv().await });
                })
                .pop()
-                .unwrap();
+                .unwrap()
+            {
+                render_app.extract(world);

-            render_app.extract(world);
-
-            render_channels.send_blocking(render_app);
+                render_channels.send_blocking(render_app);
+            } else {
+                // Renderer thread panicked
+                world.send_event(AppExit);
+            }
        });
    });
 }