Skip to content

Commit

Permalink
Use more ergonomic span syntax (#4246)
Browse files Browse the repository at this point in the history 
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)
  • Loading branch information
@cart
cart committed Mar 18, 2022
1 parent c1a2378 commit de677db
Show file tree
Hide file tree
Showing 9 changed files with 53 additions and 75 deletions.
8 changes: 2 additions & 6 deletions crates/bevy_app/src/app.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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));
Expand Down
5 changes: 2 additions & 3 deletions crates/bevy_ecs/src/schedule/executor.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down
8 changes: 2 additions & 6 deletions crates/bevy_ecs/src/schedule/executor_parallel.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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()
Expand Down
4 changes: 1 addition & 3 deletions crates/bevy_ecs/src/schedule/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down
33 changes: 14 additions & 19 deletions crates/bevy_ecs/src/schedule/stage.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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);
}
}
Expand All @@ -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);
}
}
Expand All @@ -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);
}
}
Expand Down
41 changes: 16 additions & 25 deletions crates/bevy_render/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()`
Expand All @@ -203,19 +200,17 @@ 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);
}

{
#[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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down
17 changes: 6 additions & 11 deletions crates/bevy_render/src/renderer/graph_runner.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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(())
Expand Down Expand Up @@ -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
Expand Down
3 changes: 1 addition & 2 deletions crates/bevy_render/src/renderer/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
9 changes: 9 additions & 0 deletions docs/profiling.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
```

Expand Down

0 comments on commit de677db

Please sign in to comment.