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

Fix tracing spans for system #11169

Closed
wants to merge 1 commit into from
Closed

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