From 32ac77d8c6b6ab812f1256c4d1df704484a210b2 Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Tue, 8 Aug 2023 16:35:56 -0700 Subject: [PATCH 1/7] cache system spans --- .../src/schedule/executor/multi_threaded.rs | 29 +++++++++++++++---- 1 file changed, 24 insertions(+), 5 deletions(-) diff --git a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs index 8f6a3133c5966..d586410154e8a 100644 --- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs +++ b/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}; @@ -112,6 +112,12 @@ pub struct MultiThreadedExecutor { panic_payload: Arc>>>, /// When set, stops the executor from running any more systems. stop_spawning: bool, + /// Cached tracing spans for system tasks + #[cfg(feature = "trace")] + system_task_spans: Vec, + /// Cached tracing spans for systems + #[cfg(feature = "trace")] + system_spans: Vec, } impl Default for MultiThreadedExecutor { @@ -147,6 +153,11 @@ impl SystemExecutor for MultiThreadedExecutor { self.unapplied_systems = FixedBitSet::with_capacity(sys_count); self.system_task_metadata = Vec::with_capacity(sys_count); + #[cfg(feature = "trace")] + { + self.system_task_spans = Vec::with_capacity(sys_count); + self.system_spans = Vec::with_capacity(sys_count); + } for index in 0..sys_count { self.system_task_metadata.push(SystemTaskMetadata { archetype_component_access: default(), @@ -154,6 +165,12 @@ impl SystemExecutor for MultiThreadedExecutor { is_send: schedule.systems[index].is_send(), is_exclusive: schedule.systems[index].is_exclusive(), }); + + #[cfg(feature = "trace")] + { + self.system_task_spans.push(info_span!("system_task", name = &*schedule.systems[index].name())); + self.system_spans.push(info_span!("system", name = &*schedule.systems[index].name())); + } } self.num_dependencies_remaining = Vec::with_capacity(sys_count); @@ -282,6 +299,10 @@ impl MultiThreadedExecutor { apply_final_deferred: true, panic_payload: Arc::new(Mutex::new(None)), stop_spawning: false, + #[cfg(feature = "trace")] + system_task_spans: Vec::new(), + #[cfg(feature = "trace")] + system_spans: Vec::new(), } } @@ -488,9 +509,7 @@ impl MultiThreadedExecutor { 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 system_span = self.system_spans[system_index].clone(); let sender = self.sender.clone(); let panic_payload = self.panic_payload.clone(); @@ -524,7 +543,7 @@ impl MultiThreadedExecutor { }; #[cfg(feature = "trace")] - let task = task.instrument(task_span); + let task = task.instrument(self.system_task_spans[system_index].clone()); let system_meta = &self.system_task_metadata[system_index]; self.active_access From cabaece383b18dd3a5ed5f10fdee62d609c4f2ee Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Wed, 9 Aug 2023 14:33:36 -0700 Subject: [PATCH 2/7] move spans to task meta data struct --- .../src/schedule/executor/multi_threaded.rs | 41 ++++++++----------- 1 file changed, 18 insertions(+), 23 deletions(-) diff --git a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs index d586410154e8a..7140a30c2683f 100644 --- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs +++ b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs @@ -62,6 +62,12 @@ 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, + /// Cached tracing span for system + #[cfg(feature = "trace")] + system_span: Span, } /// The result of running a system that is sent across a channel. @@ -112,12 +118,6 @@ pub struct MultiThreadedExecutor { panic_payload: Arc>>>, /// When set, stops the executor from running any more systems. stop_spawning: bool, - /// Cached tracing spans for system tasks - #[cfg(feature = "trace")] - system_task_spans: Vec, - /// Cached tracing spans for systems - #[cfg(feature = "trace")] - system_spans: Vec, } impl Default for MultiThreadedExecutor { @@ -153,24 +153,23 @@ impl SystemExecutor for MultiThreadedExecutor { self.unapplied_systems = FixedBitSet::with_capacity(sys_count); self.system_task_metadata = Vec::with_capacity(sys_count); - #[cfg(feature = "trace")] - { - self.system_task_spans = Vec::with_capacity(sys_count); - self.system_spans = Vec::with_capacity(sys_count); - } for index in 0..sys_count { self.system_task_metadata.push(SystemTaskMetadata { archetype_component_access: default(), 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() + ), + #[cfg(feature = "trace")] + system_span: info_span!( + "system", + name = &*schedule.systems[index].name() + ), }); - - #[cfg(feature = "trace")] - { - self.system_task_spans.push(info_span!("system_task", name = &*schedule.systems[index].name())); - self.system_spans.push(info_span!("system", name = &*schedule.systems[index].name())); - } } self.num_dependencies_remaining = Vec::with_capacity(sys_count); @@ -299,10 +298,6 @@ impl MultiThreadedExecutor { apply_final_deferred: true, panic_payload: Arc::new(Mutex::new(None)), stop_spawning: false, - #[cfg(feature = "trace")] - system_task_spans: Vec::new(), - #[cfg(feature = "trace")] - system_spans: Vec::new(), } } @@ -509,7 +504,7 @@ impl MultiThreadedExecutor { let system = unsafe { &mut *systems[system_index].get() }; #[cfg(feature = "trace")] - let system_span = self.system_spans[system_index].clone(); + let system_span = self.system_task_metadata[system_index].system_span.clone(); let sender = self.sender.clone(); let panic_payload = self.panic_payload.clone(); @@ -543,7 +538,7 @@ impl MultiThreadedExecutor { }; #[cfg(feature = "trace")] - let task = task.instrument(self.system_task_spans[system_index].clone()); + 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 From 987b987bbc6539dee8de3f2b8ee73a00449f8262 Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Wed, 9 Aug 2023 15:03:34 -0700 Subject: [PATCH 3/7] cache spans for commands --- crates/bevy_ecs/src/system/commands/mod.rs | 4 +--- crates/bevy_ecs/src/system/commands/parallel_scope.rs | 4 +--- crates/bevy_ecs/src/system/function_system.rs | 10 +++++++++- 3 files changed, 11 insertions(+), 7 deletions(-) diff --git a/crates/bevy_ecs/src/system/commands/mod.rs b/crates/bevy_ecs/src/system/commands/mod.rs index fac21c7c0ffc2..61b4377216f1c 100644 --- a/crates/bevy_ecs/src/system/commands/mod.rs +++ b/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); } } diff --git a/crates/bevy_ecs/src/system/commands/parallel_scope.rs b/crates/bevy_ecs/src/system/commands/parallel_scope.rs index 65b01a8f2156d..6296f0293393c 100644 --- a/crates/bevy_ecs/src/system/commands/parallel_scope.rs +++ b/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); } diff --git a/crates/bevy_ecs/src/system/function_system.rs b/crates/bevy_ecs/src/system/function_system.rs index e245f93716d78..51157adfd0dfe 100644 --- a/crates/bevy_ecs/src/system/function_system.rs +++ b/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,21 @@ pub struct SystemMeta { // SystemParams from overriding each other is_send: bool, pub(crate) last_run: Tick, + #[cfg(feature = "trace")] + pub(crate) commands_span: Span, } impl SystemMeta { pub(crate) fn new() -> Self { + let name = std::any::type_name::(); Self { - name: std::any::type_name::().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")] + commands_span: info_span!("system_commands", name = &*name), } } From c6fdcb92cb7256cd9982fddb7ba04cf997890bc9 Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Wed, 9 Aug 2023 18:36:52 -0700 Subject: [PATCH 4/7] cargo fmt --- .../bevy_ecs/src/schedule/executor/multi_threaded.rs | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs index 7140a30c2683f..d15c926790846 100644 --- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs +++ b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs @@ -165,10 +165,7 @@ impl SystemExecutor for MultiThreadedExecutor { name = &*schedule.systems[index].name() ), #[cfg(feature = "trace")] - system_span: info_span!( - "system", - name = &*schedule.systems[index].name() - ), + system_span: info_span!("system", name = &*schedule.systems[index].name()), }); } @@ -538,7 +535,11 @@ impl MultiThreadedExecutor { }; #[cfg(feature = "trace")] - let task = task.instrument(self.system_task_metadata[system_index].system_task_span.clone()); + 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 From 2859b4dafb63c4db621c0f48501e06e78c134e01 Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Wed, 9 Aug 2023 19:49:38 -0700 Subject: [PATCH 5/7] clippy --- crates/bevy_ecs/src/system/function_system.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/bevy_ecs/src/system/function_system.rs b/crates/bevy_ecs/src/system/function_system.rs index 51157adfd0dfe..f5b366533ec13 100644 --- a/crates/bevy_ecs/src/system/function_system.rs +++ b/crates/bevy_ecs/src/system/function_system.rs @@ -39,7 +39,7 @@ impl SystemMeta { is_send: true, last_run: Tick::new(0), #[cfg(feature = "trace")] - commands_span: info_span!("system_commands", name = &*name), + commands_span: info_span!("system_commands", name = name), } } From 5abf79e39ef2320874054b749f78dd6fb609596b Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Thu, 10 Aug 2023 22:29:12 -0700 Subject: [PATCH 6/7] use cached spans for exclusive systems --- .../src/schedule/executor/multi_threaded.rs | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs index d15c926790846..d6204dfd84697 100644 --- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs +++ b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs @@ -566,9 +566,7 @@ impl MultiThreadedExecutor { 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 system_span = self.system_task_metadata[system_index].system_span.clone(); let sender = self.sender.clone(); let panic_payload = self.panic_payload.clone(); @@ -597,7 +595,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); } else { let task = async move { @@ -627,7 +629,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); } From 79484d84df29045617d053e2cc875b3fd49cac1b Mon Sep 17 00:00:00 2001 From: Mike Hsu Date: Tue, 15 Aug 2023 12:48:14 -0700 Subject: [PATCH 7/7] move span into system run --- .../src/schedule/executor/multi_threaded.rs | 26 ------------------- .../bevy_ecs/src/schedule/executor/simple.rs | 10 +------ .../src/schedule/executor/single_threaded.rs | 14 +--------- .../src/system/exclusive_function_system.rs | 3 +++ crates/bevy_ecs/src/system/function_system.rs | 7 +++++ 5 files changed, 12 insertions(+), 48 deletions(-) diff --git a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs index d6204dfd84697..dad3fa4459d20 100644 --- a/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs +++ b/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs @@ -65,9 +65,6 @@ struct SystemTaskMetadata { /// Cached tracing span for system task #[cfg(feature = "trace")] system_task_span: Span, - /// Cached tracing span for system - #[cfg(feature = "trace")] - system_span: Span, } /// The result of running a system that is sent across a channel. @@ -164,8 +161,6 @@ impl SystemExecutor for MultiThreadedExecutor { "system_task", name = &*schedule.systems[index].name() ), - #[cfg(feature = "trace")] - system_span: info_span!("system", name = &*schedule.systems[index].name()), }); } @@ -499,15 +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 system_span = self.system_task_metadata[system_index].system_span.clone(); - 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 @@ -515,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 { @@ -565,9 +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 system_span = self.system_task_metadata[system_index].system_span.clone(); - let sender = self.sender.clone(); let panic_payload = self.panic_payload.clone(); if is_apply_deferred(system) { @@ -575,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 { @@ -603,13 +583,9 @@ impl MultiThreadedExecutor { 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 { @@ -739,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) } diff --git a/crates/bevy_ecs/src/schedule/executor/simple.rs b/crates/bevy_ecs/src/schedule/executor/simple.rs index e256064ff7879..c34a88c57a42c 100644 --- a/crates/bevy_ecs/src/schedule/executor/simple.rs +++ b/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) } diff --git a/crates/bevy_ecs/src/schedule/executor/single_threaded.rs b/crates/bevy_ecs/src/schedule/executor/single_threaded.rs index ab950c0e5c451..dd6c4e6a41c54 100644 --- a/crates/bevy_ecs/src/schedule/executor/single_threaded.rs +++ b/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) } diff --git a/crates/bevy_ecs/src/system/exclusive_function_system.rs b/crates/bevy_ecs/src/system/exclusive_function_system.rs index 6d2a31f554201..ef70330173068 100644 --- a/crates/bevy_ecs/src/system/exclusive_function_system.rs +++ b/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; diff --git a/crates/bevy_ecs/src/system/function_system.rs b/crates/bevy_ecs/src/system/function_system.rs index f5b366533ec13..2ef46c971863a 100644 --- a/crates/bevy_ecs/src/system/function_system.rs +++ b/crates/bevy_ecs/src/system/function_system.rs @@ -26,6 +26,8 @@ pub struct SystemMeta { is_send: bool, pub(crate) last_run: Tick, #[cfg(feature = "trace")] + pub(crate) system_span: Span, + #[cfg(feature = "trace")] pub(crate) commands_span: Span, } @@ -39,6 +41,8 @@ impl SystemMeta { 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), } } @@ -452,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: