From 3e2ee68827a04a175dbf102e0b21db95a9249dd1 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 6 Jan 2021 14:19:27 -0800 Subject: [PATCH 1/2] tracing: check `log` max level prior to dispatch check Currently, when the `log` feature is enabled but the `log-always` feature is not, we check the (dynamic, but inexpensive) `dispatch::has_been_set` variable **before** checking if the event's level would be enabled by `log`'s static max level features. Although this check is not terribly costly in terms of performance, it *does* result in code being generated even when the `log` crate disables some levels statically. This means that we will always generate *some* code when the `log` feature is disabled. This isn't ideal --- the static max level features should result in us generating *no* code whatsoever for disabled trace points. This commit moves the static max level check outside of the dispatch check. Now, we should generate 0 bytes of assembly when both `log` and `tracing` disable an event with their static filtering features. --- tracing/src/level_filters.rs | 17 ++++++++++-- tracing/src/macros.rs | 54 +++++++++++++++++++++--------------- tracing/src/span.rs | 36 ++++++++++++------------ 3 files changed, 64 insertions(+), 43 deletions(-) diff --git a/tracing/src/level_filters.rs b/tracing/src/level_filters.rs index 2932233ede..496485a1f6 100644 --- a/tracing/src/level_filters.rs +++ b/tracing/src/level_filters.rs @@ -33,10 +33,23 @@ //! [dependencies] //! tracing = { version = "0.1", features = ["max_level_debug", "release_max_level_warn"] } //! ``` +//! ## Notes //! -//! *Compiler support: requires rustc 1.39+* +//! Please note that `tracing`'s static max level features do *not* control the +//! [`log`] records that may be emitted when [`tracing`'s "log" feature flag][f] is +//! enabled. This is to allow `tracing` to be disabled entirely at compile time +//! while still emitting `log` records --- such as when a library using +//! `tracing` is used by an application using `log` that doesn't want to +//! generate any `tracing`-related code, but does want to collect `log` records. //! -//! [`log` crate]: https://docs.rs/log/0.4.6/log/#compile-time-filters +//! This means that if the "log" feature is in use, some code may be generated +//! for `log` records emitted by disabled `tracing` events. If this is not +//! desirable, `log` records may be disabled separately using [`log`'s static +//! max level features][`log` crate]. +//! +//! [`log`]: https://docs.rs/log/ +//! [`log` crate]: https://docs.rs/log/latest/log/#compile-time-filters +//! [f]: : https://docs.rs/tracing/latest/tracing/#emitting-log-records pub use tracing_core::{metadata::ParseLevelFilterError, LevelFilter}; /// The statically configured maximum trace level. diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index f69064ed8b..d24bf7c45f 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -45,7 +45,7 @@ macro_rules! span { ) } else { let span = CALLSITE.disabled_span(); - $crate::if_log_enabled! {{ + $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; span @@ -76,7 +76,7 @@ macro_rules! span { ) } else { let span = CALLSITE.disabled_span(); - $crate::if_log_enabled! {{ + $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; span @@ -2299,10 +2299,10 @@ macro_rules! __mk_format_args { #[macro_export] macro_rules! __tracing_log { (target: $target:expr, $level:expr, $($field:tt)+ ) => { - $crate::if_log_enabled! {{ + $crate::if_log_enabled! { $level, { use $crate::log; let level = $crate::level_to_log!($level); - if level <= log::STATIC_MAX_LEVEL && level <= log::max_level() { + if level <= log::max_level() { let log_meta = log::Metadata::builder() .level(level) .target($target) @@ -2326,13 +2326,13 @@ macro_rules! __tracing_log { #[doc(hidden)] #[macro_export] macro_rules! if_log_enabled { - ($e:expr;) => { - $crate::if_log_enabled! { $e } + ($lvl:expr, $e:expr;) => { + $crate::if_log_enabled! { $lvl, $e } }; - ($if_log:block) => { - $crate::if_log_enabled! { $if_log else {} } + ($lvl:expr, $if_log:block) => { + $crate::if_log_enabled! { $lvl, $if_log else {} } }; - ($if_log:block else $else_block:block) => { + ($lvl:expr, $if_log:block else $else_block:block) => { $else_block }; } @@ -2341,15 +2341,19 @@ macro_rules! if_log_enabled { #[doc(hidden)] #[macro_export] macro_rules! if_log_enabled { - ($e:expr;) => { - $crate::if_log_enabled! { $e } + ($lvl:expr, $e:expr;) => { + $crate::if_log_enabled! { $lvl, $e } }; - ($if_log:block) => { - $crate::if_log_enabled! { $if_log else {} } + ($lvl:expr, $if_log:block) => { + $crate::if_log_enabled! { $lvl, $if_log else {} } }; - ($if_log:block else $else_block:block) => { - if !$crate::dispatcher::has_been_set() { - $if_log + ($lvl:expr, $if_log:block else $else_block:block) => { + if $crate::level_to_log!($lvl) <= $crate::log::STATIC_MAX_LEVEL { + if !$crate::dispatcher::has_been_set() { + $if_log + } else { + $else_block + } } else { $else_block } @@ -2360,14 +2364,18 @@ macro_rules! if_log_enabled { #[doc(hidden)] #[macro_export] macro_rules! if_log_enabled { - ($e:expr;) => { - $crate::if_log_enabled! { $e } + ($lvl:expr, $e:expr;) => { + $crate::if_log_enabled! { $lvl, $e } }; - ($if_log:block) => { - $crate::if_log_enabled! { $if_log else {} } + ($lvl:expr, $if_log:block) => { + $crate::if_log_enabled! { $lvl, $if_log else {} } }; - ($if_log:block else $else_block:block) => { - #[allow(unused_braces)] - $if_log + ($lvl:expr, $if_log:block else $else_block:block) => { + if $crate::level_to_log!($lvl) <= $crate::log::STATIC_MAX_LEVEL { + #[allow(unused_braces)] + $if_log + } else { + $else_block + } }; } diff --git a/tracing/src/span.rs b/tracing/src/span.rs index b9dd4ff0f7..395ba0a777 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -545,7 +545,7 @@ impl Span { meta: Some(meta), }; - if_log_enabled! {{ + if_log_enabled! { *meta.level(), { let target = if attrs.is_empty() { LIFECYCLE_LOG_TARGET } else { @@ -761,7 +761,7 @@ impl Span { inner.collector.enter(&inner.id); } - if_log_enabled! {{ + if_log_enabled! { *meta.level(), { if let Some(ref meta) = self.meta { self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name())); } @@ -933,16 +933,16 @@ impl Span { inner.record(&record); } - if_log_enabled! {{ - if let Some(ref meta) = self.meta { + if let Some(ref _meta) = self.meta { + if_log_enabled! { *_meta.level(), { let target = if record.is_empty() { LIFECYCLE_LOG_TARGET } else { - meta.target() + _meta.target() }; - self.log(target, level_to_log!(*meta.level()), format_args!("{}{}", meta.name(), FmtValues(&record))); - } - }} + self.log(target, level_to_log!(*meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record))); + }} + } self } @@ -1148,15 +1148,15 @@ impl Drop for Span { collector.try_close(id.clone()); } - if_log_enabled!({ - if let Some(ref meta) = self.meta { + if let Some(ref _meta) = self.meta { + if_log_enabled! { Level::TRACE, { self.log( LIFECYCLE_LOG_TARGET, log::Level::Trace, - format_args!("-- {}", meta.name()), + format_args!("-- {}", _meta.name()), ); - } - }) + }} + } } } @@ -1251,11 +1251,11 @@ impl<'a> Drop for Entered<'a> { inner.collector.exit(&inner.id); } - if_log_enabled! {{ - if let Some(ref meta) = self.span.meta { - self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", meta.name())); - } - }} + if let Some(ref _meta) = self.span.meta { + if_log_enabled! { Level::TRACE, { + self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name())); + }} + } } } From 991cdfcd2c99307ac980fdf41dea8e8368fc2e49 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Jan 2021 10:49:09 -0800 Subject: [PATCH 2/2] fixup Signed-off-by: Eliza Weisman --- tracing/src/span.rs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 395ba0a777..0a86ca848f 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -556,6 +556,7 @@ impl Span { span } + /// Enters this span, returning a guard that will exit the span when dropped. /// /// If this span is enabled by the current collector, then this function will @@ -761,7 +762,7 @@ impl Span { inner.collector.enter(&inner.id); } - if_log_enabled! { *meta.level(), { + if_log_enabled! { crate::Level::TRACE, { if let Some(ref meta) = self.meta { self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name())); } @@ -940,7 +941,7 @@ impl Span { } else { _meta.target() }; - self.log(target, level_to_log!(*meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record))); + self.log(target, level_to_log!(*_meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record))); }} } @@ -1149,7 +1150,7 @@ impl Drop for Span { } if let Some(ref _meta) = self.meta { - if_log_enabled! { Level::TRACE, { + if_log_enabled! { crate::Level::TRACE, { self.log( LIFECYCLE_LOG_TARGET, log::Level::Trace, @@ -1252,7 +1253,7 @@ impl<'a> Drop for Entered<'a> { } if let Some(ref _meta) = self.span.meta { - if_log_enabled! { Level::TRACE, { + if_log_enabled! { crate::Level::TRACE, { self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name())); }} }