tracing/tracing-log
Koute 4e5f0f06ab
log: add an interest cache for logs emitted through the log crate (#1636)
## Motivation

We use `tracing` as our logger in
[`substrate`](https://github.com/paritytech/substrate). We've noticed
that as soon as *any* `trace` log is enabled (even one which doesn't
exists) the whole logging machinery starts to take a lot of time, even
if nothing at all is actually printed!

In one of our quick-and-dirty reproduction benchmarks (JIT-ing a WASM
program) we saw the total real runtime rise from around ~1.3s to ~7s
just by adding a `trace` log filter which doesn't match anything.
(Depending on the hardware and on how many threads are simultaneously
logging this figure varies pretty widely, but it's always a very
significant drop.)

After looking into this problem I've found that the culprit of the
slowdown were `trace!` and `debug!` logs sprinkled quite liberally in
some of the more hot codepaths. When there are no `trace`-level filters
defined on the logger it can basically reject those inert `trace!` and
`debug!` logs purely based on the current maximum logging level (which
is cheap!), but as soon as you define *any* trace filter the current
maximum logging changes, and then every `trace!` and `debug!` log has to
go through the whole filtering machinery before it can be rejected.
While this is cheap if you only do it once, it starts to become very
expensive when you do it a lot, especially when you're running multiple
threads and enable log reloading. (This is related to
https://github.com/tokio-rs/tracing/issues/1632.)

## Solution

I've added an opt-in per-thread LRU cache which tries to cache whenever
the logger is actually interested in a given `target` + `level` pair for
every log emitted through the `log` crate.

I've also added a benchmark very roughly replicating the situation from
our code; here's the performance *without* the cache: (`cargo bench`)

```
[838.67 ns 846.51 ns 854.04 ns]
```

And here's the performance *with* the cache: (`cargo bench --features
interest-cache`)

```
[25.322 ns 25.556 ns 25.820 ns]
```

As you can see the per-call cost was cut down to less than ~3%.
2021-10-18 09:23:35 -07:00
..
2021-02-19 14:55:59 -08:00

Tracing — Structured, application-level diagnostics

tracing-log

log compatibility for tracing.

Crates.io Documentation Documentation (master) MIT licensed Build Status Discord chat maintenance status

Documentation | Chat (discord)

Overview

tracing is a framework for instrumenting Rust programs with context-aware, structured, event-based diagnostic information. This crate provides compatibility layers for using tracing alongside the logging facade provided by the log crate.

This crate provides:

  • AsTrace and AsLog traits for converting between tracing and log types.
  • LogTracer, a log::Log implementation that consumes log::Records and outputs them as tracing::Events.
  • An [env_logger] module, with helpers for using the [env_logger crate] with tracing (optional, enabled by the env_logger feature).

Compiler support: requires rustc 1.42+

Supported Rust Versions

Tracing is built against the latest stable release. The minimum supported version is 1.42. The current Tracing version is not guaranteed to build on Rust versions earlier than the minimum supported version.

Tracing follows the same compiler support policies as the rest of the Tokio project. The current stable Rust compiler and the three most recent minor versions before it will always be supported. For example, if the current stable compiler version is 1.45, the minimum supported version will not be increased past 1.42, three minor versions prior. Increasing the minimum supported compiler version is not considered a semver breaking change as long as doing so complies with this policy.

License

This project is licensed under the MIT license.

Contribution

Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in Tracing by you, shall be licensed as MIT, without any additional terms or conditions.