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

nfagerlund · 2022-12-14T20:09:56Z

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.

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.

rparrett · 2022-12-14T20:26:20Z

Is it possible to use something like https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.FilterFn.html to filter the frame_mark event more specifically?

rparrett · 2022-12-14T20:55:08Z

It looks like it is possible:

let fmt_layer =
    fmt_layer.with_filter(tracing_subscriber::filter::FilterFn::new(|meta| {
        !meta.fields().field("tracy.frame_mark").is_some()
    }));

nfagerlund · 2022-12-14T21:28:03Z

Yeah!! I was messing with a FilterFn in the process of figuring out why the existing target filter wasn't doing what I expected. But since I'm not familiar enough with the performance characteristics of Tracing subscribers, I opted to keep the filter type the same.

If there's no noteworthy difference, I'd also be in favor of more surgical targeting.

rparrett · 2022-12-14T21:31:11Z

Definitely worth looking at perf, but I'm not really sure how to approach that.

My instinct is that it wouldn't be a big deal and the default subscriber is doing most of its work just writing to stdout.

alice-i-cecile · 2022-12-14T22:43:18Z

Yeah that matches my intuition. I'm in favor of surgical targeting unless we have hard data that it's too expensive.

nfagerlund · 2022-12-14T23:24:03Z

👍🏼 OK, I'll do that.

This converts the previous Target-based filter to a closure filter that only removes the one problematic event, allowing any other events that might get added to bevy_render::renderer over time.

nfagerlund · 2022-12-15T02:19:34Z

ok, cargo fmt appeased

hymm · 2022-12-17T04:49:29Z

perf seems more or less the same with many foxes

of note is that the console logs get a lot more noisy

2022-12-17T04:32:35.134926Z  INFO bevy_app:winit event_handler:frame:stage{name=CoreStage::PostUpdate}:prepare_systems:system{name="bevy_diagnostic::log_diagnostics_plugin::LogDiagnosticsPlugin::log_diagnostics_system"}: bevy diagnostic: frame_time                      :   18.593681ms (avg 18.265590ms)
2022-12-17T04:32:35.137909Z  INFO bevy_app:winit event_handler:frame:stage{name=CoreStage::PostUpdate}:prepare_systems:system{name="bevy_diagnostic::log_diagnostics_plugin::LogDiagnosticsPlugin::log_diagnostics_system"}: bevy diagnostic: fps                             :   53.862178   (avg 54.940014)
2022-12-17T04:32:35.141398Z  INFO bevy_app:winit event_handler:frame:stage{name=CoreStage::PostUpdate}:prepare_systems:system{name="bevy_diagnostic::log_diagnostics_plugin::LogDiagnosticsPlugin::log_diagnostics_system"}: bevy diagnostic: frame_count                     : 6393.000000

but that's probably better than not getting the messages.

cart · 2022-12-20T23:37:41Z

bors r+

@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.

bors · 2022-12-20T23:56:44Z

Pull request successfully merged into main.

Build succeeded:

@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.

alice-i-cecile added C-Bug An unexpected or incorrect behavior A-Diagnostics Logging, crash handling, error reporting and performance analysis labels Dec 14, 2022

alice-i-cecile self-requested a review December 14, 2022 20:12

Target the one noisy tracy.frame_mark event more precisely

de6a4da

This converts the previous Target-based filter to a closure filter that only removes the one problematic event, allowing any other events that might get added to bevy_render::renderer over time.

nfagerlund force-pushed the nf/dec22-tracy-log-suppression branch from 0dee74f to de6a4da Compare December 15, 2022 02:19

alice-i-cecile approved these changes Dec 15, 2022

View reviewed changes

alice-i-cecile requested review from jakobhellermann, hymm and mockersf December 15, 2022 02:24

alice-i-cecile mentioned this pull request Dec 15, 2022

tracing-tracy suppresses tracing to stdout #6862

Closed

hymm approved these changes Dec 17, 2022

View reviewed changes

mockersf approved these changes Dec 17, 2022

View reviewed changes

mockersf 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 Dec 17, 2022

james7132 added this to the 0.10 milestone Dec 19, 2022

bors bot changed the title ~~Fix suppression of all console logs when trace_tracy is enabled~~ [Merged by Bors] - Fix suppression of all console logs when trace_tracy is enabled Dec 20, 2022

bors bot closed this Dec 20, 2022

nfagerlund deleted the nf/dec22-tracy-log-suppression branch December 21, 2022 00:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

nfagerlund commented Dec 14, 2022 •

edited

Loading

rparrett commented Dec 14, 2022

rparrett commented Dec 14, 2022 •

edited

Loading

nfagerlund commented Dec 14, 2022

rparrett commented Dec 14, 2022 •

edited

Loading

alice-i-cecile commented Dec 14, 2022

nfagerlund commented Dec 14, 2022

nfagerlund commented Dec 15, 2022

hymm commented Dec 17, 2022

cart commented Dec 20, 2022

bors bot commented Dec 20, 2022

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

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

Conversation

nfagerlund commented Dec 14, 2022 • edited Loading

Objective

Solution

Changelog

rparrett commented Dec 14, 2022

rparrett commented Dec 14, 2022 • edited Loading

nfagerlund commented Dec 14, 2022

rparrett commented Dec 14, 2022 • edited Loading

alice-i-cecile commented Dec 14, 2022

nfagerlund commented Dec 14, 2022

nfagerlund commented Dec 15, 2022

hymm commented Dec 17, 2022

cart commented Dec 20, 2022

bors bot commented Dec 20, 2022

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

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

nfagerlund commented Dec 14, 2022 •

edited

Loading

rparrett commented Dec 14, 2022 •

edited

Loading

rparrett commented Dec 14, 2022 •

edited

Loading