Compile-out excessive wgpu log messages statically

[JMS55]

What problem does this solve or what need does it fill?

Wgpu logs a lot of messages at the trace level. While we filter this out at runtime, the filtering alone is very expensive from the traces we've seen.

bevy/crates/bevy_log/src/lib.rs

Line 163 in a47b91c

filter: "wgpu=error,naga=warn".to_string(),

What solution would you like?

Use log's cargo features to filter out the trace logs.

E.g. log = { version = "0.4", features = ["max_level_debug", "release_max_level_warn"] }.

We can make this a bevy-level feature, so that developers wanting to see trace logs or debug logs in release mode could turn this feature off.

What alternative(s) have you considered?

Add a new feature to disable trace logs within the wgpu crate, letting us keep trace logs from our other crates. Wgpu devs are open to this idea gfx-rs/wgpu#5804 (comment).

[mockersf]

previous discussion in #7223

[janhohenheim]

Reading this as someone who was not aware of this before I saw the issue, this is definitely a footgun for users.
If we don't disable tracing calls by default, we should at least mention this. In my opinion, it should be similar to how we recommend dynamic linking. Adding something small to the website like the following would be an improvement until there is a fix on wgpu's side:

Bevy's dependencies do a lot of trace logging that is not relevant for an end user. To improve your runtime, you should add the following to the [dependencies] section of your Cargo.toml. It will disable high log levels on compile time.

log = { version = "0.4", features = ["max_level_debug", "release_max_level_warn"] }

In the meantime, I've added it to Foxtrot and bevy_game_template so that new users of popular templates don't run into this.

[alice-i-cecile]

My preference is for more granular control here: being able to enable / disable logs from each crate separately is valuable. I'm also strongly opposed to disabling this by default: this sort of thing should be part of a "preparing for release" documentation IMO.

[wilk10]

this sort of thing should be part of a "preparing for release" documentation IMO.

I have found this guide very useful and well explained: https://github.com/tbillington/bevy_best_practices?tab=readme-ov-file#release

[janhohenheim]

My preference is for more granular control here: being able to enable / disable logs from each crate separately is valuable. I'm also strongly opposed to disabling this by default: this sort of thing should be part of a "preparing for release" documentation IMO.

While I agree in general, I think it is worth considering that this issue is mainly about trace calls, which should be a bit less controversial to omit by default. The issue and my comment both mention release_max_level_warn, but we could replace that by release_max_level_debug. If we hide this behind a feature, a user would have to do cargo run --no-default-features --features a_whole_bunch_of_bevy_features, which is not ergonomic, but also a very niche (and maybe advanced?) use-case.

Ultimately, I have no strong feelings about what Bevy does or doesn't by default here as long as its well documented. I do think however that it is important that this information is not only part of a release documentation. Such a document would include a lot of things that are not relevant for development like optimizing the binary size or gain performance by taking tradeoffs like longer compile times. As such, I think users will tend to not read that document until they actually want to ship. The addition of log = { version = "0.4", features = ["max_level_debug", "release_max_level_warn"] } speeds up development performance "for free", so it should be something a new user sees early.

Created bevyengine/bevy-website#1510 to track adding this info to the new book.

[TarekAS]

Is there an alternative way to achieve the same thing? Because this fails the lint #![deny(unused_crate_dependencies)], and there's no way to specify exceptions

[TarekAS]

For now, I disabled the unused_crate_dependencies because it doesn't have an allowlist which lets me make an exception to the log package. I'm switched to cargo-machete which has an allowlist.

[janhohenheim]

Note that for Wasm builds, the same features need to be enabled for the tracing crate as Bevy does not use log there.

[Imberflur]

I did some investigation in gfx-rs/wgpu#6046 (comment) and I believe the trace logs could at least be filtered out more efficiently (when the max filter level is below trace) by passing the max level to LogTracer. This allows it set the global value that macros from the log crate short-circuit on before calling out to the installed logger:

--- a/crates/bevy_log/src/lib.rs
+++ b/crates/bevy_log/src/lib.rs
@@ -50,7 +50,7 @@ pub use bevy_utils::{
 pub use tracing_subscriber;

 use bevy_app::{App, Plugin};
-use tracing_log::LogTracer;
+use tracing_log::{AsLog, LogTracer};
 #[cfg(feature = "tracing-chrome")]
 use tracing_subscriber::fmt::{format::DefaultFields, FormattedFields};
 use tracing_subscriber::{
@@ -267,9 +267,11 @@ impl Plugin for LogPlugin {
             finished_subscriber = subscriber.with(android_tracing::AndroidLayer::default());
         }

-        let logger_already_set = LogTracer::init().is_err();
         let subscriber_already_set =
             bevy_utils::tracing::subscriber::set_global_default(finished_subscriber).is_err();
+        // This must be after setting the global tracing subscriber to get the level hint from it.
+        let max_level_filter = bevy_utils::tracing::level_filters::LevelFilter::current().as_log();
+        let logger_already_set = LogTracer::init_with_filter(max_level_filter).is_err();

         match (logger_already_set, subscriber_already_set) {
             (true, true) => error!(

(inspired by the implementation details of https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/util/trait.SubscriberInitExt.html#method.try_init)

I looked at main_opaque_pass_3d in Tracy with the many_cubes example and didn't see much difference, but wgpu recently reduced the amount of logging so it is probably harder to observe differences here. I could also be looking at the wrong span in bevy. I tried disabling the logs at compile time with log's release_max_level_debug and saw a difference of roughly ~3%. FYI this was quick ad-hoc investigation and might not be very accurate and could contain mistakes.