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

Add a helper for logging only once #10291

Closed
alice-i-cecile opened this issue Oct 27, 2023 · 10 comments · Fixed by #10808
Closed

Add a helper for logging only once #10291

alice-i-cecile opened this issue Oct 27, 2023 · 10 comments · Fixed by #10808
Labels
A-Diagnostics Logging, crash handling, error reporting and performance analysis A-ECS Entities, components, systems, and events C-Code-Quality A section of code that is hard to understand or change C-Usability A targeted quality-of-life change that makes Bevy easier to use D-Trivial Nice and easy! A great choice to get started with Bevy

Comments

@alice-i-cecile
Copy link
Member

alice-i-cecile commented Oct 27, 2023

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

We commonly need to log a warning in a system, but don't want to spam the users.

What solution would you like?

Add a system param that stores a local which is flipped once:

#[derive(SystemParam)]
pub struct ActOnce {
    should_check: Local<bool>,
}

impl ActOnce {
   fn check(&mut self, condition: bool) -> bool {
       if self.should_check {
          self.should_check = false;
          condition
       } else {
          false
       }
   }
}
fn example_system(log_switch: ActOnce, my_resource: Res<MyResource>){
   // If this is true, it will set the internal bool to 
   if log_switch.check(res.is_invalid()){
      warn!("Resource is invald!"
   }
}

What alternative(s) have you considered?

We could handle this at the logging level, but this is likely to be over specific and there's no clear place to store the state.

We could handle this at the run condition level, but that delocalizes logic and we may not want to stop the system from running again.

Additional context

Suggested by @JMS55 after reviewing #9873

@alice-i-cecile alice-i-cecile added A-ECS Entities, components, systems, and events C-Code-Quality A section of code that is hard to understand or change C-Usability A targeted quality-of-life change that makes Bevy easier to use A-Diagnostics Logging, crash handling, error reporting and performance analysis labels Oct 27, 2023
@JMS55
Copy link
Contributor

JMS55 commented Oct 27, 2023

The log macros are already macros. We can probably add warn_once!() variants that create a static bool per call-site. Might be nicer than a system local argument.

@alice-i-cecile
Copy link
Member Author

Yeah, I'm open to either approach honestly.

@alice-i-cecile alice-i-cecile added the D-Trivial Nice and easy! A great choice to get started with Bevy label Oct 27, 2023
@josfeenstra
Copy link
Contributor

No experience with singletons or macros in rust, but giving this a go!

Using https://github.com/Luthaf/log-once as an example, I managed to cobble together the following PoC:

https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=73774ab6270addbd16e29bd1c138b758

This works, but uses a singleton hashset. we might not want this as our 'once' determiner. Doing something like log_once!(&my_moving_vec3) will not run once, and fills up the singleton hashset in no time.

Any idea how to statically define a unique boolean per call @JMS55 ?

@josfeenstra
Copy link
Contributor

josfeenstra commented Oct 30, 2023

Simplest solution I can think of is a &str tag:

fn example_system(res: Res<MyResource>) {
   if res.is_invalid() {
      warn_once!("my_resource_invalid_tag", "Resource is invalid! Happened at: {:?}", std::time::SystemTime::now());
   }
}

@emesare
Copy link

emesare commented Oct 30, 2023

Any idea how to statically define a unique boolean per call @JMS55 ?

The macro will expand at the callsite, resulting in a unique static SHOULD_FIRE per call to print_once!
https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=236a68a341ee52a029fe62558ab7c80f

@mgi388
Copy link
Contributor

mgi388 commented Nov 24, 2023

Is it clear that "build a log only once helper" is the right approach here? For example, another solution is a log sampling method/functionality.

I know it's not Rust, and I know it's not in the Go std lib, but take a look a Zerolog in the Go ecosystem: https://pkg.go.dev/github.com/rs/zerolog#readme-log-sampling

sampled := log.Sample(&zerolog.BasicSampler{N: 10})
sampled.Info().Msg("will be logged every 10 messages")

// Output: {"time":1494567715,"level":"info","message":"will be logged every 10 messages"}

Not saying to ape this as is, I'm just sharing an example of how a sampling solution could be flexible here without (arguably) going so far as over-engineering.

@ItsDoot
Copy link
Contributor

ItsDoot commented Nov 28, 2023

If going with the SystemParam approach, alternatively it could just be:

impl Local<'_, bool> {
   fn set_false_if(&mut self, condition: bool) -> bool {
       if self.0 {
          self.0 = false;
          condition
       } else {
          false
       }
   }
}

@josfeenstra
Copy link
Contributor

josfeenstra commented Nov 29, 2023

Not saying to ape this as is, I'm just sharing an example of how a sampling solution could be flexible here without (arguably) going so far as over-engineering.

Hmmm... You are raising some good points, @mgi388. I'm also not really sure why macro's are even used at all for logging, aside from mimicking println!(). I wonder what you guys think of logging syntax like this:

fn my_system(mut c: Commands) {
   let name = "mgi";
   c.log(Level::Info,  format!("Hello, {}!", name)).once("token");
   c.log_warn("spam");
}

In any case, lets prevent scope creep.

I think that the log_once!() macro @emesare offers is a great solution. I didnt know macro symbols are unique per macro, thanks for pointing it out!

Its concise, low-overhead, easy-to-use, and it feels like magic, since the booleans are hidden within the macro.
Its also nice that the logs are tracked per call-site, and not via 'hashing print statement', or tokens, or any other naive approaches.

Apologies for waiting quite long for continuing this. Hope to start working on it Soon (tm)

@mockersf
Copy link
Member

Macro are used for logging so that format which creates strings is not executed if that log level is disabled

@josfeenstra
Copy link
Contributor

Ah of course, thanks @mockersf !

github-merge-queue bot pushed a commit that referenced this issue Dec 5, 2023
# 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.
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-Code-Quality A section of code that is hard to understand or change C-Usability A targeted quality-of-life change that makes Bevy easier to use D-Trivial Nice and easy! A great choice to get started with Bevy
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants