From 45a5df13735ede10475a91ffd0cc063a8a512629 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 22 Apr 2022 09:11:08 -0700 Subject: [PATCH] core: add a limited form of the linked-list callsite registry for v0.1.x (#2083) ## Motivation Currently on `v0.1.x`, the global callsite registry is implemented as a `Mutex>`. This has a few downsides: * Every time a callsite is registered, the `Mutex` must be locked. This can cause a deadlock when a `register_callsite` implementation calls into code that _also_ registers a callsite. See #2020 for details. * Registering callsites is relatively slow and forces the program to synchronize on the callsite registry (and not on *individual* callsites). This means that if two threads are both registering totally different callsites, both threads must wait for the lock. Although this overhead is amortized over the entire rest of the program, it does have an impact in short-running applications where any given callsite may only be hit once or twice. * Memory allocation may occur while the registry is locked. This makes the use of `tracing` inside of memory allocators difficult or impossible. On the `master` branch (v0.2.x), PR #988 rewrote the callsite registry to use an intrusive atomic singly-linked list of `Callsite`s. This removed the need for locking the callsite registry, and made it possible to register callsites without ever allocating memory. Because the callsite registry on v0.2 will *never* allocate, this also makes it possible to compile `tracing-core` for `no_std` platforms without requiring `liballoc`. Unfortunately, however, we cannot use an identical implementation on v0.1.x, because using the intrusive linked-list registry for *all* callsites requires a breaking change to the `Callsite` trait (in order to add a way to get the callsite's linked-list node), which we cannot make on v0.1.x. ## Solution This branch adds a linked-list callsite registry for v0.1.x in a way that allows us to benefit from *some* of the advantages of this approach in a majority of cases. The trick is introducing a new `DefaultCallsite` type in `tracing-core` that implements the `Callsite` trait. This type can contain an intrusive list node, and *when a callsite is a `DefaultCallsite`*, we can register it without having to push it to the `Mutex>`. The locked vec still _exists_, for `Callsite`s that are *not* `DefaultCallsite`s, so we can't remove the `liballoc` dependency, but in most cases, we can avoid the mutex and allocation. Naturally, `tracing` has been updated to use the `DefaultCallsite` type from `tracing-core`, so the `Vec` will only be used in the following cases: * User code has a custom implementation of the `Callsite` trait, which is [not terribly common][1]. * An older version of the `tracing` crate is in use. This fixes the deadlock described in #2020 when `DefaultCallsite`s are used. Additionally, it should reduce the performance impact and memory usage of the callsite registry. Furthermore, I've changed the subscriber registry so that a `RwLock>` is only used when there actually are multiple subscribers in use. When there's only a global default subscriber, we can once again avoid locking for the registry of subscribers. When the `std` feature is disabled, thread-local scoped dispatchers are unavailable, so the single global subscriber will always be used on `no_std`. We can make additional changes, such as the ones from #2020, to _also_ resolve potential deadlocks when non-default callsites are in use, but since this branch rewrites a lot of the callsite registry code, that should probably be done in a follow-up. [1]: https://cs.github.com/?scopeName=All+repos&scope=&q=%28%2Fimpl+.*Callsite%2F+AND+language%3Arust%29+NOT+%28path%3A%2Ftracing%2F**+OR+path%3A%2Ftracing-*%2F**+OR+path%3A%2Ftokio-trace*%2F**%29%29 Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 455 +++++++++++++++++--- tracing-core/src/dispatcher.rs | 13 +- tracing-mock/src/subscriber.rs | 2 + tracing/Cargo.toml | 2 +- tracing/src/lib.rs | 189 +++----- tracing/src/macros.rs | 35 +- tracing/tests/register_callsite_deadlock.rs | 47 ++ 7 files changed, 517 insertions(+), 226 deletions(-) create mode 100644 tracing/tests/register_callsite_deadlock.rs diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 38ff14a2f0..273fecec4e 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -1,74 +1,23 @@ //! Callsites represent the source locations from which spans or events //! originate. use crate::stdlib::{ + any::TypeId, fmt, hash::{Hash, Hasher}, - sync::Mutex, + ptr, + sync::{ + atomic::{AtomicBool, AtomicPtr, AtomicU8, Ordering}, + Mutex, + }, vec::Vec, }; use crate::{ - dispatcher::{self, Dispatch}, + dispatcher::Dispatch, metadata::{LevelFilter, Metadata}, subscriber::Interest, }; -crate::lazy_static! { - static ref REGISTRY: Mutex = Mutex::new(Registry { - callsites: Vec::new(), - dispatchers: Vec::new(), - }); -} - -struct Registry { - callsites: Vec<&'static dyn Callsite>, - dispatchers: Vec, -} - -impl Registry { - fn rebuild_callsite_interest(&self, callsite: &'static dyn Callsite) { - let meta = callsite.metadata(); - - // Iterate over the subscribers in the registry, and — if they are - // active — register the callsite with them. - let mut interests = self - .dispatchers - .iter() - .filter_map(|registrar| registrar.try_register(meta)); - - // Use the first subscriber's `Interest` as the base value. - let interest = if let Some(interest) = interests.next() { - // Combine all remaining `Interest`s. - interests.fold(interest, Interest::and) - } else { - // If nobody was interested in this thing, just return `never`. - Interest::never() - }; - - callsite.set_interest(interest) - } - - fn rebuild_interest(&mut self) { - let mut max_level = LevelFilter::OFF; - self.dispatchers.retain(|registrar| { - if let Some(dispatch) = registrar.upgrade() { - // If the subscriber did not provide a max level hint, assume - // that it may enable every level. - let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE); - if level_hint > max_level { - max_level = level_hint; - } - true - } else { - false - } - }); - - self.callsites.iter().for_each(|&callsite| { - self.rebuild_callsite_interest(callsite); - }); - LevelFilter::set_max(max_level); - } -} +use self::dispatchers::Dispatchers; /// Trait implemented by callsites. /// @@ -84,6 +33,28 @@ pub trait Callsite: Sync { /// /// [metadata]: super::metadata::Metadata fn metadata(&self) -> &Metadata<'_>; + + /// This method is an *internal implementation detail* of `tracing-core`. It + /// is *not* intended to be called or overridden from downstream code. + /// + /// The `Private` type can only be constructed from within `tracing-core`. + /// Because this method takes a `Private` as an argument, it cannot be + /// called from (safe) code external to `tracing-core`. Because it must + /// *return* a `Private`, the only valid implementation possible outside of + /// `tracing-core` would have to always unconditionally panic. + /// + /// THIS IS BY DESIGN. There is currently no valid reason for code outside + /// of `tracing-core` to override this method. + // TODO(eliza): this could be used to implement a public downcasting API + // for `&dyn Callsite`s in the future. + #[doc(hidden)] + #[inline] + fn private_type_id(&self, _: private::Private<()>) -> private::Private + where + Self: 'static, + { + private::Private(TypeId::of::()) + } } /// Uniquely identifies a [`Callsite`] @@ -104,6 +75,15 @@ pub struct Identifier( pub &'static dyn Callsite, ); +/// A default [`Callsite`] implementation. +#[derive(Debug)] +pub struct DefaultCallsite { + interest: AtomicU8, + registration: AtomicU8, + meta: &'static Metadata<'static>, + next: AtomicPtr, +} + /// Clear and reregister interest on every [`Callsite`] /// /// This function is intended for runtime reconfiguration of filters on traces @@ -124,8 +104,7 @@ pub struct Identifier( /// [`Interest::sometimes()`]: super::subscriber::Interest::sometimes /// [`Subscriber`]: super::subscriber::Subscriber pub fn rebuild_interest_cache() { - let mut registry = REGISTRY.lock().unwrap(); - registry.rebuild_interest(); + CALLSITES.rebuild_interest(DISPATCHERS.rebuilder()); } /// Register a new `Callsite` with the global registry. @@ -133,15 +112,137 @@ pub fn rebuild_interest_cache() { /// This should be called once per callsite after the callsite has been /// constructed. pub fn register(callsite: &'static dyn Callsite) { - let mut registry = REGISTRY.lock().unwrap(); - registry.rebuild_callsite_interest(callsite); - registry.callsites.push(callsite); + rebuild_callsite_interest(callsite, &DISPATCHERS.rebuilder()); + + // Is this a `DefaultCallsite`? If so, use the fancy linked list! + if callsite.private_type_id(private::Private(())).0 == TypeId::of::() { + let callsite = unsafe { + // Safety: the pointer cast is safe because the type id of the + // provided callsite matches that of the target type for the cast + // (`DefaultCallsite`). Because user implementations of `Callsite` + // cannot override `private_type_id`, we can trust that the callsite + // is not lying about its type ID. + &*(callsite as *const dyn Callsite as *const DefaultCallsite) + }; + CALLSITES.push_default(callsite); + return; + } + + CALLSITES.push_dyn(callsite); } -pub(crate) fn register_dispatch(dispatch: &Dispatch) { - let mut registry = REGISTRY.lock().unwrap(); - registry.dispatchers.push(dispatch.registrar()); - registry.rebuild_interest(); +static CALLSITES: Callsites = Callsites { + list_head: AtomicPtr::new(ptr::null_mut()), + has_locked_callsites: AtomicBool::new(false), +}; + +static DISPATCHERS: Dispatchers = Dispatchers::new(); + +crate::lazy_static! { + static ref LOCKED_CALLSITES: Mutex> = Mutex::new(Vec::new()); +} + +struct Callsites { + list_head: AtomicPtr, + has_locked_callsites: AtomicBool, +} + +// === impl DefaultCallsite === + +impl DefaultCallsite { + const UNREGISTERED: u8 = 0; + const REGISTERING: u8 = 1; + const REGISTERED: u8 = 2; + + const INTEREST_NEVER: u8 = 0; + const INTEREST_SOMETIMES: u8 = 1; + const INTEREST_ALWAYS: u8 = 2; + + /// Returns a new `DefaultCallsite` with the specified `Metadata`. + pub const fn new(meta: &'static Metadata<'static>) -> Self { + Self { + interest: AtomicU8::new(0xFF), + meta, + next: AtomicPtr::new(ptr::null_mut()), + registration: AtomicU8::new(Self::UNREGISTERED), + } + } + + /// Registers this callsite with the global callsite registry. + /// + /// If the callsite is already registered, this does nothing. When using + /// [`DefaultCallsite`], this method should be preferred over + /// [`tracing_core::callsite::register`], as it ensures that the callsite is + /// only registered a single time. + /// + /// Other callsite implementations will generally ensure that + /// callsites are not re-registered through another mechanism. + #[inline(never)] + // This only happens once (or if the cached interest value was corrupted). + #[cold] + pub fn register(&'static self) -> Interest { + // Attempt to advance the registration state to `REGISTERING`... + match self.registration.compare_exchange( + Self::UNREGISTERED, + Self::REGISTERING, + Ordering::AcqRel, + Ordering::Acquire, + ) { + Ok(_) => { + // Okay, we advanced the state, try to register the callsite. + rebuild_callsite_interest(self, &DISPATCHERS.rebuilder()); + CALLSITES.push_default(self); + self.registration.store(Self::REGISTERED, Ordering::Release); + } + // Great, the callsite is already registered! Just load its + // previous cached interest. + Err(Self::REGISTERED) => {} + // Someone else is registering... + Err(_state) => { + debug_assert_eq!( + _state, + Self::REGISTERING, + "weird callsite registration state" + ); + // Just hit `enabled` this time. + return Interest::sometimes(); + } + } + + match self.interest.load(Ordering::Relaxed) { + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_ALWAYS => Interest::always(), + _ => Interest::sometimes(), + } + } + + /// Returns the callsite's cached `Interest`, or registers it for the + /// first time if it has not yet been registered. + #[inline] + pub fn interest(&'static self) -> Interest { + match self.interest.load(Ordering::Relaxed) { + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_SOMETIMES => Interest::sometimes(), + Self::INTEREST_ALWAYS => Interest::always(), + _ => self.register(), + } + } +} + +impl Callsite for DefaultCallsite { + fn set_interest(&self, interest: Interest) { + let interest = match () { + _ if interest.is_never() => Self::INTEREST_NEVER, + _ if interest.is_always() => Self::INTEREST_ALWAYS, + _ => Self::INTEREST_SOMETIMES, + }; + self.interest.store(interest, Ordering::SeqCst); + } + + #[inline(always)] + fn metadata(&self) -> &Metadata<'static> { + self.meta + } } // ===== impl Identifier ===== @@ -171,3 +272,221 @@ impl Hash for Identifier { (self.0 as *const dyn Callsite).hash(state) } } + +// === impl Callsites === + +impl Callsites { + /// Rebuild `Interest`s for all callsites in the registry. + /// + /// This also re-computes the max level hint. + fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) { + let mut max_level = LevelFilter::OFF; + dispatchers.for_each(|dispatch| { + // If the subscriber did not provide a max level hint, assume + // that it may enable every level. + let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE); + if level_hint > max_level { + max_level = level_hint; + } + }); + + self.for_each(|callsite| { + rebuild_callsite_interest(callsite, &dispatchers); + }); + LevelFilter::set_max(max_level); + } + + /// Push a `dyn Callsite` trait object to the callsite registry. + /// + /// This will attempt to lock the callsites vector. + fn push_dyn(&self, callsite: &'static dyn Callsite) { + let mut lock = LOCKED_CALLSITES.lock().unwrap(); + self.has_locked_callsites.store(true, Ordering::Release); + lock.push(callsite); + } + + /// Push a `DefaultCallsite` to the callsite registry. + /// + /// If we know the callsite being pushed is a `DefaultCallsite`, we can push + /// it to the linked list without having to acquire a lock. + fn push_default(&self, callsite: &'static DefaultCallsite) { + let mut head = self.list_head.load(Ordering::Acquire); + + loop { + callsite.next.store(head, Ordering::Release); + + assert_ne!( + callsite as *const _, head, + "Attempted to register a `DefaultCallsite` that already exists! \ + This will cause an infinite loop when attempting to read from the \ + callsite cache. This is likely a bug! You should only need to call \ + `DefaultCallsite::register` once per `DefaultCallsite`." + ); + + match self.list_head.compare_exchange( + head, + callsite as *const _ as *mut _, + Ordering::AcqRel, + Ordering::Acquire, + ) { + Ok(_) => { + break; + } + Err(current) => head = current, + } + } + } + + /// Invokes the provided closure `f` with each callsite in the registry. + fn for_each(&self, mut f: impl FnMut(&'static dyn Callsite)) { + let mut head = self.list_head.load(Ordering::Acquire); + + while let Some(cs) = unsafe { head.as_ref() } { + f(cs); + + head = cs.next.load(Ordering::Acquire); + } + + if self.has_locked_callsites.load(Ordering::Acquire) { + let locked = LOCKED_CALLSITES.lock().unwrap(); + for &cs in locked.iter() { + f(cs); + } + } + } +} + +pub(crate) fn register_dispatch(dispatch: &Dispatch) { + let dispatchers = DISPATCHERS.register_dispatch(dispatch); + CALLSITES.rebuild_interest(dispatchers); +} + +fn rebuild_callsite_interest( + callsite: &'static dyn Callsite, + dispatchers: &dispatchers::Rebuilder<'_>, +) { + let meta = callsite.metadata(); + + let mut interest = None; + dispatchers.for_each(|dispatch| { + let this_interest = dispatch.register_callsite(meta); + interest = match interest.take() { + None => Some(this_interest), + Some(that_interest) => Some(that_interest.and(this_interest)), + } + }); + + let interest = interest.unwrap_or_else(Interest::never); + callsite.set_interest(interest) +} + +mod private { + /// Don't call this function, it's private. + #[allow(missing_debug_implementations)] + pub struct Private(pub(crate) T); +} + +#[cfg(feature = "std")] +mod dispatchers { + use crate::dispatcher; + use std::sync::{ + atomic::{AtomicBool, Ordering}, + RwLock, RwLockReadGuard, RwLockWriteGuard, + }; + + pub(super) struct Dispatchers { + has_just_one: AtomicBool, + } + + crate::lazy_static! { + static ref LOCKED_DISPATCHERS: RwLock> = RwLock::new(Vec::new()); + } + + pub(super) enum Rebuilder<'a> { + JustOne, + Read(RwLockReadGuard<'a, Vec>), + Write(RwLockWriteGuard<'a, Vec>), + } + + impl Dispatchers { + pub(super) const fn new() -> Self { + Self { + has_just_one: AtomicBool::new(true), + } + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + if self.has_just_one.load(Ordering::SeqCst) { + return Rebuilder::JustOne; + } + Rebuilder::Read(LOCKED_DISPATCHERS.read().unwrap()) + } + + pub(super) fn register_dispatch(&self, dispatch: &dispatcher::Dispatch) -> Rebuilder<'_> { + let mut dispatchers = LOCKED_DISPATCHERS.write().unwrap(); + dispatchers.retain(|d| d.upgrade().is_some()); + dispatchers.push(dispatch.registrar()); + self.has_just_one + .store(dispatchers.len() <= 1, Ordering::SeqCst); + Rebuilder::Write(dispatchers) + } + } + + impl Rebuilder<'_> { + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + let iter = match self { + Rebuilder::JustOne => { + dispatcher::get_default(f); + return; + } + Rebuilder::Read(vec) => vec.iter(), + Rebuilder::Write(vec) => vec.iter(), + }; + iter.filter_map(dispatcher::Registrar::upgrade) + .for_each(|dispatch| f(&dispatch)) + } + } +} + +#[cfg(not(feature = "std"))] +mod dispatchers { + use crate::dispatcher; + + pub(super) struct Dispatchers(()); + pub(super) struct Rebuilder<'a>(Option<&'a dispatcher::Dispatch>); + + impl Dispatchers { + pub(super) const fn new() -> Self { + Self(()) + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + Rebuilder(None) + } + + pub(super) fn register_dispatch<'dispatch>( + &self, + dispatch: &'dispatch dispatcher::Dispatch, + ) -> Rebuilder<'dispatch> { + // nop; on no_std, there can only ever be one dispatcher + Rebuilder(Some(dispatch)) + } + } + + impl Rebuilder<'_> { + #[inline] + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + if let Some(dispatch) = self.0 { + // we are rebuilding the interest cache because a new dispatcher + // is about to be set. on `no_std`, this should only happen + // once, because the new dispatcher will be the global default. + f(dispatch) + } else { + // otherwise, we are rebuilding the cache because the subscriber + // configuration changed, so use the global default. + // on no_std, there can only ever be one dispatcher + dispatcher::get_default(f) + } + } + } +} diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index d6b5c6e6a1..741744437c 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -134,7 +134,7 @@ use crate::stdlib::{ fmt, sync::{ atomic::{AtomicBool, AtomicUsize, Ordering}, - Arc, Weak, + Arc, }, }; @@ -142,6 +142,7 @@ use crate::stdlib::{ use crate::stdlib::{ cell::{Cell, RefCell, RefMut}, error, + sync::Weak, }; /// `Dispatch` trace data to a [`Subscriber`]. @@ -387,6 +388,7 @@ fn get_global() -> Option<&'static Dispatch> { } } +#[cfg(feature = "std")] pub(crate) struct Registrar(Weak); impl Dispatch { @@ -412,6 +414,7 @@ impl Dispatch { me } + #[cfg(feature = "std")] pub(crate) fn registrar(&self) -> Registrar { Registrar(Arc::downgrade(&self.subscriber)) } @@ -651,14 +654,8 @@ where } } +#[cfg(feature = "std")] impl Registrar { - pub(crate) fn try_register( - &self, - metadata: &'static Metadata<'static>, - ) -> Option { - self.0.upgrade().map(|s| s.register_callsite(metadata)) - } - pub(crate) fn upgrade(&self) -> Option { self.0.upgrade().map(|subscriber| Dispatch { subscriber }) } diff --git a/tracing-mock/src/subscriber.rs b/tracing-mock/src/subscriber.rs index 8fbffbb396..17e1a7ed73 100644 --- a/tracing-mock/src/subscriber.rs +++ b/tracing-mock/src/subscriber.rs @@ -198,7 +198,9 @@ where Interest::never() } } + fn max_level_hint(&self) -> Option { + println!("[{}] max_level_hint -> {:?}", self.name, self.max_level); self.max_level } diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index 4f5e1deccf..558fd3332b 100644 --- a/tracing/Cargo.toml +++ b/tracing/Cargo.toml @@ -28,7 +28,7 @@ edition = "2018" rust-version = "1.49.0" [dependencies] -tracing-core = { path = "../tracing-core", version = "0.1.22", default-features = false } +tracing-core = { path = "../tracing-core", version = "0.1.26", default-features = false } log = { version = "0.4", optional = true } tracing-attributes = { path = "../tracing-attributes", version = "0.1.20", optional = true } cfg-if = "1.0.0" diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index f9c0669cb9..fdd12bd3eb 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -967,13 +967,8 @@ pub mod subscriber; #[doc(hidden)] pub mod __macro_support { pub use crate::callsite::Callsite; - use crate::stdlib::{ - fmt, - sync::atomic::{AtomicUsize, Ordering}, - }; use crate::{subscriber::Interest, Metadata}; pub use core::concat; - use tracing_core::Once; /// Callsite implementation used by macro-generated code. /// @@ -983,138 +978,70 @@ 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. - pub struct MacroCallsite { - interest: AtomicUsize, - meta: &'static Metadata<'static>, - registration: Once, - } - - impl MacroCallsite { - /// Returns a new `MacroCallsite` with the specified `Metadata`. - /// - /// /!\ 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 const fn new(meta: &'static Metadata<'static>) -> Self { - Self { - interest: AtomicUsize::new(0xDEAD), - meta, - registration: Once::new(), - } - } - - /// 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 - /// 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(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(), - } - } - - /// 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) { - 0 => Interest::never(), - 1 => Interest::sometimes(), - 2 => Interest::always(), - _ => self.register(), - } - } - - pub fn is_enabled(&self, interest: Interest) -> bool { - interest.is_always() - || crate::dispatcher::get_default(|default| default.enabled(self.meta)) - } - - #[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 use tracing_core::callsite::DefaultCallsite as MacroCallsite; - #[cfg(feature = "log")] - pub fn log( - &self, - logger: &'static dyn log::Log, - log_meta: log::Metadata<'_>, - values: &tracing_core::field::ValueSet<'_>, - ) { - let meta = self.metadata(); - logger.log( - &crate::log::Record::builder() - .file(meta.file()) - .module_path(meta.module_path()) - .line(meta.line()) - .metadata(log_meta) - .args(format_args!( - "{}", - crate::log::LogValueSet { - values, - is_first: true - } - )) - .build(), - ); - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, 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(meta: &Metadata<'static>, interest: Interest) -> bool { + interest.is_always() || crate::dispatcher::get_default(|default| default.enabled(meta)) } - impl Callsite for MacroCallsite { - fn set_interest(&self, interest: Interest) { - let interest = match () { - _ if interest.is_never() => 0, - _ if interest.is_always() => 2, - _ => 1, - }; - self.interest.store(interest, Ordering::SeqCst); - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, 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] + #[cfg(feature = "log")] + pub fn __disabled_span(meta: &'static Metadata<'static>) -> crate::Span { + crate::Span::new_disabled(meta) + } - #[inline(always)] - fn metadata(&self) -> &Metadata<'static> { - self.meta - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, 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] + #[cfg(not(feature = "log"))] + pub fn __disabled_span(_: &'static Metadata<'static>) -> crate::Span { + crate::Span::none() } - impl fmt::Debug for MacroCallsite { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("MacroCallsite") - .field("interest", &self.interest) - .field("meta", &self.meta) - .field("registration", &self.registration) - .finish() - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, 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. + #[cfg(feature = "log")] + pub fn __tracing_log( + meta: &Metadata<'static>, + logger: &'static dyn log::Log, + log_meta: log::Metadata<'_>, + values: &tracing_core::field::ValueSet<'_>, + ) { + logger.log( + &crate::log::Record::builder() + .file(meta.file()) + .module_path(meta.module_path()) + .line(meta.line()) + .metadata(log_meta) + .args(format_args!( + "{}", + crate::log::LogValueSet { + values, + is_first: true + } + )) + .build(), + ); } } diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 825c0d8689..bca42933b3 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -24,7 +24,7 @@ macro_rules! span { (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, @@ -34,7 +34,7 @@ macro_rules! span { let mut interest = $crate::subscriber::Interest::never(); if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() } - && CALLSITE.is_enabled(interest) + && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); // span with explicit parent @@ -44,7 +44,7 @@ macro_rules! span { &$crate::valueset!(meta.fields(), $($fields)*), ) } else { - let span = CALLSITE.disabled_span(); + let span = $crate::__macro_support::__disabled_span(CALLSITE.metadata()); $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; @@ -55,7 +55,7 @@ macro_rules! span { (target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, @@ -65,7 +65,7 @@ macro_rules! span { let mut interest = $crate::subscriber::Interest::never(); if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() } - && CALLSITE.is_enabled(interest) + && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); // span with contextual parent @@ -74,7 +74,7 @@ macro_rules! span { &$crate::valueset!(meta.fields(), $($fields)*), ) } else { - let span = CALLSITE.disabled_span(); + let span = $crate::__macro_support::__disabled_span(CALLSITE.metadata()); $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; @@ -584,7 +584,7 @@ macro_rules! error_span { macro_rules! event { (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "event ", file!(), @@ -599,7 +599,7 @@ macro_rules! event { let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - !interest.is_never() && CALLSITE.is_enabled(interest) + !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) }; if enabled { (|value_set: $crate::field::ValueSet| { @@ -641,7 +641,7 @@ macro_rules! event { ); (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "event ", file!(), @@ -655,7 +655,7 @@ macro_rules! event { }; let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - !interest.is_never() && CALLSITE.is_enabled(interest) + !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) }; if enabled { (|value_set: $crate::field::ValueSet| { @@ -965,7 +965,7 @@ macro_rules! enabled { (kind: $kind:expr, target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ if $crate::level_enabled!($lvl) { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "enabled ", file!(), @@ -978,7 +978,7 @@ macro_rules! enabled { fields: $($fields)* }; let interest = CALLSITE.interest(); - if !interest.is_never() && CALLSITE.is_enabled(interest) { + if !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); $crate::dispatcher::get_default(|current| current.enabled(meta)) } else { @@ -2096,7 +2096,6 @@ macro_rules! callsite { level: $lvl:expr, fields: $($fields:tt)* ) => {{ - use $crate::__macro_support::MacroCallsite; static META: $crate::Metadata<'static> = { $crate::metadata! { name: $name, @@ -2107,7 +2106,7 @@ macro_rules! callsite { kind: $kind, } }; - static CALLSITE: MacroCallsite = MacroCallsite::new(&META); + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite::DefaultCallsite::new(&META); CALLSITE.register(); &CALLSITE }}; @@ -2147,7 +2146,6 @@ macro_rules! callsite2 { level: $lvl:expr, fields: $($fields:tt)* ) => {{ - use $crate::__macro_support::MacroCallsite; static META: $crate::Metadata<'static> = { $crate::metadata! { name: $name, @@ -2158,7 +2156,7 @@ macro_rules! callsite2 { kind: $kind, } }; - MacroCallsite::new(&META) + $crate::callsite::DefaultCallsite::new(&META) }}; } @@ -2428,13 +2426,14 @@ macro_rules! __tracing_log { use $crate::log; let level = $crate::level_to_log!($level); if level <= log::max_level() { + let meta = $callsite.metadata(); let log_meta = log::Metadata::builder() .level(level) - .target(CALLSITE.metadata().target()) + .target(meta.target()) .build(); let logger = log::logger(); if logger.enabled(&log_meta) { - $callsite.log(logger, log_meta, $value_set) + $crate::__macro_support::__tracing_log(meta, logger, log_meta, $value_set) } } }} diff --git a/tracing/tests/register_callsite_deadlock.rs b/tracing/tests/register_callsite_deadlock.rs new file mode 100644 index 0000000000..e4c116c75f --- /dev/null +++ b/tracing/tests/register_callsite_deadlock.rs @@ -0,0 +1,47 @@ +use std::{sync::mpsc, thread, time::Duration}; +use tracing::{ + metadata::Metadata, + span, + subscriber::{self, Interest, Subscriber}, + Event, +}; + +#[test] +fn register_callsite_doesnt_deadlock() { + pub struct EvilSubscriber; + + impl Subscriber for EvilSubscriber { + fn register_callsite(&self, meta: &'static Metadata<'static>) -> Interest { + tracing::info!(?meta, "registered a callsite"); + Interest::always() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + true + } + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + } + + subscriber::set_global_default(EvilSubscriber).unwrap(); + + // spawn a thread, and assert it doesn't hang... + let (tx, didnt_hang) = mpsc::channel(); + let th = thread::spawn(move || { + tracing::info!("hello world!"); + tx.send(()).unwrap(); + }); + + didnt_hang + // Note: 60 seconds is *way* more than enough, but let's be generous in + // case of e.g. slow CI machines. + .recv_timeout(Duration::from_secs(60)) + .expect("the thread must not have hung!"); + th.join().expect("thread should join successfully"); +}