itsscb/tracing
1
0
Fork 0
mirror of https://github.com/tokio-rs/tracing.git synced 2025-10-02 07:20:35 +00:00
Code Issues Packages Projects Releases Wiki Activity

core: add a limited form of the linked-list callsite registry for v0.1.x (#2083)

Browse Source 
## Motivation

Currently on `v0.1.x`, the global callsite registry is implemented as a
`Mutex<Vec<&'static dyn Callsite>>`. 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<Vec<...>>`. 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<Vec<dyn Dispatch>>` 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 <eliza@buoyant.io>
This commit is contained in:
Eliza Weisman 2022-04-22 09:11:08 -07:00 committed by GitHub
parent cdbd122933
commit 45a5df1373
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 517 additions and 226 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

455
tracing-core/src/callsite.rs
View File

@ -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<Registry> = Mutex::new(Registry {
callsites: Vec::new(),
dispatchers: Vec::new(),
});
}
struct Registry {
callsites: Vec<&'static dyn Callsite>,
dispatchers: Vec<dispatcher::Registrar>,
}
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<TypeId>
where
Self: 'static,
{
private::Private(TypeId::of::<Self>())
}
}
/// 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<Self>,
}
/// 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::<DefaultCallsite>() {
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<Vec<&'static dyn Callsite>> = Mutex::new(Vec::new());
}
struct Callsites {
list_head: AtomicPtr<DefaultCallsite>,
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<T>(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<Vec<dispatcher::Registrar>> = RwLock::new(Vec::new());
}
pub(super) enum Rebuilder<'a> {
JustOne,
Read(RwLockReadGuard<'a, Vec<dispatcher::Registrar>>),
Write(RwLockWriteGuard<'a, Vec<dispatcher::Registrar>>),
}
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)
}
}
}
}

13
tracing-core/src/dispatcher.rs
View File

@ -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<dyn Subscriber + Send + Sync>);
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<subscriber::Interest> {
self.0.upgrade().map(|s| s.register_callsite(metadata))
}
pub(crate) fn upgrade(&self) -> Option<Dispatch> {
self.0.upgrade().map(|subscriber| Dispatch { subscriber })
}

2
tracing-mock/src/subscriber.rs
View File

@ -198,7 +198,9 @@ where
Interest::never()
}
}
fn max_level_hint(&self) -> Option<LevelFilter> {
println!("[{}] max_level_hint -> {:?}", self.name, self.max_level);
self.max_level
}

2
tracing/Cargo.toml
View File

@ -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"

189
tracing/src/lib.rs
View File

@ -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,
pub use tracing_core::callsite::DefaultCallsite as MacroCallsite;
/// /!\ 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 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()
}
#[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.
#[inline]
#[cfg(feature = "log")]
pub fn __disabled_span(meta: &'static Metadata<'static>) -> crate::Span {
crate::Span::new_disabled(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(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(),
);
}
}

35
tracing/src/macros.rs
View File

@ -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)
}
}
}}

47
tracing/tests/register_callsite_deadlock.rs Normal file
View File

@ -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");
}