[Merged by Bors] - bevy_app: add tracing event with `tracy.frame_mark` #4320

jakobhellermann · 2022-03-24T14:04:38Z

Currently tracy interprets the entire trace as one frame because the marker for frames isn't being recorded.

When an event with tracy.trace_marker=true is recorded, tracing-tracy will mark the frame as finished:
https://github.com/nagisa/rust_tracy_client/blob/aa0b96b2ae2aee6f3831994f9a3a8c29bcc85fae/tracing-tracy/src/lib.rs#L240

~~Unfortunately this leads to~~

INFO bevy_app:frame: bevy_app::app: finished frame tracy.frame_mark=true

~~being printed every frame (we can't use DEBUG because bevy_log sets max_release_level_info.~~

Instead of emitting an event that gets logged every frame, we can depend on tracy-client itself and call finish_continuous_frame!();

mockersf · 2022-03-24T15:06:41Z

Is it a good idea to depend on both tracy_client and tracing_tracy?

From their doc it seems they shouldn't be used both at the same time

superdump

Did you try using a tracing event with the frame marker but at the debug level or so? Does it just get filtered out before it gets sent to Tracy? I think that aspect was maybe why I didn't make a PR.

Perhaps if that is a negative side effect of using the tracing frame marker API, we could make a contribution to tracing-tracy to allow directly calling finish continuous frame for when an event or message or so is undesirable.

crates/bevy_app/src/app.rs

jakobhellermann · 2022-03-24T15:51:22Z

Is it a good idea to depend on both tracy_client and tracing_tracy?

tracing_tracy uses tracy_client will call finish_continous_frame! when an event with tracy.frame_mark is recorded: https://github.com/nagisa/rust_tracy_client/blob/aa0b96b2ae2aee6f3831994f9a3a8c29bcc85fae/tracing-tracy/src/lib.rs#L240
So this PR is doing exactly the same, just without the event.

Did you try using a tracing event with the frame marker but at the debug level or so?

I tried but that didn't work in release mode as bevy_log enabled the max_release_level_info feature on tracing-subscriber.

alice-i-cecile

LGTM once you resolve the correct position of the frame end :)

robtfm · 2022-03-24T20:14:26Z

just to note an alternative to using another import, we could also suppress the info logging for tracy events:

+++ b/crates/bevy_log/src/lib.rs
@@ -159,6 +159,11 @@ impl Plugin for LogPlugin {
             let tracy_layer = tracing_tracy::TracyLayer::new();

             let fmt_layer = tracing_subscriber::fmt::Layer::default();
+            #[cfg(feature = "tracing-tracy")]
+            let fmt_layer = fmt_layer.with_filter(
+                tracing_subscriber::filter::Targets::new().with_target("tracy", Level::ERROR),
+            );
+
             let subscriber = subscriber.with(fmt_layer);

             #[cfg(feature = "tracing-chrome")]

superdump · 2022-03-24T20:19:11Z

@robtfm oh that’s a good find. I guess warnings would be ok

superdump · 2022-03-30T03:46:39Z

@jakobhellermann what do you think of @robtfm ’s suggestion?

This reverts commit 8c9a878.

jakobhellermann · 2022-03-31T15:57:05Z

I switched to @robtfm's suggestion to use the event but exclude it from the fmt_layer and moved the marker to right after the surface is presented and the SurfaceTexture dropped.

mockersf · 2022-04-08T22:50:07Z

bors r+

Currently `tracy` interprets the entire trace as one frame because the marker for frames isn't being recorded. ~~When an event with `tracy.trace_marker=true` is recorded, `tracing-tracy` will mark the frame as finished: <https://github.com/nagisa/rust_tracy_client/blob/aa0b96b2ae2aee6f3831994f9a3a8c29bcc85fae/tracing-tracy/src/lib.rs#L240>~~ ~~Unfortunately this leads to~~ ```rs INFO bevy_app:frame: bevy_app::app: finished frame tracy.frame_mark=true ``` ~~being printed every frame (we can't use DEBUG because bevy_log sets `max_release_level_info`.~~ Instead of emitting an event that gets logged every frame, we can depend on tracy-client itself and call `finish_continuous_frame!();`

bors · 2022-04-08T23:12:24Z

Pull request successfully merged into main.

Build succeeded:

Currently `tracy` interprets the entire trace as one frame because the marker for frames isn't being recorded. ~~When an event with `tracy.trace_marker=true` is recorded, `tracing-tracy` will mark the frame as finished: <https://github.com/nagisa/rust_tracy_client/blob/aa0b96b2ae2aee6f3831994f9a3a8c29bcc85fae/tracing-tracy/src/lib.rs#L240>~~ ~~Unfortunately this leads to~~ ```rs INFO bevy_app:frame: bevy_app::app: finished frame tracy.frame_mark=true ``` ~~being printed every frame (we can't use DEBUG because bevy_log sets `max_release_level_info`.~~ Instead of emitting an event that gets logged every frame, we can depend on tracy-client itself and call `finish_continuous_frame!();`

Bevy was failing to print events from `info!()` and friends to the console if the `trace_tracy` feature was enabled. The problem was this per-layer filter that was added in bevyengine#4320 to suppress a noisy per-frame event (which Tracy requires in order to properly close out a frame): - The problem event's target was `"bevy_render::renderer"`, not `"tracy"`. - So, the filter wasn't specifically targeting the noisy event. - Without a default, `tracing_subscriber::filter::Targets` will remove _everything_ that doesn't match an explicit target rule. - So, the filter _was_ silencing the noisy event, along with everything else. This commit changes that filter to do what was probably intended in bevyengine#4320: suppress any events more verbose than `ERROR` from `bevy_render::renderer`, but allow anything else that already made it through the top-level filter_layer.

@alice-i-cecile

) # Objective Fixes #6862 (oh hey good catch @alice-i-cecile) Bevy was failing to print events from `info!()` and friends to the console if the `trace_tracy` feature was enabled. It shouldn't be doing that. ## Solution The problem was this per-layer filter that was added in #4320 to suppress a noisy per-frame event (which Tracy requires in order to properly close out a frame): - The problem event's target was `"bevy_render::renderer"`, not `"tracy"`. - So, the filter wasn't specifically targeting the noisy event. - Without a default, `tracing_subscriber::filter::Targets` will remove _everything_ that doesn't match an explicit target rule. - So, the filter _was_ silencing the noisy event, along with everything else. This PR changes that filter to do what was probably intended in #4320: suppress ~any events more verbose than `ERROR` from `bevy_render::renderer`~ the one problematically noisy event, but allow anything else that already made it through the top-level filter_layer. Also, adds a comment to clarify the intent of that filter, since it's otherwise a bit opaque and required some research. --- ## Changelog Fixed a bug that hid console log messages when the `trace_tracy` feature was enabled.

@alice-i-cecile

…vyengine#6955) # Objective Fixes bevyengine#6862 (oh hey good catch @alice-i-cecile) Bevy was failing to print events from `info!()` and friends to the console if the `trace_tracy` feature was enabled. It shouldn't be doing that. ## Solution The problem was this per-layer filter that was added in bevyengine#4320 to suppress a noisy per-frame event (which Tracy requires in order to properly close out a frame): - The problem event's target was `"bevy_render::renderer"`, not `"tracy"`. - So, the filter wasn't specifically targeting the noisy event. - Without a default, `tracing_subscriber::filter::Targets` will remove _everything_ that doesn't match an explicit target rule. - So, the filter _was_ silencing the noisy event, along with everything else. This PR changes that filter to do what was probably intended in bevyengine#4320: suppress ~any events more verbose than `ERROR` from `bevy_render::renderer`~ the one problematically noisy event, but allow anything else that already made it through the top-level filter_layer. Also, adds a comment to clarify the intent of that filter, since it's otherwise a bit opaque and required some research. --- ## Changelog Fixed a bug that hid console log messages when the `trace_tracy` feature was enabled.

@alice-i-cecile

…vyengine#6955) # Objective Fixes bevyengine#6862 (oh hey good catch @alice-i-cecile) Bevy was failing to print events from `info!()` and friends to the console if the `trace_tracy` feature was enabled. It shouldn't be doing that. ## Solution The problem was this per-layer filter that was added in bevyengine#4320 to suppress a noisy per-frame event (which Tracy requires in order to properly close out a frame): - The problem event's target was `"bevy_render::renderer"`, not `"tracy"`. - So, the filter wasn't specifically targeting the noisy event. - Without a default, `tracing_subscriber::filter::Targets` will remove _everything_ that doesn't match an explicit target rule. - So, the filter _was_ silencing the noisy event, along with everything else. This PR changes that filter to do what was probably intended in bevyengine#4320: suppress ~any events more verbose than `ERROR` from `bevy_render::renderer`~ the one problematically noisy event, but allow anything else that already made it through the top-level filter_layer. Also, adds a comment to clarify the intent of that filter, since it's otherwise a bit opaque and required some research. --- ## Changelog Fixed a bug that hid console log messages when the `trace_tracy` feature was enabled.

Currently `tracy` interprets the entire trace as one frame because the marker for frames isn't being recorded. ~~When an event with `tracy.trace_marker=true` is recorded, `tracing-tracy` will mark the frame as finished: <https://github.com/nagisa/rust_tracy_client/blob/aa0b96b2ae2aee6f3831994f9a3a8c29bcc85fae/tracing-tracy/src/lib.rs#L240>~~ ~~Unfortunately this leads to~~ ```rs INFO bevy_app:frame: bevy_app::app: finished frame tracy.frame_mark=true ``` ~~being printed every frame (we can't use DEBUG because bevy_log sets `max_release_level_info`.~~ Instead of emitting an event that gets logged every frame, we can depend on tracy-client itself and call `finish_continuous_frame!();`

bevy_app: add tracing event with tracy.frame_mark

9774eaf

github-actions bot added the S-Needs-Triage This issue needs to be labelled label Mar 24, 2022

mockersf approved these changes Mar 24, 2022

View reviewed changes

finish tracy frame directly instead of through tracing-tracy

8c9a878

superdump requested changes Mar 24, 2022

View reviewed changes

crates/bevy_app/src/app.rs Outdated Show resolved Hide resolved

alice-i-cecile added C-Bug An unexpected or incorrect behavior A-Diagnostics Logging, crash handling, error reporting and performance analysis and removed S-Needs-Triage This issue needs to be labelled labels Mar 24, 2022

alice-i-cecile approved these changes Mar 24, 2022

View reviewed changes

mockersf approved these changes Mar 28, 2022

View reviewed changes

alice-i-cecile added the S-Ready-For-Final-Review This PR has been approved by the community. It's ready for a maintainer to consider merging it label Mar 29, 2022

jakobhellermann added 3 commits March 31, 2022 17:47

Revert "finish tracy frame directly instead of through tracing-tracy"

d924457

This reverts commit 8c9a878.

set log level for tracy targets to ERROR

080793e

move frame marker to right after surface is presented

2972e50

superdump approved these changes Apr 8, 2022

View reviewed changes

bors bot changed the title ~~bevy_app: add tracing event with tracy.frame_mark~~ [Merged by Bors] - bevy_app: add tracing event with tracy.frame_mark Apr 8, 2022

bors bot closed this Apr 8, 2022

nfagerlund mentioned this pull request Dec 14, 2022

[Merged by Bors] - Fix suppression of all console logs when trace_tracy is enabled #6955

Closed

LamequeFernandes mentioned this pull request Dec 15, 2022

rename 'w and 's to 'world and 'state #6958

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

[Merged by Bors] - bevy_app: add tracing event with `tracy.frame_mark` #4320

[Merged by Bors] - bevy_app: add tracing event with `tracy.frame_mark` #4320

Uh oh!

jakobhellermann commented Mar 24, 2022 •

edited

Loading

Uh oh!

mockersf commented Mar 24, 2022

Uh oh!

superdump left a comment

Uh oh!

Uh oh!

jakobhellermann commented Mar 24, 2022

Uh oh!

alice-i-cecile left a comment

Uh oh!

robtfm commented Mar 24, 2022

Uh oh!

superdump commented Mar 24, 2022

Uh oh!

superdump commented Mar 30, 2022

Uh oh!

jakobhellermann commented Mar 31, 2022

Uh oh!

mockersf commented Apr 8, 2022

Uh oh!

bors bot commented Apr 8, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Uh oh!

[Merged by Bors] - bevy_app: add tracing event with tracy.frame_mark #4320

[Merged by Bors] - bevy_app: add tracing event with tracy.frame_mark #4320

Uh oh!

Conversation

jakobhellermann commented Mar 24, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mockersf commented Mar 24, 2022

Uh oh!

superdump left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jakobhellermann commented Mar 24, 2022

Uh oh!

alice-i-cecile left a comment

Choose a reason for hiding this comment

Uh oh!

robtfm commented Mar 24, 2022

Uh oh!

superdump commented Mar 24, 2022

Uh oh!

superdump commented Mar 30, 2022

Uh oh!

jakobhellermann commented Mar 31, 2022

Uh oh!

mockersf commented Apr 8, 2022

Uh oh!

bors bot commented Apr 8, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

[Merged by Bors] - bevy_app: add tracing event with `tracy.frame_mark` #4320

[Merged by Bors] - bevy_app: add tracing event with `tracy.frame_mark` #4320

jakobhellermann commented Mar 24, 2022 •

edited

Loading