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-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 9a6048bc1b..658463584e 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,12 @@ 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. +#[cfg(feature = "std")] +struct Entered<'a>(&'a State); + /// A guard that resets the current default dispatcher to the prior /// default dispatcher when dropped. #[cfg(feature = "std")] @@ -325,38 +331,46 @@ 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())) } +/// 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)] +#[inline(never)] +pub fn get_current(f: impl FnOnce(&Dispatch) -> T) -> Option { + CURRENT_STATE + .try_with(|state| { + let entered = state.enter()?; + Some(f(&*entered.current())) + }) + .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 @@ -711,6 +725,42 @@ 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 Entered ===== + +#[cfg(feature = "std")] +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 + } +} + +#[cfg(feature = "std")] +impl<'a> Drop for Entered<'a> { + #[inline] + fn drop(&mut self) { + self.0.can_enter.set(true); + } } // ===== impl DefaultGuard ===== 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" diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 1aade9a666..99c81ca852 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -916,9 +916,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. @@ -947,15 +947,15 @@ 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`. + /// Registers this callsite with the global callsite registry. + /// + /// If the callsite is already registered, this does nothing. /// /// /!\ WARNING: This is *not* a stable API! /!\ /// This method, and all code contained in the `__macro_support` module, is @@ -963,22 +963,21 @@ 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 { - let interest = self.interest(); - if interest.is_always() { - return true; - } - if interest.is_never() { - return false; + #[inline(never)] + // This only happens once (or if the cached interest value was corrupted). + #[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(), } - - 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. + /// 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 @@ -986,20 +985,53 @@ 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) { - self.registration - .call_once(|| crate::callsite::register(self)); - } - - #[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(), } } + + 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] + #[cfg(feature = "log")] + pub fn disabled_span(&self) -> crate::Span { + crate::Span::new_disabled(self.meta) + } + + #[inline] + #[cfg(not(feature = "log"))] + pub fn disabled_span(&self) -> crate::Span { + crate::Span::none() + } + + 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); + } + 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..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,) @@ -538,7 +592,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 +604,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 +636,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 +648,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 +1863,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)] @@ -2060,124 +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::*; - let callsite = $crate::callsite! { - 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)*), - ) - } 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::*; - let callsite = $crate::callsite! { - 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)*), - ) - } 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] 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