Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add tracing spans to schedules, stages, systems #789

Merged
merged 3 commits into from
Nov 11, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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);
}
}