Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Turn on the logger's interest cache #11264

Merged

Conversation

koute
Copy link
Contributor

@koute koute commented Apr 22, 2022

polkadot companion: paritytech/polkadot#5393

This lowers the CPU overhead of our logging machinery when any trace log is enabled down to ~3% of what it is without any trace logs enabled.

Background

The tracing-log crate has a bunch of relatively expensive filtering machinery which decides whether a given log should be printed out or not. This machinery has a fast path: if the current most verbose logging level is set to X then the logger can just reject every log which uses a more verbose level and skip the expensive checks.

For example, if we have set RUST_LOG to foo=info,bar=warn then the most verbose log level is info, so any trace logs can be quickly rejected because we know that a log must be at least info to be printable. Now, if we have set RUST_LOG to foo=info,bar=trace then the most verbose log level is trace, so now for any trace log the logger must actually check whether that log came from foo or from bar to decide whether it should be printed out, and this is expensive when you're generating thousands of trace logs every second (even if they're not printed out!).

So this PR enables a built-in interest cache which I've previously added to tracing-log. This cache allows the logger to essentially skip the heavyweight filtering machinery by just doing the work once, and then just querying the cache on any subsequent call. According to the measurements I've done a long time ago this should cut down the CPU usage of the logger to ~3% when you have any trace log enabled (even if it's for a target which doesn't actually exist and will never actually match anything).

(This is the second time I'm making this PR; the previous PR couldn't be merged since the tracing-log crate was not released on crates.io; but that finally changed today with the release of tracing-log 0.1.3.)

@koute koute added A0-please_review Pull request needs code review. I9-optimisation An enhancement to provide better overall performance in terms of time-to-completion for a task. B0-silent Changes should not be mentioned in any release notes C1-low PR touches the given topic and has a low impact on builders. D3-trivial 🧸 PR contains trivial changes in a runtime directory that do not require an audit labels Apr 22, 2022
@koute koute requested a review from a team April 22, 2022 05:16
Copy link
Contributor

@gilescope gilescope left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great to see it land at last! Good things come to those that wait.

@koute
Copy link
Contributor Author

koute commented Apr 26, 2022

bot merge

@paritytech-processbot
Copy link

Error: "Check reviews" status is not passing for paritytech/polkadot#5393

@koute
Copy link
Contributor Author

koute commented Apr 26, 2022

bot merge

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A0-please_review Pull request needs code review. B0-silent Changes should not be mentioned in any release notes C1-low PR touches the given topic and has a low impact on builders. D3-trivial 🧸 PR contains trivial changes in a runtime directory that do not require an audit I9-optimisation An enhancement to provide better overall performance in terms of time-to-completion for a task.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants