Cache System Tracing Spans (bevyengine#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,26 +494,16 @@ 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
  // access the world data used by the system.
  // - `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,23 +552,14 @@ 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) {
  // TODO: avoid allocation
  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| {
- #[cfg(feature = "trace")]
- let _condition_span = info_span!("condition", name = &*condition.name()).entered();
- condition.run((), world)
- })
+ .map(|condition| 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| {
- #[cfg(feature = "trace")]
- let _condition_span = info_span!("condition", name = &*condition.name()).entered();
- condition.run((), world)
- })
+ .map(|condition| 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 =
- bevy_utils::tracing::info_span!("system_commands", name = _system_meta.name())
- .entered();
+ let _span_guard = _system_meta.commands_span.enter();
  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 =
- bevy_utils::tracing::info_span!("system_commands", name = _system_meta.name())
- .entered();
+ let _system_span = _system_meta.commands_span.enter();
  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: