Skip to content

Commit

Permalink
Add tracing spans to schedules, stages, systems (#789)
Browse files Browse the repository at this point in the history
Add tracing spans to schedules, stages, systems
  • Loading branch information
superdump authored Nov 11, 2020
1 parent b3e1048 commit a266578
Show file tree
Hide file tree
Showing 8 changed files with 111 additions and 1 deletion.
8 changes: 8 additions & 0 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,7 @@ bevy_wgpu = ["bevy_internal/bevy_wgpu"]
bevy_winit = ["bevy_internal/bevy_winit"]

profiler = ["bevy_internal/profiler"]
trace = ["bevy_internal/trace"]
wgpu_trace = ["bevy_internal/wgpu_trace"]

# Image format support for texture loading (PNG and HDR are enabled by default)
Expand Down Expand Up @@ -77,6 +78,9 @@ log = "0.4"
rand = "0.7.3"
ron = "0.6"
serde = {version = "1", features = ["derive"]}
tracing = "0.1.21"
tracing-chrome = "0.2.0"
tracing-subscriber = "0.2.15"

# bevy (Android)
[target.'cfg(target_os = "android")'.dependencies]
Expand Down Expand Up @@ -167,6 +171,10 @@ path = "examples/app/return_after_run.rs"
name = "thread_pool_resources"
path = "examples/app/thread_pool_resources.rs"

[[example]]
name = "tracing"
path = "examples/app/tracing.rs"

[[example]]
name = "hot_asset_reloading"
path = "examples/asset/hot_asset_reloading.rs"
Expand Down
4 changes: 4 additions & 0 deletions crates/bevy_app/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,9 @@ repository = "https://github.com/bevyengine/bevy"
license = "MIT"
keywords = ["bevy"]

[features]
trace = [ "tracing" ]

[dependencies]
# bevy
bevy_derive = { path = "../bevy_derive", version = "0.3.0" }
Expand All @@ -21,6 +24,7 @@ bevy_utils = { path = "../bevy_utils", version = "0.3.0" }
# other
log = { version = "0.4", features = ["release_max_level_info"] }
serde = { version = "1.0", features = ["derive"] }
tracing = { version = "0.1.21", optional = true }

[target.'cfg(target_arch = "wasm32")'.dependencies]
wasm-bindgen = { version = "0.2" }
Expand Down
12 changes: 12 additions & 0 deletions crates/bevy_app/src/app.rs
Original file line number Diff line number Diff line change
@@ -1,5 +1,7 @@
use crate::app_builder::AppBuilder;
use bevy_ecs::{ParallelExecutor, Resources, Schedule, World};
#[cfg(feature = "trace")]
use tracing::info_span;

#[allow(clippy::needless_doctest_main)]
/// Containers of app logic and data
Expand Down Expand Up @@ -65,6 +67,10 @@ impl App {
}

pub fn initialize(&mut self) {
#[cfg(feature = "trace")]
let startup_schedule_span = info_span!("startup_schedule");
#[cfg(feature = "trace")]
let _startup_schedule_guard = startup_schedule_span.enter();
self.startup_schedule
.initialize(&mut self.world, &mut self.resources);
self.startup_executor.initialize(&mut self.resources);
Expand All @@ -76,7 +82,13 @@ impl App {
}

pub fn run(mut self) {
#[cfg(feature = "trace")]
let bevy_app_run_span = info_span!("bevy_app_run");
#[cfg(feature = "trace")]
let _bevy_app_run_guard = bevy_app_run_span.enter();

self.executor.initialize(&mut self.resources);

let runner = std::mem::replace(&mut self.runner, Box::new(run_once));
(runner)(self);
}
Expand Down
2 changes: 2 additions & 0 deletions crates/bevy_ecs/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ categories = ["game-engines", "data-structures"]

[features]
profiler = []
trace = [ "tracing" ]

[dependencies]
bevy_hecs = { path = "hecs", features = ["macros", "serialize"], version = "0.3.0" }
Expand All @@ -26,3 +27,4 @@ fixedbitset = "0.3.1"
downcast-rs = "1.2.0"
parking_lot = "0.11.0"
log = { version = "0.4", features = ["release_max_level_info"] }
tracing = { version = "0.1.21", optional = true }
35 changes: 34 additions & 1 deletion crates/bevy_ecs/src/schedule/parallel_executor.rs
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@ use bevy_hecs::{ArchetypesGeneration, TypeAccess, World};
use bevy_tasks::{ComputeTaskPool, CountdownEvent, TaskPool};
use fixedbitset::FixedBitSet;
use std::ops::Range;
#[cfg(feature = "trace")]
use tracing::info_span;

/// Executes each schedule stage in parallel by analyzing system dependencies.
/// System execution order is undefined except under the following conditions:
Expand Down Expand Up @@ -48,6 +50,11 @@ impl ParallelExecutor {
}

pub fn run(&mut self, schedule: &mut Schedule, world: &mut World, resources: &mut Resources) {
#[cfg(feature = "trace")]
let schedule_span = info_span!("schedule");
#[cfg(feature = "trace")]
let _schedule_guard = schedule_span.enter();

let schedule_generation = schedule.generation();
let schedule_changed = schedule.generation() != self.last_schedule_generation;
if schedule_changed {
Expand All @@ -57,6 +64,10 @@ impl ParallelExecutor {
}
for (stage_name, executor_stage) in schedule.stage_order.iter().zip(self.stages.iter_mut())
{
#[cfg(feature = "trace")]
let stage_span = info_span!("stage", name = stage_name.as_ref());
#[cfg(feature = "trace")]
let _stage_guard = stage_span.enter();
log::trace!("run stage {:?}", stage_name);
if let Some(stage_systems) = schedule.stages.get_mut(stage_name) {
executor_stage.run(world, resources, stage_systems, schedule_changed);
Expand Down Expand Up @@ -392,6 +403,11 @@ impl ExecutorStage {
// Execute the system - in a scope to ensure the system lock is dropped before
// triggering dependents
{
#[cfg(feature = "trace")]
let system_span = info_span!("system", name = system.name().as_ref());
#[cfg(feature = "trace")]
let _system_guard = system_span.enter();

log::trace!("run {}", system.name());
#[cfg(feature = "profiler")]
crate::profiler_start(resources, system.name().clone());
Expand Down Expand Up @@ -442,6 +458,11 @@ impl ExecutorStage {

for (system_index, system) in systems.iter().enumerate() {
if system.thread_local_execution() == ThreadLocalExecution::Immediate {
#[cfg(feature = "trace")]
let system_span = info_span!("system", name = system.name().as_ref());
#[cfg(feature = "trace")]
let _system_guard = system_span.enter();

self.thread_local_system_indices.push(system_index);
}
}
Expand Down Expand Up @@ -483,6 +504,12 @@ impl ExecutorStage {
{
// if a thread local system is ready to run, run it exclusively on the main thread
let system = systems[thread_local_system_index].as_mut();

#[cfg(feature = "trace")]
let system_span = info_span!("system", name = system.name().as_ref());
#[cfg(feature = "trace")]
let _system_guard = system_span.enter();

log::trace!("running thread local system {}", system.name());
system.run(world, resources);
system.run_thread_local(world, resources);
Expand Down Expand Up @@ -513,7 +540,13 @@ impl ExecutorStage {
// "flush"
for system in systems.iter_mut() {
match system.thread_local_execution() {
ThreadLocalExecution::NextFlush => system.run_thread_local(world, resources),
ThreadLocalExecution::NextFlush => {
#[cfg(feature = "trace")]
let system_span = info_span!("system", name = system.name().as_ref());
#[cfg(feature = "trace")]
let _system_guard = system_span.enter();
system.run_thread_local(world, resources);
}
ThreadLocalExecution::Immediate => { /* already ran */ }
}
}
Expand Down
1 change: 1 addition & 0 deletions crates/bevy_internal/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ categories = ["game-engines", "graphics", "gui", "rendering"]
[features]
profiler = ["bevy_ecs/profiler", "bevy_diagnostic/profiler"]
wgpu_trace = ["bevy_wgpu/trace"]
trace = [ "bevy_app/trace", "bevy_ecs/trace" ]

# Image format support for texture loading (PNG and HDR are enabled by default)
hdr = ["bevy_render/hdr"]
Expand Down
1 change: 1 addition & 0 deletions examples/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,7 @@ Example | File | Description
`headless` | [`app/headless.rs`](./app/headless.rs) | An application that runs without default plugins
`plugin` | [`app/plugin.rs`](./app/plugin.rs) | Demonstrates the creation and registration of a custom plugin
`thread_pool_resources` | [`app/thread_pool_resources.rs`](./app/thread_pool_resources.rs) | Creates and customizes the internal thread pool
`tracing` | [`app/tracing.rs`](./app/tracing.rs) | Demonstrates `trace` feature output. Run with `RUST_LOG=info cargo run --example tracing --features trace` and then open the `trace-1234.json` file (where 1234 is a time since the beginning of the epoch) in `chrome://tracing` in Chrome.

## Assets

Expand Down
49 changes: 49 additions & 0 deletions examples/app/tracing.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
use bevy::{input::system::exit_on_esc_system, prelude::*};
use std::{thread, time};
use tracing::info;
use tracing_chrome::ChromeLayerBuilder;
use tracing_subscriber::{fmt, prelude::*, registry::Registry, EnvFilter};

pub fn setup_global_subscriber() -> impl Drop {
let fmt_layer = fmt::Layer::default();
let filter_layer = EnvFilter::try_from_default_env()
.or_else(|_| EnvFilter::try_new("info,wgpu=warn"))
.unwrap();

let (chrome_layer, _guard) = ChromeLayerBuilder::new().build();

let subscriber = Registry::default()
.with(filter_layer)
.with(fmt_layer)
.with(chrome_layer);

tracing::subscriber::set_global_default(subscriber).expect("Could not set global default");
_guard
}

fn main() {
let _guard = setup_global_subscriber();

App::build()
.add_plugins(DefaultPlugins)
.add_startup_system(a_system.system())
.add_system(foo_bar_baz.system())
.add_system(exit_on_esc_system.system())
.run();
}

fn a_system(commands: &mut Commands) {
let ten_millis = time::Duration::from_millis(10);
thread::sleep(ten_millis);

commands.spawn((GlobalTransform::default(), Transform::default()));
}

fn foo_bar_baz(query: Query<&Transform>) {
for transform in query.iter() {
let five_millis = time::Duration::from_millis(5);
thread::sleep(five_millis);

info!(?transform);
}
}

0 comments on commit a266578

Please sign in to comment.