From 4837cb4a2837434116ee95201b503b0ee16855f5 Mon Sep 17 00:00:00 2001 From: Carter Anderson Date: Fri, 18 Mar 2022 04:19:21 +0000 Subject: [PATCH] Use more ergonomic span syntax (#4246) Tracing added support for "inline span entering", which cuts down on a lot of complexity: ```rust let span = info_span!("my_span").entered(); ``` This adapts our code to use this pattern where possible, and updates our docs to recommend it. This produces equivalent tracing behavior. Here is a side by side profile of "before" and "after" these changes. ![image](https://user-images.githubusercontent.com/2694663/158912137-b0aa6dc8-c603-425f-880f-6ccf5ad1b7ef.png) --- crates/bevy_app/src/app.rs | 8 +--- crates/bevy_ecs/src/schedule/executor.rs | 5 +-- .../src/schedule/executor_parallel.rs | 8 +--- crates/bevy_ecs/src/schedule/mod.rs | 4 +- crates/bevy_ecs/src/schedule/stage.rs | 33 +++++++-------- crates/bevy_render/src/lib.rs | 41 ++++++++----------- .../bevy_render/src/renderer/graph_runner.rs | 17 +++----- crates/bevy_render/src/renderer/mod.rs | 3 +- docs/profiling.md | 9 ++++ 9 files changed, 53 insertions(+), 75 deletions(-) diff --git a/crates/bevy_app/src/app.rs b/crates/bevy_app/src/app.rs index bc26b97419100f..7316ae119326f9 100644 --- a/crates/bevy_app/src/app.rs +++ b/crates/bevy_app/src/app.rs @@ -109,9 +109,7 @@ impl App { /// See [`Schedule::run_once`] for more details. pub fn update(&mut self) { #[cfg(feature = "trace")] - let bevy_frame_update_span = info_span!("frame"); - #[cfg(feature = "trace")] - let _bevy_frame_update_guard = bevy_frame_update_span.enter(); + let _bevy_frame_update_span = info_span!("frame").entered(); self.schedule.run(&mut self.world); for sub_app in self.sub_apps.values_mut() { (sub_app.runner)(&mut self.world, &mut sub_app.app); @@ -124,9 +122,7 @@ impl App { /// level documentation. pub fn run(&mut self) { #[cfg(feature = "trace")] - let bevy_app_run_span = info_span!("bevy_app"); - #[cfg(feature = "trace")] - let _bevy_app_run_guard = bevy_app_run_span.enter(); + let _bevy_app_run_span = info_span!("bevy_app").entered(); let mut app = std::mem::replace(self, App::empty()); let runner = std::mem::replace(&mut app.runner, Box::new(run_once)); diff --git a/crates/bevy_ecs/src/schedule/executor.rs b/crates/bevy_ecs/src/schedule/executor.rs index ae746717c25e9f..e5cc61960a1715 100644 --- a/crates/bevy_ecs/src/schedule/executor.rs +++ b/crates/bevy_ecs/src/schedule/executor.rs @@ -31,9 +31,8 @@ impl ParallelSystemExecutor for SingleThreadedExecutor { for system in systems { if system.should_run() { #[cfg(feature = "trace")] - let system_span = bevy_utils::tracing::info_span!("system", name = &*system.name()); - #[cfg(feature = "trace")] - let _system_guard = system_span.enter(); + let _system_span = + bevy_utils::tracing::info_span!("system", name = &*system.name()).entered(); system.system_mut().run((), world); } } diff --git a/crates/bevy_ecs/src/schedule/executor_parallel.rs b/crates/bevy_ecs/src/schedule/executor_parallel.rs index f94db72ac55ac5..b2ab15c7a528c9 100644 --- a/crates/bevy_ecs/src/schedule/executor_parallel.rs +++ b/crates/bevy_ecs/src/schedule/executor_parallel.rs @@ -158,9 +158,7 @@ impl ParallelExecutor { /// `update_archetypes` and updates cached `archetype_component_access`. fn update_archetypes(&mut self, systems: &mut [ParallelSystemContainer], world: &World) { #[cfg(feature = "trace")] - let span = bevy_utils::tracing::info_span!("update_archetypes"); - #[cfg(feature = "trace")] - let _guard = span.enter(); + let _span = bevy_utils::tracing::info_span!("update_archetypes").entered(); let archetypes = world.archetypes(); let new_generation = archetypes.generation(); let old_generation = std::mem::replace(&mut self.archetype_generation, new_generation); @@ -186,9 +184,7 @@ impl ParallelExecutor { world: &'scope World, ) { #[cfg(feature = "trace")] - let span = bevy_utils::tracing::info_span!("prepare_systems"); - #[cfg(feature = "trace")] - let _guard = span.enter(); + let _span = bevy_utils::tracing::info_span!("prepare_systems").entered(); self.should_run.clear(); for (index, (system_data, system)) in self.system_metadata.iter_mut().zip(systems).enumerate() diff --git a/crates/bevy_ecs/src/schedule/mod.rs b/crates/bevy_ecs/src/schedule/mod.rs index 192dd00cb8a4db..dc228f4265de3e 100644 --- a/crates/bevy_ecs/src/schedule/mod.rs +++ b/crates/bevy_ecs/src/schedule/mod.rs @@ -336,9 +336,7 @@ impl Schedule { pub fn run_once(&mut self, world: &mut World) { for label in &self.stage_order { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = ?label); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = bevy_utils::tracing::info_span!("stage", name = ?label).entered(); let stage = self.stages.get_mut(label).unwrap(); stage.run(world); } diff --git a/crates/bevy_ecs/src/schedule/stage.rs b/crates/bevy_ecs/src/schedule/stage.rs index 0ec7312ff19f75..8901d24cdf8854 100644 --- a/crates/bevy_ecs/src/schedule/stage.rs +++ b/crates/bevy_ecs/src/schedule/stage.rs @@ -212,9 +212,8 @@ impl SystemStage { for container in &mut self.parallel { let system = container.system_mut(); #[cfg(feature = "trace")] - let span = bevy_utils::tracing::info_span!("system_commands", name = &*system.name()); - #[cfg(feature = "trace")] - let _guard = span.enter(); + let _span = bevy_utils::tracing::info_span!("system_commands", name = &*system.name()) + .entered(); system.apply_buffers(world); } } @@ -836,12 +835,11 @@ impl Stage for SystemStage { for container in &mut self.exclusive_at_start { if should_run(container, &self.run_criteria, default_should_run) { #[cfg(feature = "trace")] - let system_span = bevy_utils::tracing::info_span!( + let _system_span = bevy_utils::tracing::info_span!( "exclusive_system", name = &*container.name() - ); - #[cfg(feature = "trace")] - let _guard = system_span.enter(); + ) + .entered(); container.system_mut().run(world); } } @@ -858,12 +856,11 @@ impl Stage for SystemStage { for container in &mut self.exclusive_before_commands { if should_run(container, &self.run_criteria, default_should_run) { #[cfg(feature = "trace")] - let system_span = bevy_utils::tracing::info_span!( + let _system_span = bevy_utils::tracing::info_span!( "exclusive_system", name = &*container.name() - ); - #[cfg(feature = "trace")] - let _guard = system_span.enter(); + ) + .entered(); container.system_mut().run(world); } } @@ -873,12 +870,11 @@ impl Stage for SystemStage { for container in &mut self.parallel { if container.should_run { #[cfg(feature = "trace")] - let span = bevy_utils::tracing::info_span!( + let _span = bevy_utils::tracing::info_span!( "system_commands", name = &*container.name() - ); - #[cfg(feature = "trace")] - let _guard = span.enter(); + ) + .entered(); container.system_mut().apply_buffers(world); } } @@ -888,12 +884,11 @@ impl Stage for SystemStage { for container in &mut self.exclusive_at_end { if should_run(container, &self.run_criteria, default_should_run) { #[cfg(feature = "trace")] - let system_span = bevy_utils::tracing::info_span!( + let _system_span = bevy_utils::tracing::info_span!( "exclusive_system", name = &*container.name() - ); - #[cfg(feature = "trace")] - let _guard = system_span.enter(); + ) + .entered(); container.system_mut().run(world); } } diff --git a/crates/bevy_render/src/lib.rs b/crates/bevy_render/src/lib.rs index 5133fdc9a198c5..7cdd8de6810d4d 100644 --- a/crates/bevy_render/src/lib.rs +++ b/crates/bevy_render/src/lib.rs @@ -177,15 +177,12 @@ impl Plugin for RenderPlugin { app.add_sub_app(RenderApp, render_app, move |app_world, render_app| { #[cfg(feature = "trace")] - let render_span = bevy_utils::tracing::info_span!("renderer subapp"); - #[cfg(feature = "trace")] - let _render_guard = render_span.enter(); + let _render_span = bevy_utils::tracing::info_span!("renderer subapp").entered(); { #[cfg(feature = "trace")] - let stage_span = - bevy_utils::tracing::info_span!("stage", name = "reserve_and_flush"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "reserve_and_flush") + .entered(); // reserve all existing app entities for use in render_app // they can only be spawned using `get_or_spawn()` @@ -203,9 +200,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "extract"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "extract").entered(); // extract extract(app_world, render_app); @@ -213,9 +209,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "prepare"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "prepare").entered(); // prepare let prepare = render_app @@ -227,9 +222,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "queue"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "queue").entered(); // queue let queue = render_app @@ -241,9 +235,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "sort"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "sort").entered(); // phase sort let phase_sort = render_app @@ -255,9 +248,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "render"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "render").entered(); // render let render = render_app @@ -269,9 +261,8 @@ impl Plugin for RenderPlugin { { #[cfg(feature = "trace")] - let stage_span = bevy_utils::tracing::info_span!("stage", name = "cleanup"); - #[cfg(feature = "trace")] - let _stage_guard = stage_span.enter(); + let _stage_span = + bevy_utils::tracing::info_span!("stage", name = "cleanup").entered(); // cleanup let cleanup = render_app diff --git a/crates/bevy_render/src/renderer/graph_runner.rs b/crates/bevy_render/src/renderer/graph_runner.rs index 5df63dd3ad88cd..413642bc3c07ff 100644 --- a/crates/bevy_render/src/renderer/graph_runner.rs +++ b/crates/bevy_render/src/renderer/graph_runner.rs @@ -60,9 +60,7 @@ impl RenderGraphRunner { Self::run_graph(graph, None, &mut render_context, world, &[])?; { #[cfg(feature = "trace")] - let span = info_span!("submit_graph_commands"); - #[cfg(feature = "trace")] - let _guard = span.enter(); + let _span = info_span!("submit_graph_commands").entered(); queue.submit(vec![render_context.command_encoder.finish()]); } Ok(()) @@ -170,15 +168,12 @@ impl RenderGraphRunner { smallvec![None; node_state.output_slots.len()]; { let mut context = RenderGraphContext::new(graph, node_state, &inputs, &mut outputs); - #[cfg(feature = "trace")] - let span = info_span!("node", name = node_state.type_name); - #[cfg(feature = "trace")] - let guard = span.enter(); - - node_state.node.run(&mut context, render_context, world)?; + { + #[cfg(feature = "trace")] + let _span = info_span!("node", name = node_state.type_name).entered(); - #[cfg(feature = "trace")] - drop(guard); + node_state.node.run(&mut context, render_context, world)?; + } for run_sub_graph in context.finish() { let sub_graph = graph diff --git a/crates/bevy_render/src/renderer/mod.rs b/crates/bevy_render/src/renderer/mod.rs index 2789ef51c8194d..9589ed6e83ac48 100644 --- a/crates/bevy_render/src/renderer/mod.rs +++ b/crates/bevy_render/src/renderer/mod.rs @@ -45,8 +45,7 @@ pub fn render_system(world: &mut World) { } { - let span = info_span!("present_frames"); - let _guard = span.enter(); + let _span = info_span!("present_frames").entered(); // Remove ViewTarget components to ensure swap chain TextureViews are dropped. // If all TextureViews aren't dropped before present, acquiring the next swap chain texture will fail. diff --git a/docs/profiling.md b/docs/profiling.md index cef50326d6b744..7894cb7b1f953e 100644 --- a/docs/profiling.md +++ b/docs/profiling.md @@ -17,11 +17,20 @@ After running your app a `json` file in the "chrome tracing format" will be prod Add spans to your app like this (these are in `bevy::prelude::*` and `bevy::log::*`, just like the normal logging macros). ```rust +{ + // creates a span and starts the timer + let my_span = info_span!("span_name", name = "span_name").entered(); + do_something_here(); +} // my_span is dropped here ... this stops the timer + +// You can also "manually" enter the span if you need more control over when the timer starts +// Prefer the previous, simpler syntax unless you need the extra control. let my_span = info_span!("span_name", name = "span_name"); { // starts the span's timer let guard = my_span.enter(); + do_something_here(); } // guard is dropped here ... this stops the timer ```