Cache System Tracing Spans (#9390)

# Objective

- Reduce the overhead of tracing by caching the system spans.

Yellow is this pr. Red is main.


![image](https://github.com/bevyengine/bevy/assets/2180432/fe9bb7c2-ae9a-4522-80a9-75a943a562b6)

crates/bevy_ecs/src/schedule/executor/multi_threaded.rs

@@ -7,7 +7,7 @@ use bevy_tasks::{ComputeTaskPool, Scope, TaskPool, ThreadExecutor};
 use bevy_utils::default;
 use bevy_utils::syncunsafecell::SyncUnsafeCell;
 #[cfg(feature = "trace")]
-use bevy_utils::tracing::{info_span, Instrument};
+use bevy_utils::tracing::{info_span, Instrument, Span};
 use std::panic::AssertUnwindSafe;
 
 use async_channel::{Receiver, Sender};
@@ -62,6 +62,9 @@ struct SystemTaskMetadata {
     is_send: bool,
     /// Is `true` if the system is exclusive.
     is_exclusive: bool,
+    /// Cached tracing span for system task
+    #[cfg(feature = "trace")]
+    system_task_span: Span,
 }
 
 /// The result of running a system that is sent across a channel.
@@ -153,6 +156,11 @@ impl SystemExecutor for MultiThreadedExecutor {
                 dependents: schedule.system_dependents[index].clone(),
                 is_send: schedule.systems[index].is_send(),
                 is_exclusive: schedule.systems[index].is_exclusive(),
+                #[cfg(feature = "trace")]
+                system_task_span: info_span!(
+                    "system_task",
+                    name = &*schedule.systems[index].name()
+                ),
             });
         }
 
@@ -486,17 +494,9 @@ impl MultiThreadedExecutor {
     ) {
         // SAFETY: this system is not running, no other reference exists
         let system = unsafe { &mut *systems[system_index].get() };
-
-        #[cfg(feature = "trace")]
-        let task_span = info_span!("system_task", name = &*system.name());
-        #[cfg(feature = "trace")]
-        let system_span = info_span!("system", name = &*system.name());
-
         let sender = self.sender.clone();
         let panic_payload = self.panic_payload.clone();
         let task = async move {
-            #[cfg(feature = "trace")]
-            let system_guard = system_span.enter();
             let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                 // SAFETY:
                 // - The caller ensures that we have permission to
@@ -504,8 +504,6 @@ impl MultiThreadedExecutor {
                 // - `update_archetype_component_access` has been called.
                 unsafe { system.run_unsafe((), world) };
             }));
-            #[cfg(feature = "trace")]
-            drop(system_guard);
             // tell the executor that the system finished
             sender
                 .try_send(SystemResult {
@@ -524,7 +522,11 @@ impl MultiThreadedExecutor {
         };
 
         #[cfg(feature = "trace")]
-        let task = task.instrument(task_span);
+        let task = task.instrument(
+            self.system_task_metadata[system_index]
+                .system_task_span
+                .clone(),
+        );
 
         let system_meta = &self.system_task_metadata[system_index];
         self.active_access
@@ -550,11 +552,6 @@ impl MultiThreadedExecutor {
         // SAFETY: this system is not running, no other reference exists
         let system = unsafe { &mut *systems[system_index].get() };
 
-        #[cfg(feature = "trace")]
-        let task_span = info_span!("system_task", name = &*system.name());
-        #[cfg(feature = "trace")]
-        let system_span = info_span!("system", name = &*system.name());
-
         let sender = self.sender.clone();
         let panic_payload = self.panic_payload.clone();
         if is_apply_deferred(system) {
@@ -562,11 +559,7 @@ impl MultiThreadedExecutor {
             let unapplied_systems = self.unapplied_systems.clone();
             self.unapplied_systems.clear();
             let task = async move {
-                #[cfg(feature = "trace")]
-                let system_guard = system_span.enter();
                 let res = apply_deferred(&unapplied_systems, systems, world);
-                #[cfg(feature = "trace")]
-                drop(system_guard);
                 // tell the executor that the system finished
                 sender
                     .try_send(SystemResult {
@@ -582,17 +575,17 @@ impl MultiThreadedExecutor {
             };
 
             #[cfg(feature = "trace")]
-            let task = task.instrument(task_span);
+            let task = task.instrument(
+                self.system_task_metadata[system_index]
+                    .system_task_span
+                    .clone(),
+            );
             scope.spawn_on_scope(task);
         } else {
             let task = async move {
-                #[cfg(feature = "trace")]
-                let system_guard = system_span.enter();
                 let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                     system.run((), world);
                 }));
-                #[cfg(feature = "trace")]
-                drop(system_guard);
                 // tell the executor that the system finished
                 sender
                     .try_send(SystemResult {
@@ -612,7 +605,11 @@ impl MultiThreadedExecutor {
             };
 
             #[cfg(feature = "trace")]
-            let task = task.instrument(task_span);
+            let task = task.instrument(
+                self.system_task_metadata[system_index]
+                    .system_task_span
+                    .clone(),
+            );
             scope.spawn_on_scope(task);
         }
 
@@ -718,8 +715,6 @@ unsafe fn evaluate_and_fold_conditions(
     conditions
         .iter_mut()
         .map(|condition| {
-            #[cfg(feature = "trace")]
-            let _condition_span = info_span!("condition", name = &*condition.name()).entered();
             // SAFETY: The caller ensures that `world` has permission to
             // access any data required by the condition.
             unsafe { condition.run_unsafe((), world) }

crates/bevy_ecs/src/schedule/executor/simple.rs

@@ -77,13 +77,9 @@ impl SystemExecutor for SimpleExecutor {
             }
 
             let system = &mut schedule.systems[system_index];
-            #[cfg(feature = "trace")]
-            let system_span = info_span!("system", name = &*name).entered();
             let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                 system.run((), world);
             }));
-            #[cfg(feature = "trace")]
-            system_span.exit();
             if let Err(payload) = res {
                 eprintln!("Encountered a panic in system `{}`!", &*system.name());
                 std::panic::resume_unwind(payload);
@@ -113,10 +109,6 @@ fn evaluate_and_fold_conditions(conditions: &mut [BoxedCondition], world: &mut W
     #[allow(clippy::unnecessary_fold)]
     conditions
         .iter_mut()
-        .map(|condition| {
+        .map(|condition| condition.run((), world))
-            #[cfg(feature = "trace")]
-            let _condition_span = info_span!("condition", name = &*condition.name()).entered();
-            condition.run((), world)
-        })
         .fold(true, |acc, res| acc && res)
 }

crates/bevy_ecs/src/schedule/executor/single_threaded.rs

@@ -86,19 +86,11 @@ impl SystemExecutor for SingleThreadedExecutor {
 
             let system = &mut schedule.systems[system_index];
             if is_apply_deferred(system) {
-                #[cfg(feature = "trace")]
-                let system_span = info_span!("system", name = &*name).entered();
                 self.apply_deferred(schedule, world);
-                #[cfg(feature = "trace")]
-                system_span.exit();
             } else {
-                #[cfg(feature = "trace")]
-                let system_span = info_span!("system", name = &*name).entered();
                 let res = std::panic::catch_unwind(AssertUnwindSafe(|| {
                     system.run((), world);
                 }));
-                #[cfg(feature = "trace")]
-                system_span.exit();
                 if let Err(payload) = res {
                     eprintln!("Encountered a panic in system `{}`!", &*system.name());
                     std::panic::resume_unwind(payload);
@@ -143,10 +135,6 @@ fn evaluate_and_fold_conditions(conditions: &mut [BoxedCondition], world: &mut W
     #[allow(clippy::unnecessary_fold)]
     conditions
         .iter_mut()
-        .map(|condition| {
+        .map(|condition| condition.run((), world))
-            #[cfg(feature = "trace")]
-            let _condition_span = info_span!("condition", name = &*condition.name()).entered();
-            condition.run((), world)
-        })
         .fold(true, |acc, res| acc && res)
 }

crates/bevy_ecs/src/system/commands/mod.rs

@@ -118,9 +118,7 @@ impl SystemBuffer for CommandQueue {
     #[inline]
     fn apply(&mut self, _system_meta: &SystemMeta, world: &mut World) {
         #[cfg(feature = "trace")]
-        let _system_span =
+        let _span_guard = _system_meta.commands_span.enter();
-            bevy_utils::tracing::info_span!("system_commands", name = _system_meta.name())
-                .entered();
         self.apply(world);
     }
 }

crates/bevy_ecs/src/system/commands/parallel_scope.rs

@@ -52,9 +52,7 @@ impl SystemBuffer for ParallelCommandQueue {
     #[inline]
     fn apply(&mut self, _system_meta: &SystemMeta, world: &mut World) {
         #[cfg(feature = "trace")]
-        let _system_span =
+        let _system_span = _system_meta.commands_span.enter();
-            bevy_utils::tracing::info_span!("system_commands", name = _system_meta.name())
-                .entered();
         for cq in &mut self.thread_local_storage {
             cq.get_mut().apply(world);
         }

crates/bevy_ecs/src/system/exclusive_function_system.rs

@@ -93,6 +93,9 @@ where
     }
 
     fn run(&mut self, input: Self::In, world: &mut World) -> Self::Out {
+        #[cfg(feature = "trace")]
+        let _span_guard = self.system_meta.system_span.enter();
+
         let saved_last_tick = world.last_change_tick;
         world.last_change_tick = self.system_meta.last_run;
 

crates/bevy_ecs/src/system/function_system.rs

@@ -10,6 +10,9 @@ use crate::{
 use bevy_utils::all_tuples;
 use std::{any::TypeId, borrow::Cow, marker::PhantomData};
 
+#[cfg(feature = "trace")]
+use bevy_utils::tracing::{info_span, Span};
+
 use super::{In, IntoSystem, ReadOnlySystem};
 
 /// The metadata of a [`System`].
@@ -22,16 +25,25 @@ pub struct SystemMeta {
     // SystemParams from overriding each other
     is_send: bool,
     pub(crate) last_run: Tick,
+    #[cfg(feature = "trace")]
+    pub(crate) system_span: Span,
+    #[cfg(feature = "trace")]
+    pub(crate) commands_span: Span,
 }
 
 impl SystemMeta {
     pub(crate) fn new<T>() -> Self {
+        let name = std::any::type_name::<T>();
         Self {
-            name: std::any::type_name::<T>().into(),
+            name: name.into(),
             archetype_component_access: Access::default(),
             component_access_set: FilteredAccessSet::default(),
             is_send: true,
             last_run: Tick::new(0),
+            #[cfg(feature = "trace")]
+            system_span: info_span!("system", name = name),
+            #[cfg(feature = "trace")]
+            commands_span: info_span!("system_commands", name = name),
         }
     }
 
@@ -444,6 +456,9 @@ where
 
     #[inline]
     unsafe fn run_unsafe(&mut self, input: Self::In, world: UnsafeWorldCell) -> Self::Out {
+        #[cfg(feature = "trace")]
+        let _span_guard = self.system_meta.system_span.enter();
+
         let change_tick = world.increment_change_tick();
 
         // SAFETY: