Skip to content

Commit

Permalink
Add helper macro's for logging only once (#10808)
Browse files Browse the repository at this point in the history
# Objective

Fixes #10291

This adds a way to easily log messages once within system which are
called every frame.

## Solution

Opted for a macro-based approach. The fact that the 'once' call is
tracked per call site makes the `log_once!()` macro very versatile and
easy-to-use. I suspect it will be very handy for all of us, but
especially beginners, to get some initial feedback from systems without
spamming up the place!

I've made the macro's return its internal `has_fired` state, for
situations in which that might be useful to know (trigger something else
alongside the log, for example).

Please let me know if I placed the macro's in the right location, and if
you would like me to do something more clever with the macro's
themselves, since its looking quite copy-pastey at the moment. I've
tried ways to replace 5 with 1 macro's, but no success yet.

One downside of this approach is: Say you wish to warn the user if a
resource is invalid. In this situation, the
`resource.is_valid()` check would still be performed every frame:
```rust
fn my_system(my_res: Res<MyResource>) {
   if !my_res.is_valid() {
      warn_once!("resource is invalid!");
   }
}
```
If you want to prevent that, you would still need to introduce a local
boolean. I don't think this is a very big deal, as expensive checks
shouldn't be called every frame in any case.


## Changelog
Added: `trace_once!()`, `debug_once!()`, `info_once!()`, `warn_once!()`,
and `error_once!()` log macros which fire only once per call site.
  • Loading branch information
josfeenstra authored Dec 5, 2023
1 parent 2653adf commit 18ac125
Show file tree
Hide file tree
Showing 3 changed files with 94 additions and 0 deletions.
4 changes: 4 additions & 0 deletions crates/bevy_log/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,8 @@
//! For more fine-tuned control over logging behavior, set up the [`LogPlugin`] or
//! `DefaultPlugins` during app initialization.
mod once;

#[cfg(feature = "trace")]
use std::panic;

Expand All @@ -28,6 +30,8 @@ pub mod prelude {
pub use bevy_utils::tracing::{
debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn, warn_span,
};

pub use crate::{debug_once, error_once, info_once, trace_once, warn_once};
}

pub use bevy_utils::tracing::{
Expand Down
62 changes: 62 additions & 0 deletions crates/bevy_log/src/once.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
/// Call some expression only once per call site.
#[macro_export]
macro_rules! once {
($expression:expr) => {{
use ::std::sync::atomic::{AtomicBool, Ordering};

static SHOULD_FIRE: AtomicBool = AtomicBool::new(true);
if SHOULD_FIRE.swap(false, Ordering::Relaxed) {
$expression;
}
}};
}

/// Call [`trace!`](crate::trace) once per call site.
///
/// Useful for logging within systems which are called every frame.
#[macro_export]
macro_rules! trace_once {
($($arg:tt)+) => ({
$crate::once!($crate::trace!($($arg)+))
});
}

/// Call [`debug!`](crate::debug) once per call site.
///
/// Useful for logging within systems which are called every frame.
#[macro_export]
macro_rules! debug_once {
($($arg:tt)+) => ({
$crate::once!($crate::debug!($($arg)+))
});
}

/// Call [`info!`](crate::info) once per call site.
///
/// Useful for logging within systems which are called every frame.
#[macro_export]
macro_rules! info_once {
($($arg:tt)+) => ({
$crate::once!($crate::info!($($arg)+))
});
}

/// Call [`warn!`](crate::warn) once per call site.
///
/// Useful for logging within systems which are called every frame.
#[macro_export]
macro_rules! warn_once {
($($arg:tt)+) => ({
$crate::once!($crate::warn!($($arg)+))
});
}

/// Call [`error!`](crate::error) once per call site.
///
/// Useful for logging within systems which are called every frame.
#[macro_export]
macro_rules! error_once {
($($arg:tt)+) => ({
$crate::once!($crate::error!($($arg)+))
});
}
28 changes: 28 additions & 0 deletions examples/app/logs.rs
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
//! This example illustrates how to use logs in bevy.
use bevy::log::once;
use bevy::prelude::*;

fn main() {
Expand All @@ -11,6 +12,7 @@ fn main() {
..default()
}))
.add_systems(Update, log_system)
.add_systems(Update, log_once_system)
.run();
}

Expand All @@ -30,3 +32,29 @@ fn log_system() {
// the format used here is super flexible. check out this documentation for more info:
// https://docs.rs/tracing-subscriber/*/tracing_subscriber/filter/struct.EnvFilter.html
}

fn log_once_system() {
// The 'once' variants of each log level are useful when a system is called every frame,
// but we still wish to inform the user only once. In other words, use these to prevent spam :)

trace_once!("one time noisy message");
debug_once!("one time debug message");
info_once!("some info which is printed only once");
warn_once!("some warning we wish to call out only once");
error_once!("some error we wish to report only once");

for i in 0..10 {
info_once!("logs once per call site, so this works just fine: {}", i);
}

// you can also use the 'once!' macro directly, in situations you want do do
// something expensive only once within the context of a continous system.
once!({
info!("doing expensive things");
let mut a: u64 = 0;
for i in 0..100000000 {
a += i;
}
info!("result of some expensive one time calculation: {}", a);
});
}

0 comments on commit 18ac125

Please sign in to comment.