From 2209bcaef65a0d512bc41ea8c6e98167f5c428c2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 24 Mar 2022 11:49:18 -0700 Subject: [PATCH 01/12] tracing: test reproducing register_callsite deadlock Signed-off-by: Eliza Weisman --- tracing/tests/register_callsite_deadlock.rs | 47 +++++++++++++++++++++ 1 file changed, 47 insertions(+) create mode 100644 tracing/tests/register_callsite_deadlock.rs 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"); +} From dff2fa4b6ddee6402015a1c30696a2069fc774cd Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 24 Mar 2022 14:19:02 -0700 Subject: [PATCH 02/12] crazy idea that might even work... Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 313 +++++++++++++++++++++++++++++------ 1 file changed, 265 insertions(+), 48 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index d0acae41de..3511d9bbba 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -3,71 +3,219 @@ use crate::stdlib::{ fmt, hash::{Hash, Hasher}, - sync::Mutex, + ptr, + sync::{ + atomic::{AtomicBool, AtomicPtr, AtomicUsize, Ordering}, + Mutex, + }, vec::Vec, }; use crate::{ - dispatcher::{self, Dispatch}, + dispatcher::Dispatch, metadata::{LevelFilter, Metadata}, subscriber::Interest, + Once, }; +use self::dispatchers::Dispatchers; + crate::lazy_static! { - static ref REGISTRY: Mutex = Mutex::new(Registry { - callsites: Vec::new(), - dispatchers: Vec::new(), - }); + static ref CALLSITES: Callsites = Callsites { + list_head: AtomicPtr::new(ptr::null_mut()), + has_locked_callsites: AtomicBool::new(false), + locked_callsites: Mutex::new(Vec::new()), + }; + + static ref DISPATCHERS: Dispatchers = Dispatchers::new(); +} + +struct Callsites { + list_head: AtomicPtr, + has_locked_callsites: AtomicBool, + locked_callsites: Mutex>, } -struct Registry { - callsites: Vec<&'static dyn Callsite>, - dispatchers: Vec, +/// A default [`Callsite`] implementation. +pub struct DefaultCallsite { + interest: AtomicUsize, + meta: &'static Metadata<'static>, + next: AtomicPtr, + registration: Once, } -impl Registry { - fn rebuild_callsite_interest(&self, callsite: &'static dyn Callsite) { - let meta = callsite.metadata(); +impl DefaultCallsite { + /// Returns a new `DefaultCallsite` with the specified `Metadata`. + pub const fn new(meta: &'static Metadata<'static>) -> Self { + Self { + interest: AtomicUsize::new(0xDEADFACED), + meta, + next: AtomicPtr::new(ptr::null_mut()), + 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(|| { + rebuild_callsite_interest(self, &DISPATCHERS.rebuilder()); + CALLSITES.push_default(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(), + } + } - // 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)); + pub fn is_enabled(&self, interest: Interest) -> bool { + interest.is_always() || crate::dispatcher::get_default(|default| default.enabled(self.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() +impl Callsite for DefaultCallsite { + 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); + } + + #[inline(always)] + fn metadata(&self) -> &Metadata<'static> { + self.meta + } +} - callsite.set_interest(interest) +impl fmt::Debug for DefaultCallsite { + 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() } +} + +impl Callsites { + 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); - fn rebuild_interest(&mut self) { + head = cs.next.load(Ordering::Acquire); + } + + if self.has_locked_callsites.load(Ordering::Acquire) { + let locked = self.locked_callsites.lock().unwrap(); + for &cs in locked.iter() { + f(cs); + } + } + } + + fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) { 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 + 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.callsites.iter().for_each(|&callsite| { - self.rebuild_callsite_interest(callsite); + self.for_each(|callsite| { + rebuild_callsite_interest(callsite, &dispatchers); }); LevelFilter::set_max(max_level); } + + fn push_dyn(&self, callsite: &'static dyn Callsite) { + let mut lock = self.locked_callsites.lock().unwrap(); + self.has_locked_callsites.store(true, Ordering::Release); + lock.push(callsite); + } + + 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, + } + } + } +} + +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) } /// Trait implemented by callsites. @@ -125,8 +273,7 @@ pub struct Identifier( /// [`Interest::sometimes()`]: ../subscriber/struct.Interest.html#method.sometimes /// [`Subscriber`]: ../subscriber/trait.Subscriber.html 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. @@ -134,15 +281,13 @@ 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()); + 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(); + let dispatchers = DISPATCHERS.register_dispatch(dispatch); + CALLSITES.rebuild_interest(dispatchers); } // ===== impl Identifier ===== @@ -172,3 +317,75 @@ impl Hash for Identifier { (self.0 as *const dyn Callsite).hash(state) } } + +#[cfg(feature = "std")] +mod dispatchers { + use crate::dispatcher; + use std::sync::{RwLock, RwLockReadGuard, RwLockWriteGuard}; + + pub(super) struct Dispatchers(RwLock>); + pub(super) enum Rebuilder<'a> { + Read(RwLockReadGuard<'a, Vec>), + Write(RwLockWriteGuard<'a, Vec>), + } + + impl Dispatchers { + pub(super) fn new() -> Self { + Self(RwLock::new(Vec::new())) + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + Rebuilder::Read(self.0.read().unwrap()) + } + + pub(super) fn register_dispatch(&self, dispatch: &dispatcher::Dispatch) -> Rebuilder<'_> { + let mut dispatchers = self.0.write().unwrap(); + dispatchers.retain(|d| d.upgrade().is_some()); + dispatchers.push(dispatch.registrar()); + Rebuilder::Write(dispatchers) + } + } + + impl Rebuilder<'_> { + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + let iter = match self { + 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; + use core::marker::PhantomData; + use std::marker::PhantomData; + + pub(super) struct Dispatchers(()); + pub(super) struct Rebuilder<'a>(PhantomData<'a>); + + impl Dispatchers { + pub(super) fn new() -> Self { + Self(()) + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + Rebuilder(PhantomData) + } + + pub(super) fn register_dispatch(&self, _: &dispatcher::Dispatch) -> Rebuilder<'_> { + // nop; on no_std, there can only ever be one dispatcher + Rebuilder(PhantomData) + } + } + + impl Rebuilder<'_> { + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + // on no_std, there can only ever be one dispatcher + dispatcher::get_default(f) + } + } +} From 88fbab0840be3ffda0580874aff9bd279a7d9cca Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 24 Mar 2022 14:34:54 -0700 Subject: [PATCH 03/12] cleanup --- tracing-core/src/callsite.rs | 288 ++++++++++++++++----------------- tracing-core/src/dispatcher.rs | 7 - 2 files changed, 141 insertions(+), 154 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 3511d9bbba..cc1182900a 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -19,6 +19,86 @@ use crate::{ use self::dispatchers::Dispatchers; +/// Trait implemented by callsites. +/// +/// These functions are only intended to be called by the callsite registry, which +/// correctly handles determining the common interest between all subscribers. +pub trait Callsite: Sync { + /// Sets the [`Interest`] for this callsite. + /// + /// [`Interest`]: ../subscriber/struct.Interest.html + fn set_interest(&self, interest: Interest); + + /// Returns the [metadata] associated with the callsite. + /// + /// [metadata]: ../metadata/struct.Metadata.html + fn metadata(&self) -> &Metadata<'_>; +} + +/// Uniquely identifies a [`Callsite`] +/// +/// Two `Identifier`s are equal if they both refer to the same callsite. +/// +/// [`Callsite`]: ../callsite/trait.Callsite.html +#[derive(Clone)] +pub struct Identifier( + /// **Warning**: The fields on this type are currently `pub` because it must + /// be able to be constructed statically by macros. However, when `const + /// fn`s are available on stable Rust, this will no longer be necessary. + /// Thus, these fields are *not* considered stable public API, and they may + /// change warning. Do not rely on any fields on `Identifier`. When + /// constructing new `Identifier`s, use the `identify_callsite!` macro or + /// the `Callsite::id` function instead. + // TODO: When `Callsite::id` is a const fn, this need no longer be `pub`. + #[doc(hidden)] + pub &'static dyn Callsite, +); + +/// A default [`Callsite`] implementation. +#[derive(Debug)] +pub struct DefaultCallsite { + interest: AtomicUsize, + meta: &'static Metadata<'static>, + next: AtomicPtr, + registration: Once, +} + +/// Clear and reregister interest on every [`Callsite`] +/// +/// This function is intended for runtime reconfiguration of filters on traces +/// when the filter recalculation is much less frequent than trace events are. +/// The alternative is to have the [`Subscriber`] that supports runtime +/// reconfiguration of filters always return [`Interest::sometimes()`] so that +/// [`enabled`] is evaluated for every event. +/// +/// This function will also re-compute the global maximum level as determined by +/// the [`max_level_hint`] method. If a [`Subscriber`] +/// implementation changes the value returned by its `max_level_hint` +/// implementation at runtime, then it **must** call this function after that +/// value changes, in order for the change to be reflected. +/// +/// [`max_level_hint`]: ../subscriber/trait.Subscriber.html#method.max_level_hint +/// [`Callsite`]: ../callsite/trait.Callsite.html +/// [`enabled`]: ../subscriber/trait.Subscriber.html#tymethod.enabled +/// [`Interest::sometimes()`]: ../subscriber/struct.Interest.html#method.sometimes +/// [`Subscriber`]: ../subscriber/trait.Subscriber.html +pub fn rebuild_interest_cache() { + CALLSITES.rebuild_interest(DISPATCHERS.rebuilder()); +} + +/// Register a new `Callsite` with the global registry. +/// +/// This should be called once per callsite after the callsite has been +/// constructed. +pub fn register(callsite: &'static dyn Callsite) { + rebuild_callsite_interest(callsite, &DISPATCHERS.rebuilder()); + + // TODO(eliza): if we wanted to be *really* cute we could also add some kind + // of downcasting to `Callsite` and use `push_default` here, too, if we are + // registering a default callsite... + CALLSITES.push_dyn(callsite); +} + crate::lazy_static! { static ref CALLSITES: Callsites = Callsites { list_head: AtomicPtr::new(ptr::null_mut()), @@ -35,13 +115,7 @@ struct Callsites { locked_callsites: Mutex>, } -/// A default [`Callsite`] implementation. -pub struct DefaultCallsite { - interest: AtomicUsize, - meta: &'static Metadata<'static>, - next: AtomicPtr, - registration: Once, -} +// === impl DefaultCallsite === impl DefaultCallsite { /// Returns a new `DefaultCallsite` with the specified `Metadata`. @@ -56,14 +130,9 @@ impl DefaultCallsite { /// 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. + /// If the callsite is already registered, this does nothing. When using + /// [`DefaultCallsite`], this method should be preferred over + /// [`tracing_core::callsite::register`]. #[inline(never)] // This only happens once (or if the cached interest value was corrupted). #[cold] @@ -81,13 +150,6 @@ impl DefaultCallsite { /// 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) { @@ -97,10 +159,6 @@ impl DefaultCallsite { _ => self.register(), } } - - pub fn is_enabled(&self, interest: Interest) -> bool { - interest.is_always() || crate::dispatcher::get_default(|default| default.enabled(self.meta)) - } } impl Callsite for DefaultCallsite { @@ -119,34 +177,40 @@ impl Callsite for DefaultCallsite { } } -impl fmt::Debug for DefaultCallsite { - 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() +// ===== impl Identifier ===== + +impl PartialEq for Identifier { + fn eq(&self, other: &Identifier) -> bool { + core::ptr::eq( + self.0 as *const _ as *const (), + other.0 as *const _ as *const (), + ) } } -impl Callsites { - 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); +impl Eq for Identifier {} - head = cs.next.load(Ordering::Acquire); - } +impl fmt::Debug for Identifier { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "Identifier({:p})", self.0) + } +} - if self.has_locked_callsites.load(Ordering::Acquire) { - let locked = self.locked_callsites.lock().unwrap(); - for &cs in locked.iter() { - f(cs); - } - } +impl Hash for Identifier { + fn hash(&self, state: &mut H) + where + H: Hasher, + { + (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| { @@ -164,12 +228,19 @@ impl Callsites { 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 = self.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); @@ -197,6 +268,29 @@ impl Callsites { } } } + + /// 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 = self.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( @@ -218,106 +312,6 @@ fn rebuild_callsite_interest( callsite.set_interest(interest) } -/// Trait implemented by callsites. -/// -/// These functions are only intended to be called by the callsite registry, which -/// correctly handles determining the common interest between all subscribers. -pub trait Callsite: Sync { - /// Sets the [`Interest`] for this callsite. - /// - /// [`Interest`]: ../subscriber/struct.Interest.html - fn set_interest(&self, interest: Interest); - - /// Returns the [metadata] associated with the callsite. - /// - /// [metadata]: ../metadata/struct.Metadata.html - fn metadata(&self) -> &Metadata<'_>; -} - -/// Uniquely identifies a [`Callsite`] -/// -/// Two `Identifier`s are equal if they both refer to the same callsite. -/// -/// [`Callsite`]: ../callsite/trait.Callsite.html -#[derive(Clone)] -pub struct Identifier( - /// **Warning**: The fields on this type are currently `pub` because it must - /// be able to be constructed statically by macros. However, when `const - /// fn`s are available on stable Rust, this will no longer be necessary. - /// Thus, these fields are *not* considered stable public API, and they may - /// change warning. Do not rely on any fields on `Identifier`. When - /// constructing new `Identifier`s, use the `identify_callsite!` macro or - /// the `Callsite::id` function instead. - // TODO: When `Callsite::id` is a const fn, this need no longer be `pub`. - #[doc(hidden)] - pub &'static dyn Callsite, -); - -/// Clear and reregister interest on every [`Callsite`] -/// -/// This function is intended for runtime reconfiguration of filters on traces -/// when the filter recalculation is much less frequent than trace events are. -/// The alternative is to have the [`Subscriber`] that supports runtime -/// reconfiguration of filters always return [`Interest::sometimes()`] so that -/// [`enabled`] is evaluated for every event. -/// -/// This function will also re-compute the global maximum level as determined by -/// the [`max_level_hint`] method. If a [`Subscriber`] -/// implementation changes the value returned by its `max_level_hint` -/// implementation at runtime, then it **must** call this function after that -/// value changes, in order for the change to be reflected. -/// -/// [`max_level_hint`]: ../subscriber/trait.Subscriber.html#method.max_level_hint -/// [`Callsite`]: ../callsite/trait.Callsite.html -/// [`enabled`]: ../subscriber/trait.Subscriber.html#tymethod.enabled -/// [`Interest::sometimes()`]: ../subscriber/struct.Interest.html#method.sometimes -/// [`Subscriber`]: ../subscriber/trait.Subscriber.html -pub fn rebuild_interest_cache() { - CALLSITES.rebuild_interest(DISPATCHERS.rebuilder()); -} - -/// Register a new `Callsite` with the global registry. -/// -/// This should be called once per callsite after the callsite has been -/// constructed. -pub fn register(callsite: &'static dyn Callsite) { - rebuild_callsite_interest(callsite, &DISPATCHERS.rebuilder()); - CALLSITES.push_dyn(callsite); -} - -pub(crate) fn register_dispatch(dispatch: &Dispatch) { - let dispatchers = DISPATCHERS.register_dispatch(dispatch); - CALLSITES.rebuild_interest(dispatchers); -} - -// ===== impl Identifier ===== - -impl PartialEq for Identifier { - fn eq(&self, other: &Identifier) -> bool { - core::ptr::eq( - self.0 as *const _ as *const (), - other.0 as *const _ as *const (), - ) - } -} - -impl Eq for Identifier {} - -impl fmt::Debug for Identifier { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "Identifier({:p})", self.0) - } -} - -impl Hash for Identifier { - fn hash(&self, state: &mut H) - where - H: Hasher, - { - (self.0 as *const dyn Callsite).hash(state) - } -} - #[cfg(feature = "std")] mod dispatchers { use crate::dispatcher; diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 204c261e41..dba9bab5d0 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -658,13 +658,6 @@ where } 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 }) } From e4ee1307f4c64bfacffe7acdeede3cf00fca104d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 24 Mar 2022 14:54:56 -0700 Subject: [PATCH 04/12] avoid hitting the lock in more cases Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 57 +++++++++++++++++++++++++----------- 1 file changed, 40 insertions(+), 17 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index cc1182900a..6031de0483 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -99,20 +99,20 @@ pub fn register(callsite: &'static dyn Callsite) { CALLSITES.push_dyn(callsite); } -crate::lazy_static! { - static ref CALLSITES: Callsites = Callsites { - list_head: AtomicPtr::new(ptr::null_mut()), - has_locked_callsites: AtomicBool::new(false), - locked_callsites: Mutex::new(Vec::new()), - }; +static CALLSITES: Callsites = Callsites { + list_head: AtomicPtr::new(ptr::null_mut()), + has_locked_callsites: AtomicBool::new(false), +}; + +static DISPATCHERS: Dispatchers = Dispatchers::new(); - static ref 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, - locked_callsites: Mutex>, } // === impl DefaultCallsite === @@ -232,7 +232,7 @@ impl Callsites { /// /// This will attempt to lock the callsites vector. fn push_dyn(&self, callsite: &'static dyn Callsite) { - let mut lock = self.locked_callsites.lock().unwrap(); + let mut lock = LOCKED_CALLSITES.lock().unwrap(); self.has_locked_callsites.store(true, Ordering::Release); lock.push(callsite); } @@ -280,7 +280,7 @@ impl Callsites { } if self.has_locked_callsites.load(Ordering::Acquire) { - let locked = self.locked_callsites.lock().unwrap(); + let locked = LOCKED_CALLSITES.lock().unwrap(); for &cs in locked.iter() { f(cs); } @@ -315,27 +315,45 @@ fn rebuild_callsite_interest( #[cfg(feature = "std")] mod dispatchers { use crate::dispatcher; - use std::sync::{RwLock, RwLockReadGuard, RwLockWriteGuard}; + 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) struct Dispatchers(RwLock>); pub(super) enum Rebuilder<'a> { + JustOne, Read(RwLockReadGuard<'a, Vec>), Write(RwLockWriteGuard<'a, Vec>), } impl Dispatchers { - pub(super) fn new() -> Self { - Self(RwLock::new(Vec::new())) + pub(super) const fn new() -> Self { + Self { + has_just_one: AtomicBool::new(true), + } } pub(super) fn rebuilder(&self) -> Rebuilder<'_> { - Rebuilder::Read(self.0.read().unwrap()) + 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 = self.0.write().unwrap(); + 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) } } @@ -343,6 +361,10 @@ mod 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(), }; @@ -362,7 +384,7 @@ mod dispatchers { pub(super) struct Rebuilder<'a>(PhantomData<'a>); impl Dispatchers { - pub(super) fn new() -> Self { + pub(super) const fn new() -> Self { Self(()) } @@ -377,6 +399,7 @@ mod dispatchers { } impl Rebuilder<'_> { + #[inline(always)] pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { // on no_std, there can only ever be one dispatcher dispatcher::get_default(f) From 969b61881174dedbd4f962c8a5ae0a9c346c0214 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 24 Mar 2022 16:54:44 -0700 Subject: [PATCH 05/12] fix no-std code Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 6031de0483..ad1338646e 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -378,10 +378,9 @@ mod dispatchers { mod dispatchers { use crate::dispatcher; use core::marker::PhantomData; - use std::marker::PhantomData; pub(super) struct Dispatchers(()); - pub(super) struct Rebuilder<'a>(PhantomData<'a>); + pub(super) struct Rebuilder<'a>(PhantomData<&'a ()>); impl Dispatchers { pub(super) const fn new() -> Self { From 3cd2f152a58d6109594dc8fe6f1cc66e5dda0d79 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Mon, 18 Apr 2022 11:26:04 -0700 Subject: [PATCH 06/12] update everything to use the new callsites Signed-off-by: Eliza Weisman --- tracing-core/Cargo.toml | 2 +- tracing/Cargo.toml | 2 +- tracing/src/lib.rs | 137 +++++++++------------------------------- tracing/src/macros.rs | 30 ++++----- 4 files changed, 45 insertions(+), 126 deletions(-) diff --git a/tracing-core/Cargo.toml b/tracing-core/Cargo.toml index 87d95289c3..77075846e7 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.25" +version = "0.1.26" authors = ["Tokio Contributors "] license = "MIT" readme = "README.md" diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index 926c492d52..ba44028741 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 4a78c8fd72..c12fb673e2 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -972,13 +972,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. /// @@ -988,113 +983,39 @@ 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 use tracing_core::callsite::DefaultCallsite as MacroCallsite; - 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() - } + /// /!\ 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); - } - - #[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(feature = "log")] + pub fn __disabled_span(meta: &Metadata<'static>) -> crate::Span { + crate::Span::new_disabled(meta) } - 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. + #[inline] + #[cfg(not(feature = "log"))] + pub fn __disabled_span(_: &Metadata<'static>) -> crate::Span { + crate::Span::none() } #[cfg(feature = "log")] diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 0a599c6bb7..28de176545 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) }}; } From 94bc0c2af5488ef4f39183ed0431701a95ede792 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 19 Apr 2022 10:59:21 -0700 Subject: [PATCH 07/12] downcasty trick This way, `callsite::register` also does the right thing Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 40 ++++++++++++++++++++++++++++++++---- 1 file changed, 36 insertions(+), 4 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index ad1338646e..fd4b5e96c3 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -1,6 +1,7 @@ //! Callsites represent the source locations from which spans or events //! originate. use crate::stdlib::{ + any::TypeId, fmt, hash::{Hash, Hasher}, ptr, @@ -33,6 +34,16 @@ pub trait Callsite: Sync { /// /// [metadata]: ../metadata/struct.Metadata.html fn metadata(&self) -> &Metadata<'_>; + + // TODO(eliza): this could be used to implement a public downcasting API + // for `&dyn Callsite`s in the future. + #[doc(hidden)] + fn private_type_id(&self, _: private::Private<()>) -> private::Private + where + Self: 'static, + { + private::Private(TypeId::of::()) + } } /// Uniquely identifies a [`Callsite`] @@ -93,9 +104,20 @@ pub fn rebuild_interest_cache() { pub fn register(callsite: &'static dyn Callsite) { rebuild_callsite_interest(callsite, &DISPATCHERS.rebuilder()); - // TODO(eliza): if we wanted to be *really* cute we could also add some kind - // of downcasting to `Callsite` and use `push_default` here, too, if we are - // registering a default callsite... + // 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); } @@ -132,7 +154,11 @@ impl DefaultCallsite { /// /// If the callsite is already registered, this does nothing. When using /// [`DefaultCallsite`], this method should be preferred over - /// [`tracing_core::callsite::register`]. + /// [`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] @@ -312,6 +338,12 @@ fn rebuild_callsite_interest( 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; From 3e6fadd942da49df1dcb8eb3ef0c80c2af42e88d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 19 Apr 2022 11:26:49 -0700 Subject: [PATCH 08/12] docs Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index fd4b5e96c3..6777844d9e 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -35,9 +35,21 @@ pub trait Callsite: Sync { /// [metadata]: ../metadata/struct.Metadata.html 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, From a9893a67616565eb221c185c241b702ced73415e Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 19 Apr 2022 14:30:00 -0700 Subject: [PATCH 09/12] fix lifetimes in log support code Signed-off-by: Eliza Weisman --- tracing/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 582c1e0aee..fdd12bd3eb 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -998,7 +998,7 @@ pub mod __macro_support { /// without warning. #[inline] #[cfg(feature = "log")] - pub fn __disabled_span(meta: &Metadata<'static>) -> crate::Span { + pub fn __disabled_span(meta: &'static Metadata<'static>) -> crate::Span { crate::Span::new_disabled(meta) } @@ -1010,7 +1010,7 @@ pub mod __macro_support { /// without warning. #[inline] #[cfg(not(feature = "log"))] - pub fn __disabled_span(_: &Metadata<'static>) -> crate::Span { + pub fn __disabled_span(_: &'static Metadata<'static>) -> crate::Span { crate::Span::none() } From e04f82ec808ade42e4bebdaae9fd572fe7a3d7ff Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 20 Apr 2022 09:39:20 -0700 Subject: [PATCH 10/12] fix max_level_hint on nostd Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 27 +++++++++++++++++++-------- tracing-mock/src/subscriber.rs | 2 ++ 2 files changed, 21 insertions(+), 8 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index eeed16ca66..71287336df 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -420,10 +420,9 @@ mod dispatchers { #[cfg(not(feature = "std"))] mod dispatchers { use crate::dispatcher; - use core::marker::PhantomData; pub(super) struct Dispatchers(()); - pub(super) struct Rebuilder<'a>(PhantomData<&'a ()>); + pub(super) struct Rebuilder<'a>(Option<&'a dispatcher::Dispatch>); impl Dispatchers { pub(super) const fn new() -> Self { @@ -431,20 +430,32 @@ mod dispatchers { } pub(super) fn rebuilder(&self) -> Rebuilder<'_> { - Rebuilder(PhantomData) + Rebuilder(None) } - pub(super) fn register_dispatch(&self, _: &dispatcher::Dispatch) -> Rebuilder<'_> { + 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(PhantomData) + Rebuilder(Some(dispatch)) } } impl Rebuilder<'_> { - #[inline(always)] + #[inline] pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { - // on no_std, there can only ever be one dispatcher - dispatcher::get_default(f) + 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-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 } From b6c70b0c25f36be4e89b257fcebcb632977a4213 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 20 Apr 2022 09:59:40 -0700 Subject: [PATCH 11/12] fix deadlock on no_std when hitting once cell Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 66 ++++++++++++++++++++++++++---------- 1 file changed, 49 insertions(+), 17 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 71287336df..3a0ccd02ff 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -6,7 +6,7 @@ use crate::stdlib::{ hash::{Hash, Hasher}, ptr, sync::{ - atomic::{AtomicBool, AtomicPtr, AtomicUsize, Ordering}, + atomic::{AtomicBool, AtomicPtr, AtomicU8, Ordering}, Mutex, }, vec::Vec, @@ -79,10 +79,10 @@ pub struct Identifier( /// A default [`Callsite`] implementation. #[derive(Debug)] pub struct DefaultCallsite { - interest: AtomicUsize, + interest: AtomicU8, + registration: AtomicU8, meta: &'static Metadata<'static>, next: AtomicPtr, - registration: Once, } /// Clear and reregister interest on every [`Callsite`] @@ -151,13 +151,21 @@ struct Callsites { // === 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: AtomicUsize::new(0xDEADFACED), + interest: AtomicU8::new(0xFF), meta, next: AtomicPtr::new(ptr::null_mut()), - registration: Once::new(), + registration: AtomicU8::new(Self::UNREGISTERED), } } @@ -174,13 +182,37 @@ impl DefaultCallsite { // This only happens once (or if the cached interest value was corrupted). #[cold] pub fn register(&'static self) -> Interest { - self.registration.call_once(|| { - rebuild_callsite_interest(self, &DISPATCHERS.rebuilder()); - CALLSITES.push_default(self); - }); + // 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) { - 0 => Interest::never(), - 2 => Interest::always(), + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_ALWAYS => Interest::always(), _ => Interest::sometimes(), } } @@ -190,9 +222,9 @@ impl DefaultCallsite { #[inline] pub fn interest(&'static self) -> Interest { match self.interest.load(Ordering::Relaxed) { - 0 => Interest::never(), - 1 => Interest::sometimes(), - 2 => Interest::always(), + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_SOMETIMES => Interest::sometimes(), + Self::INTEREST_ALWAYS => Interest::always(), _ => self.register(), } } @@ -201,9 +233,9 @@ impl DefaultCallsite { impl Callsite for DefaultCallsite { fn set_interest(&self, interest: Interest) { let interest = match () { - _ if interest.is_never() => 0, - _ if interest.is_always() => 2, - _ => 1, + _ if interest.is_never() => Self::INTEREST_NEVER, + _ if interest.is_always() => Self::INTEREST_ALWAYS, + _ => Self::INTEREST_SOMETIMES, }; self.interest.store(interest, Ordering::SeqCst); } From 18cc711ac5ad8add1c8ed33037250fda48ca6ff0 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 20 Apr 2022 10:07:25 -0700 Subject: [PATCH 12/12] cleanup warnings Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 1 - tracing-core/src/dispatcher.rs | 6 +++++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 3a0ccd02ff..273fecec4e 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -15,7 +15,6 @@ use crate::{ dispatcher::Dispatch, metadata::{LevelFilter, Metadata}, subscriber::Interest, - Once, }; use self::dispatchers::Dispatchers; diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index f81a6c463e..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,6 +654,7 @@ where } } +#[cfg(feature = "std")] impl Registrar { pub(crate) fn upgrade(&self) -> Option { self.0.upgrade().map(|subscriber| Dispatch { subscriber })