debug! statements still codegen despite release_max_level_off

[MarkMcCaskey]

Bug Report

Hello, I'm investigating binary bloat in an application and I noticed that there seems to be a lot from log statements, even if I try to statically compile them away.

Version

tracing: 0.1.22
Rust: rustc 1.51.0-nightly (da305a2b0 2021-01-05)

Platform

Darwin mark 20.2.0 Darwin Kernel Version 20.2.0: Wed Dec 2 20:39:59 PST 2020; root:xnu-7195.60.75~1/RELEASE_X86_64 x86_64

Crates

tracing, tracing-log?

Description

features:

tracing = { version = "0.1", features = ["log", "release_max_level_off", "max_level_off"] }

context:

#[typetag::serde(tag = "type")]
pub trait WasiFile: fmt::Debug + Send + Write + Read + Seek + 'static + Upcastable {
    fn set_last_accessed(&self, _last_accessed: __wasi_timestamp_t) {
       // debug!("{:?} did nothing in WasiFile::set_last_accessed due to using the default implementation", self);
    }

    fn set_last_modified(&self, _last_modified: __wasi_timestamp_t) {
        debug!("{:?} did nothing in WasiFile::set_last_modified due to using the default implementation", self);
    }
...

This was most noticeable in this trait where the empty default methods log and then return without doing anything. This trait is implemented on a number of types and many of the types use the default implementations.

note that set_last_accessed has been commented out as a baseline to compare against.

Running cargo bloat without the release_max_level_off and max_level_off features in release mode, we get:

591B  wasmer_wasi wasmer_wasi::state::types::WasiFile::set_last_modified
6B  wasmer_wasi wasmer_wasi::state::types::WasiFile::set_last_accessed

with multiple entries.

Running cargo bloat with release_max_level_off and max_level_off features in release mode, we get:

300B  wasmer_wasi wasmer_wasi::state::types::WasiFile::set_last_modified
6B  wasmer_wasi wasmer_wasi::state::types::WasiFile::set_last_accessed

So we get a reduction of about half in terms of bytes of generated code by enabling these features. I'd expect these features to be equivalent to commenting out the log statement.

---

cargo expanding it, we get:

fn set_last_accessed(&self, _last_accessed: __wasi_timestamp_t) {}

and

fn set_last_modified(&self, _last_modified: __wasi_timestamp_t) {
    {
        if !::tracing::dispatcher::has_been_set() {
            {
                use ::tracing::log;
                let level = match ::tracing::Level::DEBUG {
                    ::tracing::Level::ERROR => ::tracing::log::Level::Error,
                    ::tracing::Level::WARN => ::tracing::log::Level::Warn,
                    ::tracing::Level::INFO => ::tracing::log::Level::Info,
                    ::tracing::Level::DEBUG => ::tracing::log::Level::Debug,
                    _ => ::tracing::log::Level::Trace,
                };
                if level <= log::STATIC_MAX_LEVEL && level <= log::max_level() {
                    let log_meta = log::Metadata::builder()
                        .level(level)
                        .target("wasmer_wasi::state::types")
                        .build();
                    let logger = log::logger();
                    if logger.enabled(&log_meta) {
                        logger . log ( & log :: Record :: builder ( ) . file ( Some ( "lib/wasi/src/state/types.rs" ) ) . module_path ( Some ( "wasmer_wasi::state::types" ) ) . line ( Some ( 171u32 ) ) . metadata ( log_meta ) . args ( { # [ allow ( unused_imports ) ] use :: tracing :: field :: { debug , display } ; :: core :: fmt :: Arguments :: new_v1 ( & [ "" , " " ] , & match ( & :: core :: fmt :: Arguments :: new_v1 ( & [ "" , " did nothing in WasiFile::set_last_modified due to using the default implementation" ] , & match ( & self , ) { ( arg0 , ) => [ :: core :: fmt :: ArgumentV1 :: new ( arg0 , :: core :: fmt :: Debug :: fmt ) ] , } ) , ) { ( arg0 , ) => [ :: core :: fmt :: ArgumentV1 :: new ( arg0 , :: core :: fmt :: Display :: fmt ) ] , } ) } ) . build ( ) ) ;
                    }
                }
            }
        } else {
            {}
        };
        if ::tracing::Level::DEBUG <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && ::tracing::Level::DEBUG
                <= ::tracing::level_filters::LevelFilter::current()
        {
            use ::tracing::__macro_support::*;
            static CALLSITE: ::tracing::__macro_support::MacroCallsite = {
                use ::tracing::__macro_support::MacroCallsite;
                static META: ::tracing::Metadata<'static> = {
                    ::tracing_core::metadata::Metadata::new(
                        "event lib/wasi/src/state/types.rs:171",
                        "wasmer_wasi::state::types",
                        ::tracing::Level::DEBUG,
                        Some("lib/wasi/src/state/types.rs"),
                        Some(171u32),
                        Some("wasmer_wasi::state::types"),
                        ::tracing_core::field::FieldSet::new(
                            &["message"],
                            ::tracing_core::callsite::Identifier(&CALLSITE),
                        ),
                        ::tracing::metadata::Kind::EVENT,
                    )
                };
                MacroCallsite::new(&META)
            };
            let interest = CALLSITE.interest();
            if !interest.is_never() && CALLSITE.is_enabled(interest) {
                let meta = CALLSITE.metadata();
                ::tracing::Event::dispatch(meta, &{
                    #[allow(unused_imports)]
                    use ::tracing::field::{debug, display, Value};
                    let mut iter = meta.fields().iter();
                    meta . fields ( ) . value_set ( & [ ( & iter . next ( ) . expect ( "FieldSet corrupted (this is a bug)" ) , Some ( & :: core :: fmt :: Arguments :: new_v1 ( & [ "" , " did nothing in WasiFile::set_last_modified due to using the default implementation" ] , & match ( & self , ) { ( arg0 , ) => [ :: core :: fmt :: ArgumentV1 :: new ( arg0 , :: core :: fmt :: Debug :: fmt ) ] , } ) as & Value ) ) ] )
                });
            }
        }
    };
}

Expected behavior is:

1. When these features are set, for the macro expansion to be empty (using features to make the macros no-ops)
2. OR The macro-expanded code should be reduced into "0" bytes (leaving 6 bytes total for the trait method in this case, same as the base line)

---

Extra context

It probably doesn't matter but the release profile was tweaked when running this:

[profile.release]
opt-level = 'z'
debug = false
debug-assertions = false
overflow-checks = false
lto = true
panic = 'abort'
incremental = false
codegen-units = 1
rpath = false

Thanks!

[hawkw]

Thanks for the bug report. It looks like the culprit is the log crate support. The if $level <= $::level_filters::STATIC_MAX_LEVEL check should statically evaluate to false, resulting in the compiler eliminating all the code inside that if --- 0 bytes should be generated.

However, the code for also emitting log records is outside this if, since we want libraries using tracing to be able to emit log events even when tracing is globally disabled.

If you can disable tracing's log feature flag (and ensure that no other dependencies are enabling it as well), and check if any code is generated, that could be useful for validating this assumption.

It looks like we also ought to move the dispatcher::has_been_set check inside of the log static max level check. That way, we can also generate no code for the log support when the log crate's static_max_level_off feature is enabled.

[MarkMcCaskey]

@hawkw

I can confirm that disabling the log feature does work exactly as expected: each of those trait methods is now 6 bytes. Thanks!

[hawkw]

@hawkw

I can confirm that disabling the log feature does work exactly as expected: each of those trait methods is now 6 bytes. Thanks!

Great, thanks for checking! I'll go ahead and move the log max level check outside of the dispatcher::has_been_set check. Then, it should be possible to get 0 additional bytes of code generated by either depending on the log crate and setting its static_max_level features, or by disabling tracing's log feature.

I'll also make sure the docs explain clearly that some code may be generated if tracing is statically disabled but the log crate is in use and is not statically disabled!