From f8100396631cd519623b1a63e9505111dd1cd2da Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 18 Aug 2020 16:31:59 -0700 Subject: [PATCH 1/9] [WIP] shrink code inlined by macro expansions --- Cargo.toml | 7 ++- tracing-core/src/dispatcher.rs | 52 +++++++++++++++++ tracing/src/lib.rs | 56 +++++++++++++++--- tracing/src/macros.rs | 102 +++++++++++++++++++++++++-------- 4 files changed, 186 insertions(+), 31 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 79b600dbfb..b07181f08a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,5 +15,10 @@ members = [ "tracing-serde", "tracing-appender", "tracing-journald", - "examples" + "examples", + "disas" ] + + +[profile.release] +debug = true \ No newline at end of file diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 9a6048bc1b..b602d27034 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -357,6 +357,58 @@ where .unwrap_or_else(|_| f(&Dispatch::none())) } +/// Executes a closure with a reference to this thread's current [dispatcher]. +/// +/// Note that calls to `get_default` should not be nested; if this function is +/// called while inside of another `get_default`, that closure will be provided +/// with `Dispatch::none` rather than the previously set dispatcher. +/// +/// [dispatcher]: ../dispatcher/struct.Dispatch.html +#[cfg(feature = "std")] +#[doc(hidden)] +pub fn get_current(f: impl FnOnce(&Dispatch) -> T) -> Option { + // While this guard is active, additional calls to subscriber functions on + // the default dispatcher will not be able to access the dispatch context. + // Dropping the guard will allow the dispatch context to be re-entered. + struct Entered<'a>(&'a Cell); + impl<'a> Drop for Entered<'a> { + #[inline] + fn drop(&mut self) { + self.0.set(true); + } + } + + CURRENT_STATE + .try_with(|state| { + if state.can_enter.replace(false) { + let _guard = Entered(&state.can_enter); + + let mut default = state.default.borrow_mut(); + + if default.is::() { + if let Some(global) = get_global() { + // don't redo this call on the next check + *default = global.clone(); + } + } + return Some(f(&*default)); + } + + None + }) + .ok()? +} + +/// Executes a closure with a reference to the current [dispatcher]. +/// +/// [dispatcher]: ../dispatcher/struct.Dispatch.html +#[cfg(not(feature = "std"))] +#[doc(hidden)] +pub fn get_current(f: impl FnOnce(&Dispatch) -> T) -> Option { + let dispatch = get_global()?; + Some(f(&dispatch)) +} + /// Executes a closure with a reference to the current [dispatcher]. /// /// [dispatcher]: ../dispatcher/struct.Dispatch.html diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 40660a3983..85238ec91b 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -954,8 +954,7 @@ pub mod __macro_support { /// by the `tracing` macros, but it is not part of the stable versioned API. /// Breaking changes to this module may occur in small-numbered versions /// without warning. - #[inline(always)] - pub fn is_enabled(&self) -> bool { + pub fn is_enabled(&'static self) -> bool { let interest = self.interest(); if interest.is_always() { return true; @@ -977,20 +976,63 @@ pub mod __macro_support { /// by the `tracing` macros, but it is not part of the stable versioned API. /// Breaking changes to this module may occur in small-numbered versions /// without warning. - #[inline(always)] - pub fn register(&'static self) { + #[inline(never)] + #[cold] + pub fn register(&'static self) -> Interest { self.registration .call_once(|| crate::callsite::register(self)); + match self.interest.load(Ordering::Relaxed) { + 0 => Interest::never(), + 2 => Interest::always(), + _ => Interest::sometimes(), + } } - #[inline(always)] - fn interest(&self) -> Interest { + #[inline] + pub fn interest(&'static self) -> Interest { match self.interest.load(Ordering::Relaxed) { 0 => Interest::never(), + 1 => Interest::sometimes(), 2 => Interest::always(), - _ => Interest::sometimes(), + _ => self.register(), } } + + #[inline(never)] + pub fn dispatch_event(&'static self, interest: Interest, f: impl FnOnce(&crate::Dispatch)) { + tracing_core::dispatcher::get_current(|current| { + if interest.is_always() || current.enabled(self.meta) { + f(current) + } + }); + } + + #[inline(always)] + #[cfg(feature = "log")] + fn disabled_span(&self) -> crate::Span { + crate::Span::new_disabled(self.meta) + } + + #[inline(always)] + #[cfg(not(feature = "log"))] + fn disabled_span(&self) -> crate::Span { + crate::Span::none() + } + + #[inline(never)] + pub fn dispatch_span( + &'static self, + interest: Interest, + f: impl FnOnce(&crate::Dispatch) -> crate::Span, + ) -> crate::Span { + tracing_core::dispatcher::get_current(|current| { + if interest.is_always() || current.enabled(self.meta) { + return f(current); + } + self.disabled_span() + }) + .unwrap_or_else(|| self.disabled_span()) + } } impl Callsite for MacroCallsite { diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 3d010aadd0..a40cad6e57 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -538,7 +538,7 @@ macro_rules! event { if $crate::level_enabled!($lvl) { use $crate::__macro_support::*; - let callsite = $crate::callsite! { + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { name: concat!( "event ", file!(), @@ -550,9 +550,12 @@ macro_rules! event { level: $lvl, fields: $($fields)* }; - if callsite.is_enabled() { - let meta = callsite.metadata(); - $crate::Event::child_of($parent, meta, &$crate::valueset!(meta.fields(), $($fields)*) ); + let interest = CALLSITE.interest(); + if !interest.is_never() { + CALLSITE.dispatch_event(interest, |current| { + let meta = CALLSITE.metadata(); + current.event(&$crate::Event::new_child_of($parent, meta, &$crate::valueset!(meta.fields(), $($fields)*))) + }); } } ); @@ -579,7 +582,7 @@ macro_rules! event { ); if $crate::level_enabled!($lvl) { use $crate::__macro_support::*; - let callsite = $crate::callsite! { + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { name: concat!( "event ", file!(), @@ -591,9 +594,12 @@ macro_rules! event { level: $lvl, fields: $($fields)* }; - if callsite.is_enabled() { - let meta = callsite.metadata(); - $crate::Event::dispatch(meta, &$crate::valueset!(meta.fields(), $($fields)*) ); + let interest = CALLSITE.interest(); + if !interest.is_never() { + CALLSITE.dispatch_event(interest, |current| { + let meta = CALLSITE.metadata(); + current.event(&$crate::Event::new(meta, &$crate::valueset!(meta.fields(), $($fields)*))); + }); } } }); @@ -1803,6 +1809,55 @@ macro_rules! callsite { }}; } +/// Constructs a new static callsite for a span or event. +#[doc(hidden)] +#[macro_export] +macro_rules! callsite2 { + (name: $name:expr, kind: $kind:expr, fields: $($fields:tt)*) => {{ + $crate::callsite2! { + name: $name, + kind: $kind, + target: module_path!(), + level: $crate::Level::TRACE, + fields: $($fields)* + } + }}; + ( + name: $name:expr, + kind: $kind:expr, + level: $lvl:expr, + fields: $($fields:tt)* + ) => {{ + $crate::callsite2! { + name: $name, + kind: $kind, + target: module_path!(), + level: $lvl, + fields: $($fields)* + } + }}; + ( + name: $name:expr, + kind: $kind:expr, + target: $target:expr, + level: $lvl:expr, + fields: $($fields:tt)* + ) => {{ + use $crate::__macro_support::MacroCallsite; + static META: $crate::Metadata<'static> = { + $crate::metadata! { + name: $name, + target: $target, + level: $lvl, + fields: $crate::fieldset!( $($fields)* ), + callsite: &CALLSITE, + kind: $kind, + } + }; + MacroCallsite::new(&META) + }}; +} + #[macro_export] // TODO: determine if this ought to be public API?` #[doc(hidden)] @@ -2068,20 +2123,20 @@ macro_rules! __tracing_mk_span { { if $crate::level_enabled!($lvl) { use $crate::__macro_support::*; - let callsite = $crate::callsite! { + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, level: $lvl, fields: $($fields)* }; - if callsite.is_enabled() { - let meta = callsite.metadata(); - $crate::Span::child_of( - $parent, - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - ) + let interest = CALLSITE.interest(); + if !interest.is_never() { + CALLSITE.dispatch_span(interest, |current| { + let meta = CALLSITE.metadata(); + // span with parent + unimplemented!("span with parent") + }); } else { $crate::Span::none() } @@ -2094,19 +2149,20 @@ macro_rules! __tracing_mk_span { { if $crate::level_enabled!($lvl) { use $crate::__macro_support::*; - let callsite = $crate::callsite! { + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, level: $lvl, fields: $($fields)* }; - if callsite.is_enabled() { - let meta = callsite.metadata(); - $crate::Span::new( - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - ) + let interest = CALLSITE.interest(); + if !interest.is_never() { + CALLSITE.dispatch_span(interest, |current| { + let meta = CALLSITE.metadata(); + // span without parent + unimplemented!("span without parent") + }); } else { $crate::Span::none() } From 540a158441044a034c7714cd842b9ba00477d467 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 18 Aug 2020 16:41:22 -0700 Subject: [PATCH 2/9] wip Signed-off-by: Eliza Weisman --- Cargo.toml | 9 ++------- tracing/src/macros.rs | 4 ++-- 2 files changed, 4 insertions(+), 9 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index b07181f08a..a1ee84b90c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,10 +15,5 @@ members = [ "tracing-serde", "tracing-appender", "tracing-journald", - "examples", - "disas" -] - - -[profile.release] -debug = true \ No newline at end of file + "examples" +] \ No newline at end of file diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index a40cad6e57..eeeaa7b642 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -2136,7 +2136,7 @@ macro_rules! __tracing_mk_span { let meta = CALLSITE.metadata(); // span with parent unimplemented!("span with parent") - }); + }) } else { $crate::Span::none() } @@ -2162,7 +2162,7 @@ macro_rules! __tracing_mk_span { let meta = CALLSITE.metadata(); // span without parent unimplemented!("span without parent") - }); + }) } else { $crate::Span::none() } From 182d1b4a6001fe729a979d7560dbcceccec19452 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 19 Aug 2020 10:15:14 -0700 Subject: [PATCH 3/9] okay spans actually work now Signed-off-by: Eliza Weisman --- tracing/src/macros.rs | 13 +++++++++-- tracing/src/span.rs | 54 +++++++++++++++++++++++++++++++++++-------- 2 files changed, 56 insertions(+), 11 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index eeeaa7b642..b37ddb47f6 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -2135,7 +2135,12 @@ macro_rules! __tracing_mk_span { CALLSITE.dispatch_span(interest, |current| { let meta = CALLSITE.metadata(); // span with parent - unimplemented!("span with parent") + $crate::Span::child_of_with( + $parent, + meta, + &$crate::valueset!(meta.fields(), $($fields)*), + current + ) }) } else { $crate::Span::none() @@ -2161,7 +2166,11 @@ macro_rules! __tracing_mk_span { CALLSITE.dispatch_span(interest, |current| { let meta = CALLSITE.metadata(); // span without parent - unimplemented!("span without parent") + $crate::Span::new_with( + meta, + &$crate::valueset!(meta.fields(), $($fields)*), + current, + ) }) } else { $crate::Span::none() diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 6a3653cd93..574dd7e3a3 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -406,8 +406,18 @@ impl Span { /// [`follows_from`]: ../struct.Span.html#method.follows_from #[inline] pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { + dispatcher::get_default(|dispatch| Self::new_with(meta, values, dispatch)) + } + + #[inline] + #[doc(hidden)] + pub fn new_with( + meta: &'static Metadata<'static>, + values: &field::ValueSet<'_>, + dispatch: &Dispatch, + ) -> Span { let new_span = Attributes::new(meta, values); - Self::make(meta, new_span) + Self::make_with(meta, new_span, dispatch) } /// Constructs a new `Span` as the root of its own trace tree, with the @@ -421,7 +431,18 @@ impl Span { /// [`follows_from`]: ../struct.Span.html#method.follows_from #[inline] pub fn new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { - Self::make(meta, Attributes::new_root(meta, values)) + dispatcher::get_default(|dispatch| Self::new_root_with(meta, values, dispatch)) + } + + #[inline] + #[doc(hidden)] + pub fn new_root_with( + meta: &'static Metadata<'static>, + values: &field::ValueSet<'_>, + dispatch: &Dispatch, + ) -> Span { + let new_span = Attributes::new_root(meta, values); + Self::make_with(meta, new_span, dispatch) } /// Constructs a new `Span` as child of the given parent span, with the @@ -437,12 +458,26 @@ impl Span { parent: impl Into>, meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, + ) -> Span { + let mut parent = parent.into(); + dispatcher::get_default(move |dispatch| { + Self::child_of_with(Option::take(&mut parent), meta, values, dispatch) + }) + } + + #[inline] + #[doc(hidden)] + pub fn child_of_with( + parent: impl Into>, + meta: &'static Metadata<'static>, + values: &field::ValueSet<'_>, + dispatch: &Dispatch, ) -> Span { let new_span = match parent.into() { Some(parent) => Attributes::child_of(parent, meta, values), None => Attributes::new_root(meta, values), }; - Self::make(meta, new_span) + Self::make_with(meta, new_span, dispatch) } /// Constructs a new disabled span with the given `Metadata`. @@ -497,12 +532,14 @@ impl Span { }) } - fn make(meta: &'static Metadata<'static>, new_span: Attributes<'_>) -> Span { + fn make_with( + meta: &'static Metadata<'static>, + new_span: Attributes<'_>, + dispatch: &Dispatch, + ) -> Span { let attrs = &new_span; - let inner = dispatcher::get_default(move |dispatch| { - let id = dispatch.new_span(attrs); - Some(Inner::new(id, dispatch)) - }); + let id = dispatch.new_span(attrs); + let inner = Some(Inner::new(id, dispatch)); let span = Self { inner, @@ -520,7 +557,6 @@ impl Span { span } - /// Enters this span, returning a guard that will exit the span when dropped. /// /// If this span is enabled by the current subscriber, then this function will From 1d31fe106f07740aa8fcb2cbd375728658905f63 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 19 Aug 2020 12:37:27 -0700 Subject: [PATCH 4/9] shrink span macros some more Signed-off-by: Eliza Weisman --- tracing-core/src/dispatcher.rs | 1 + tracing/src/lib.rs | 53 ++++------ tracing/src/macros.rs | 186 ++++++++++----------------------- 3 files changed, 78 insertions(+), 162 deletions(-) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index b602d27034..a3308dd4a9 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -366,6 +366,7 @@ where /// [dispatcher]: ../dispatcher/struct.Dispatch.html #[cfg(feature = "std")] #[doc(hidden)] +#[inline(never)] pub fn get_current(f: impl FnOnce(&Dispatch) -> T) -> Option { // While this guard is active, additional calls to subscriber functions on // the default dispatcher will not be able to access the dispatch context. diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 85238ec91b..0b91f1ba05 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -907,9 +907,9 @@ pub mod subscriber; #[doc(hidden)] pub mod __macro_support { - pub use crate::callsite::Callsite as _; + pub use crate::callsite::Callsite; use crate::stdlib::sync::atomic::{AtomicUsize, Ordering}; - use crate::{subscriber::Interest, Callsite, Metadata}; + use crate::{subscriber::Interest, Metadata}; use tracing_core::Once; /// Callsite implementation used by macro-generated code. @@ -938,34 +938,12 @@ pub mod __macro_support { /// without warning. pub const fn new(meta: &'static Metadata<'static>) -> Self { Self { - interest: AtomicUsize::new(0), + interest: AtomicUsize::new(0xDEADFACED), meta, registration: Once::new(), } } - /// Returns `true` if the callsite is enabled by a cached interest, or - /// by the current `Dispatch`'s `enabled` method if the cached - /// `Interest` is `sometimes`. - /// - /// /!\ WARNING: This is *not* a stable API! /!\ - /// This method, and all code contained in the `__macro_support` module, is - /// a *private* API of `tracing`. It is exposed publicly because it is used - /// by the `tracing` macros, but it is not part of the stable versioned API. - /// Breaking changes to this module may occur in small-numbered versions - /// without warning. - pub fn is_enabled(&'static self) -> bool { - let interest = self.interest(); - if interest.is_always() { - return true; - } - if interest.is_never() { - return false; - } - - crate::dispatcher::get_default(|current| current.enabled(self.meta)) - } - /// Registers this callsite with the global callsite registry. /// /// If the callsite is already registered, this does nothing. @@ -977,6 +955,7 @@ pub mod __macro_support { /// Breaking changes to this module may occur in small-numbered versions /// without warning. #[inline(never)] + // This only happens once (or if the cached interest value was corrupted). #[cold] pub fn register(&'static self) -> Interest { self.registration @@ -987,7 +966,15 @@ pub mod __macro_support { _ => Interest::sometimes(), } } - + /// Returns the callsite's cached Interest, or registers it for the + /// first time if it has not yet been registered. + /// + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This method, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. #[inline] pub fn interest(&'static self) -> Interest { match self.interest.load(Ordering::Relaxed) { @@ -998,7 +985,6 @@ pub mod __macro_support { } } - #[inline(never)] pub fn dispatch_event(&'static self, interest: Interest, f: impl FnOnce(&crate::Dispatch)) { tracing_core::dispatcher::get_current(|current| { if interest.is_always() || current.enabled(self.meta) { @@ -1007,24 +993,27 @@ pub mod __macro_support { }); } - #[inline(always)] + #[inline] #[cfg(feature = "log")] - fn disabled_span(&self) -> crate::Span { + pub fn disabled_span(&self) -> crate::Span { crate::Span::new_disabled(self.meta) } - #[inline(always)] + #[inline] #[cfg(not(feature = "log"))] - fn disabled_span(&self) -> crate::Span { + pub fn disabled_span(&self) -> crate::Span { crate::Span::none() } - #[inline(never)] pub fn dispatch_span( &'static self, interest: Interest, f: impl FnOnce(&crate::Dispatch) -> crate::Span, ) -> crate::Span { + if interest.is_never() { + return self.disabled_span(); + } + tracing_core::dispatcher::get_current(|current| { if interest.is_always() || current.enabled(self.meta) { return f(current); diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index b37ddb47f6..a3e646d4d8 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -22,10 +22,64 @@ macro_rules! span { $crate::span!(target: $target, parent: $parent, $lvl, $name,) }; (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - $crate::__tracing_mk_span!(target: $target, parent: $parent, $lvl, $name, $($fields)*) + { + use $crate::__macro_support::Callsite as _; + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + name: $name, + kind: $crate::metadata::Kind::SPAN, + target: $target, + level: $lvl, + fields: $($fields)* + }; + let mut interest = $crate::subscriber::Interest::never(); + if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{ + CALLSITE.dispatch_span(interest, |current| { + let meta = CALLSITE.metadata(); + // span with parent + $crate::Span::child_of_with( + $parent, + meta, + &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*), + current, + ) + }) + } else { + let span = CALLSITE.disabled_span(); + $crate::if_log_enabled! {{ + span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); + }}; + span + } + } }; (target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - $crate::__tracing_mk_span!(target: $target, $lvl, $name, $($fields)*) + { + use $crate::__macro_support::Callsite as _; + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + name: $name, + kind: $crate::metadata::Kind::SPAN, + target: $target, + level: $lvl, + fields: $($fields)* + }; + let mut interest = $crate::subscriber::Interest::never(); + if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{ + CALLSITE.dispatch_span(interest, |current| { + let meta = CALLSITE.metadata(); + $crate::Span::new_with( + meta, + &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*), + current, + ) + }) + } else { + let span = CALLSITE.disabled_span(); + $crate::if_log_enabled! {{ + span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); + }}; + span + } + } }; (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr) => { $crate::span!(target: $target, parent: $parent, $lvl, $name,) @@ -2115,134 +2169,6 @@ macro_rules! __tracing_log { (target: $target:expr, $level:expr, $($field:tt)+ ) => {}; } -#[cfg(not(feature = "log"))] -#[doc(hidden)] -#[macro_export] -macro_rules! __tracing_mk_span { - (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - { - if $crate::level_enabled!($lvl) { - use $crate::__macro_support::*; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { - name: $name, - kind: $crate::metadata::Kind::SPAN, - target: $target, - level: $lvl, - fields: $($fields)* - }; - let interest = CALLSITE.interest(); - if !interest.is_never() { - CALLSITE.dispatch_span(interest, |current| { - let meta = CALLSITE.metadata(); - // span with parent - $crate::Span::child_of_with( - $parent, - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - current - ) - }) - } else { - $crate::Span::none() - } - } else { - $crate::Span::none() - } - } - }; - (target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - { - if $crate::level_enabled!($lvl) { - use $crate::__macro_support::*; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { - name: $name, - kind: $crate::metadata::Kind::SPAN, - target: $target, - level: $lvl, - fields: $($fields)* - }; - let interest = CALLSITE.interest(); - if !interest.is_never() { - CALLSITE.dispatch_span(interest, |current| { - let meta = CALLSITE.metadata(); - // span without parent - $crate::Span::new_with( - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - current, - ) - }) - } else { - $crate::Span::none() - } - } else { - $crate::Span::none() - } - } - }; -} - -#[cfg(feature = "log")] -#[doc(hidden)] -#[macro_export] -macro_rules! __tracing_mk_span { - (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - { - use $crate::callsite::Callsite; - let callsite = $crate::callsite! { - name: $name, - kind: $crate::metadata::Kind::SPAN, - target: $target, - level: $lvl, - fields: $($fields)* - }; - let meta = callsite.metadata(); - if $crate::level_enabled!($lvl) && callsite.is_enabled() { - $crate::Span::child_of( - $parent, - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - ) - } else { - $crate::if_log_enabled! {{ - let span = $crate::Span::new_disabled(meta); - span.record_all(&$crate::valueset!(meta.fields(), $($fields)*)); - span - } else { - $crate::Span::none() - }} - } - } - }; - (target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { - { - use $crate::callsite::Callsite; - let callsite = $crate::callsite! { - name: $name, - kind: $crate::metadata::Kind::SPAN, - target: $target, - level: $lvl, - fields: $($fields)* - }; - let meta = callsite.metadata(); - if $crate::level_enabled!($lvl) && callsite.is_enabled() { - $crate::Span::new( - meta, - &$crate::valueset!(meta.fields(), $($fields)*), - ) - } else { - $crate::if_log_enabled! {{ - let span = $crate::Span::new_disabled(meta); - span.record_all(&$crate::valueset!(meta.fields(), $($fields)*)); - span - } else { - $crate::Span::none() - }} - } - } - }; -} - #[cfg(feature = "log")] #[doc(hidden)] #[macro_export] From 283dcb95edd45e5f3535f3197902c030e6ad64ef Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 20 Aug 2020 10:10:24 -0700 Subject: [PATCH 5/9] deduplicate some internals Signed-off-by: Eliza Weisman --- tracing-core/src/dispatcher.rs | 96 ++++++++++++++++------------------ 1 file changed, 44 insertions(+), 52 deletions(-) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index a3308dd4a9..500874070f 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -149,7 +149,7 @@ use crate::stdlib::{ #[cfg(feature = "std")] use crate::stdlib::{ - cell::{Cell, RefCell}, + cell::{Cell, RefCell, RefMut}, error, }; @@ -193,6 +193,11 @@ struct State { can_enter: Cell, } +// While this guard is active, additional calls to subscriber functions on +// the default dispatcher will not be able to access the dispatch context. +// Dropping the guard will allow the dispatch context to be re-entered. +struct Entered<'a>(&'a State); + /// A guard that resets the current default dispatcher to the prior /// default dispatcher when dropped. #[cfg(feature = "std")] @@ -325,34 +330,13 @@ pub fn get_default(mut f: F) -> T where F: FnMut(&Dispatch) -> T, { - // While this guard is active, additional calls to subscriber functions on - // the default dispatcher will not be able to access the dispatch context. - // Dropping the guard will allow the dispatch context to be re-entered. - struct Entered<'a>(&'a Cell); - impl<'a> Drop for Entered<'a> { - #[inline] - fn drop(&mut self) { - self.0.set(true); - } - } - CURRENT_STATE .try_with(|state| { - if state.can_enter.replace(false) { - let _guard = Entered(&state.can_enter); - - let mut default = state.default.borrow_mut(); - - if default.is::() { - if let Some(global) = get_global() { - // don't redo this call on the next check - *default = global.clone(); - } - } - f(&*default) - } else { - f(&Dispatch::none()) + if let Some(entered) = state.enter() { + return f(&*entered.current()); } + + f(&Dispatch::none()) }) .unwrap_or_else(|_| f(&Dispatch::none())) } @@ -368,34 +352,10 @@ where #[doc(hidden)] #[inline(never)] pub fn get_current(f: impl FnOnce(&Dispatch) -> T) -> Option { - // While this guard is active, additional calls to subscriber functions on - // the default dispatcher will not be able to access the dispatch context. - // Dropping the guard will allow the dispatch context to be re-entered. - struct Entered<'a>(&'a Cell); - impl<'a> Drop for Entered<'a> { - #[inline] - fn drop(&mut self) { - self.0.set(true); - } - } - CURRENT_STATE .try_with(|state| { - if state.can_enter.replace(false) { - let _guard = Entered(&state.can_enter); - - let mut default = state.default.borrow_mut(); - - if default.is::() { - if let Some(global) = get_global() { - // don't redo this call on the next check - *default = global.clone(); - } - } - return Some(f(&*default)); - } - - None + let entered = state.enter()?; + Some(f(&*entered.current())) }) .ok()? } @@ -764,6 +724,38 @@ impl State { EXISTS.store(true, Ordering::Release); DefaultGuard(prior) } + + #[inline] + fn enter(&self) -> Option> { + if self.can_enter.replace(false) { + Some(Entered(&self)) + } else { + None + } + } +} + +impl<'a> Entered<'a> { + #[inline] + fn current(&self) -> RefMut<'a, Dispatch> { + let mut default = self.0.default.borrow_mut(); + + if default.is::() { + if let Some(global) = get_global() { + // don't redo this call on the next check + *default = global.clone(); + } + } + + default + } +} + +impl<'a> Drop for Entered<'a> { + #[inline] + fn drop(&mut self) { + self.0.can_enter.set(true); + } } // ===== impl DefaultGuard ===== From 4a52a1225c1bd6b3abfd04a2fdc158f1708fc683 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 20 Aug 2020 10:21:52 -0700 Subject: [PATCH 6/9] fix whitespace Signed-off-by: Eliza Weisman --- Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Cargo.toml b/Cargo.toml index a1ee84b90c..79b600dbfb 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -16,4 +16,4 @@ members = [ "tracing-appender", "tracing-journald", "examples" -] \ No newline at end of file +] From ec438887758b021ffd7f164123c017d42ecb18bc Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 20 Aug 2020 10:25:37 -0700 Subject: [PATCH 7/9] fix nostd Signed-off-by: Eliza Weisman --- tracing-core/src/dispatcher.rs | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 500874070f..658463584e 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -193,9 +193,10 @@ struct State { can_enter: Cell, } -// While this guard is active, additional calls to subscriber functions on -// the default dispatcher will not be able to access the dispatch context. -// Dropping the guard will allow the dispatch context to be re-entered. +/// While this guard is active, additional calls to subscriber functions on +/// the default dispatcher will not be able to access the dispatch context. +/// Dropping the guard will allow the dispatch context to be re-entered. +#[cfg(feature = "std")] struct Entered<'a>(&'a State); /// A guard that resets the current default dispatcher to the prior @@ -735,6 +736,9 @@ impl State { } } +// ===== impl Entered ===== + +#[cfg(feature = "std")] impl<'a> Entered<'a> { #[inline] fn current(&self) -> RefMut<'a, Dispatch> { @@ -751,6 +755,7 @@ impl<'a> Entered<'a> { } } +#[cfg(feature = "std")] impl<'a> Drop for Entered<'a> { #[inline] fn drop(&mut self) { From 9d458e22a2a9cd550ed319595947b97ab02ba17d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 21 Aug 2020 10:16:49 -0700 Subject: [PATCH 8/9] bump core version (tracing depends on new APIs) Signed-off-by: Eliza Weisman --- tracing-core/CHANGELOG.md | 6 ++++++ tracing-core/Cargo.toml | 2 +- tracing/Cargo.toml | 2 +- 3 files changed, 8 insertions(+), 2 deletions(-) diff --git a/tracing-core/CHANGELOG.md b/tracing-core/CHANGELOG.md index dea419a313..ca801d04b0 100644 --- a/tracing-core/CHANGELOG.md +++ b/tracing-core/CHANGELOG.md @@ -1,3 +1,9 @@ +# Unreleased + +## Added + +- Internal API changes to support optimizations in the `tracing` crate (#943) + # 0.1.14 (August 10, 2020) ### Fixed diff --git a/tracing-core/Cargo.toml b/tracing-core/Cargo.toml index ae6306d3fb..5077f3fc83 100644 --- a/tracing-core/Cargo.toml +++ b/tracing-core/Cargo.toml @@ -8,7 +8,7 @@ name = "tracing-core" # - README.md # - Update CHANGELOG.md. # - Create "v0.1.x" git tag. -version = "0.1.14" +version = "0.1.15" authors = ["Tokio Contributors "] license = "MIT" readme = "README.md" diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index a16f0e5c50..fd315621cb 100644 --- a/tracing/Cargo.toml +++ b/tracing/Cargo.toml @@ -27,7 +27,7 @@ keywords = ["logging", "tracing", "metrics", "async"] edition = "2018" [dependencies] -tracing-core = { path = "../tracing-core", version = "0.1.14", default-features = false } +tracing-core = { path = "../tracing-core", version = "0.1.15", default-features = false } log = { version = "0.4", optional = true } tracing-attributes = { path = "../tracing-attributes", version = "0.1.10", optional = true } cfg-if = "0.1.10" From 248c7d292bb8acb456ab5c52d991ddeab36c7ba8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 21 Aug 2020 13:07:48 -0700 Subject: [PATCH 9/9] Update tracing/src/lib.rs Co-authored-by: Lucio Franco --- tracing/src/lib.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 0b91f1ba05..dfd3d1baa7 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -966,6 +966,7 @@ pub mod __macro_support { _ => Interest::sometimes(), } } + /// Returns the callsite's cached Interest, or registers it for the /// first time if it has not yet been registered. ///