Skip to content

Fix tracing spans for system#11169

Closed
stepancheg wants to merge 1 commit intobevyengine:mainfrom
stepancheg:span
Closed

Fix tracing spans for system#11169
stepancheg wants to merge 1 commit intobevyengine:mainfrom
stepancheg:span

Conversation

@stepancheg
Copy link
Contributor

@stepancheg stepancheg commented Jan 1, 2024

Objective

Spans are not recorded correctly for system,

Solution

Do not create spans prematurely.

Test

Modify logs example:

diff --git a/examples/app/logs.rs b/examples/app/logs.rs
index 797fd85fc..787f4d381 100644
--- a/examples/app/logs.rs
+++ b/examples/app/logs.rs
@@ -25,6 +25,8 @@ fn log_system() {
     warn!("something bad happened that isn't a failure, but thats worth calling out");
     error!("something failed");

+    panic!("test");
+
     // by default, trace and debug logs are ignored because they are "noisy"
     // you can control what level is logged by setting up the LogPlugin
     // alternatively you can set the log level via the RUST_LOG=LEVEL environment variable

Apply another fix from separate PR #11170.

Run command:

cargo run --example logs --features=trace

Before:

2024-01-01T14:36:02.900476Z  INFO system{name="logs::log_once_system"}: logs: doing expensive things
2024-01-01T14:36:02.900449Z ERROR system{name="logs::log_system"}: logs: something failed
   0: bevy_ecs::system::function_system::system
           with name="logs::log_system"
             at crates/bevy_ecs/src/system/function_system.rs:47

After:

2024-01-01T14:34:32.119761Z ERROR bevy_app:winit event_handler:update:main app:schedule{name=Main}:system{name="bevy_app::main_schedule::Main::run_main"}:schedule{name=Update}:system_task{name="logs::log_system"}:system{name="logs::log_system"}: logs: something failed
2024-01-01T14:34:32.119823Z  INFO bevy_app:winit event_handler:update:main app:schedule{name=Main}:system{name="bevy_app::main_schedule::Main::run_main"}:schedule{name=Update}:system_task{name="logs::log_once_system"}:system{name="logs::log_once_system"}: logs: doing expensive things
   0: bevy_ecs::system::function_system::system
           with name="logs::log_system"
             at crates/bevy_ecs/src/system/function_system.rs:479
   1: bevy_ecs::schedule::executor::multi_threaded::system_task
           with name="logs::log_system"
             at crates/bevy_ecs/src/schedule/executor/multi_threaded.rs:156
   2: bevy_ecs::schedule::schedule::schedule
           with name=Update
             at crates/bevy_ecs/src/schedule/schedule.rs:291
   3: bevy_ecs::system::exclusive_function_system::system
           with name="bevy_app::main_schedule::Main::run_main"
             at crates/bevy_ecs/src/system/exclusive_function_system.rs:110
   4: bevy_ecs::schedule::schedule::schedule
           with name=Main
             at crates/bevy_ecs/src/schedule/schedule.rs:291
   5: bevy_app::app::main app
             at crates/bevy_app/src/app.rs:261
   6: bevy_app::app::update
             at crates/bevy_app/src/app.rs:258
   7: bevy_winit::winit event_handler
             at crates/bevy_winit/src/lib.rs:345
   8: bevy_app::app::bevy_app
             at crates/bevy_app/src/app.rs:299

Changelog

  • Fix tracing spans for system.

@alice-i-cecile alice-i-cecile added C-Bug An unexpected or incorrect behavior A-ECS Entities, components, systems, and events A-Diagnostics Logging, crash handling, error reporting and performance analysis labels Jan 1, 2024
@alice-i-cecile alice-i-cecile added this to the 0.13 milestone Jan 1, 2024
Copy link
Member

@james7132 james7132 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This effectively reverts #9390 and re-opens #4892. This also recollects effectively the same stack trace for every system, so it's generally more noise than it's actually beneficial to users.

With the effort @hymm has spent ensuring we get accurate traces while profiling Bevy apps, I am very much against this change as is.

github-merge-queue bot pushed a commit that referenced this pull request Jan 1, 2024
# Objective

When panic handler prints to stdout instead of stderr, I've observed two
outcomes with this PR test #11169:
- Sometimes output is mixed up, so it is not clear where one record ends
and another stards
- Sometimes output is lost

## Solution

Print to stderr.

## Changelog

- Panic handler in `LogPlugin` writes to stderr instead of stdin.
github-merge-queue bot pushed a commit that referenced this pull request Jan 2, 2024
# Objective

To debug issues like #11169.

## Solution

When P is pressed in logs example, call `panic!()`.

<img width="1392" alt="Screenshot 2024-01-02 at 01 10 16"
src="https://github.com/bevyengine/bevy/assets/28969/a788737e-d23c-43a3-bc68-d6c5b0ab88ad">
@alice-i-cecile alice-i-cecile removed this from the 0.13 milestone Jan 3, 2024
@alice-i-cecile alice-i-cecile added the S-Needs-Benchmarking This set of changes needs performance benchmarking to double-check that they help label Jan 3, 2024
@alice-i-cecile
Copy link
Member

Closing this out then.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

A-Diagnostics Logging, crash handling, error reporting and performance analysis A-ECS Entities, components, systems, and events C-Bug An unexpected or incorrect behavior S-Needs-Benchmarking This set of changes needs performance benchmarking to double-check that they help

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants