When using tracing-log, log::log_enabled! is always true

[pchickey]

Bug Report

Version

├── tracing-subscriber v0.2.15
│ ├── tracing v0.1.22 ()
│ ├── tracing-log v0.1.1
│ │ └── tracing-core v0.1.17 ()

Platform

Linux finknottle 5.8.0-43-generic #49~20.04.1-Ubuntu SMP Fri Feb 5 09:57:56 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Crates

tracing-log

Description

We use tracing-log (via tracing-subscriber) in several executables in the Wasmtime project (https://github.com/bytecodealliance/wasmtime/), and log macros in many crates and dependencies of the project.

We recently discovered that tracing-log was causing every log_enabled!(LogLevel::Debug) in the project to be true, which incurs some costly formatting of datastructures into strings, even when the log level is disabled (e.g. RUST_LOG is undefined).

In our particular case this ended up being a 2x slowdown of our JIT compiler.

[davidbarsky]

I believe this issue will be resolved in #1248.

[hawkw]

@davidbarsky yeah, I'm going to keep this open until I get it backported and @pchickey can confirm that it resolves the problem.

[hawkw]

@pchickey okay, you should be able to test this out with a git dependency on this branch: #1250

I believe you will have to patch the tracing-subscriber and tracing-log crates, since the tracing-subscriber fix depends on changes in tracing-log. The easiest way might be pointing .cargo/config at a local git checkout, rather than messing around with [patch].

[pchickey]

Unfortunately the backport branch (#1250) isn't quite working yet. Alex put together this https://gist.github.com/alexcrichton/bfaa02d0833e1a95709e3432a1d18c46to reproduce it - "log level enabled" prints in both v0.1.x and eliza/backport-log-stuff

[hawkw]

Unfortunately the backport branch (#1250) isn't quite working yet. Alex put together this https://gist.github.com/alexcrichton/bfaa02d0833e1a95709e3432a1d18c46to reproduce it - "log level enabled" prints in both v0.1.x and eliza/backport-log-stuff

Ah, looks like there's actually just two bugs here. I added some dbg!s:

[tracing-core/src/callsite.rs:56] dispatch.max_level_hint() = None
[tracing-core/src/callsite.rs:57] level_hint = LevelFilter::TRACE
[tracing-log/src/log_tracer.rs:260] self.filter = Trace
[examples/examples/log-enabled.rs:8] tracing_core::LevelFilter::current() = LevelFilter::TRACE
log level enabled

It looks like the FmtSubscriber type in particular does not forward the max level hint correctly. If I change the example to set up the subscriber like this:

    use tracing_subscriber::prelude::*;
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer())
        .with(tracing_subscriber::EnvFilter::from_default_env())
        .init();

everything works correctly, and "log level enabled" is not printed.

This should be pretty easy to fix: we just want to ensure that method is forwarded in the Subscriber implementation for the FmtSubscriber wrapper type.

[hawkw]

#1251 fixes the FmtSubscriber bug (technically the FmtCollector bug, since it's against 0.2). I'll backport that to 0.1 once it merges.

I'm going to go ahead and merge the backport branch, since it does in fact fix the issue, except when using the FmtSubscriber type (as in the repro).

[hawkw]

@pchickey just triple-checking: landing both #1250 and backporting #1251 to v0.1.x fixes the repro case for you, correct?

[pchickey]

Yes, I checked that the merge of those branches fixes both the small repro case and the bigger issue over in wasmtime.

[hawkw]

One last PR: #1254 should ensure we handle log_enabled! correctly in even more cases.

[hawkw]

closed by...the sum total of all the various PRs i mentioned here.