Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tracing: ensmallerate assembly generated by macro expansions #943

Merged
merged 9 commits into from
Aug 21, 2020
Merged
Show file tree
Hide file tree
Changes from 8 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions tracing-core/CHANGELOG.md
Original file line number Diff line number Diff line change
@@ -1,3 +1,9 @@
# Unreleased

## Added

- Internal API changes to support optimizations in the `tracing` crate (#943)

# 0.1.14 (August 10, 2020)

### Fixed
Expand Down
2 changes: 1 addition & 1 deletion tracing-core/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ name = "tracing-core"
# - README.md
# - Update CHANGELOG.md.
# - Create "v0.1.x" git tag.
version = "0.1.14"
version = "0.1.15"
authors = ["Tokio Contributors <team@tokio.rs>"]
license = "MIT"
readme = "README.md"
Expand Down
102 changes: 76 additions & 26 deletions tracing-core/src/dispatcher.rs
Original file line number Diff line number Diff line change
Expand Up @@ -149,7 +149,7 @@ use crate::stdlib::{

#[cfg(feature = "std")]
use crate::stdlib::{
cell::{Cell, RefCell},
cell::{Cell, RefCell, RefMut},
error,
};

Expand Down Expand Up @@ -193,6 +193,12 @@ struct State {
can_enter: Cell<bool>,
}

/// While this guard is active, additional calls to subscriber functions on
/// the default dispatcher will not be able to access the dispatch context.
/// Dropping the guard will allow the dispatch context to be re-entered.
#[cfg(feature = "std")]
struct Entered<'a>(&'a State);

/// A guard that resets the current default dispatcher to the prior
/// default dispatcher when dropped.
#[cfg(feature = "std")]
Expand Down Expand Up @@ -325,38 +331,46 @@ pub fn get_default<T, F>(mut f: F) -> T
where
F: FnMut(&Dispatch) -> T,
{
// While this guard is active, additional calls to subscriber functions on
// the default dispatcher will not be able to access the dispatch context.
// Dropping the guard will allow the dispatch context to be re-entered.
struct Entered<'a>(&'a Cell<bool>);
impl<'a> Drop for Entered<'a> {
#[inline]
fn drop(&mut self) {
self.0.set(true);
}
}

CURRENT_STATE
.try_with(|state| {
if state.can_enter.replace(false) {
let _guard = Entered(&state.can_enter);

let mut default = state.default.borrow_mut();

if default.is::<NoSubscriber>() {
if let Some(global) = get_global() {
// don't redo this call on the next check
*default = global.clone();
}
}
f(&*default)
} else {
f(&Dispatch::none())
if let Some(entered) = state.enter() {
return f(&*entered.current());
}

f(&Dispatch::none())
})
.unwrap_or_else(|_| f(&Dispatch::none()))
}

/// Executes a closure with a reference to this thread's current [dispatcher].
///
/// Note that calls to `get_default` should not be nested; if this function is
/// called while inside of another `get_default`, that closure will be provided
/// with `Dispatch::none` rather than the previously set dispatcher.
///
/// [dispatcher]: ../dispatcher/struct.Dispatch.html
#[cfg(feature = "std")]
#[doc(hidden)]
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adding this was necessary since constructing the ValueSet in a closure means we needed a FnOnce so that values can be moved into the closure (which happens primarily when users wrap values in field::display/field::debug without borrowing). Not supporting this would break at least some code. I opted to add a new function that takes a FnOnce, rather than capturing an Option<FnOnce> into the FnMut and takeing it, because that seemed significantly less efficient.

We could probably commit to making this a public API (and even deprecate get_default, the version that takes a FnMut). This is probably a more useful API than get_default taking a FnMut... I didn't make it public here, though, because introducing a new public API seemed like a job for another PR.

Also, in 0.2, the Value changes will make Value::debug and Value::display also borrow rather than move. So, the FnOnce will no longer be necessary, and we could, alternatively, remove this function in 0.2, rather than deprecating the existing get_current.

So, there should probably be an actual design discussion... :)

#[inline(never)]
pub fn get_current<T>(f: impl FnOnce(&Dispatch) -> T) -> Option<T> {
CURRENT_STATE
.try_with(|state| {
let entered = state.enter()?;
Some(f(&*entered.current()))
})
.ok()?
}

/// Executes a closure with a reference to the current [dispatcher].
///
/// [dispatcher]: ../dispatcher/struct.Dispatch.html
#[cfg(not(feature = "std"))]
#[doc(hidden)]
pub fn get_current<T>(f: impl FnOnce(&Dispatch) -> T) -> Option<T> {
let dispatch = get_global()?;
Some(f(&dispatch))
}

/// Executes a closure with a reference to the current [dispatcher].
///
/// [dispatcher]: ../dispatcher/struct.Dispatch.html
Expand Down Expand Up @@ -711,6 +725,42 @@ impl State {
EXISTS.store(true, Ordering::Release);
DefaultGuard(prior)
}

#[inline]
fn enter(&self) -> Option<Entered<'_>> {
if self.can_enter.replace(false) {
Some(Entered(&self))
} else {
None
}
}
}

// ===== impl Entered =====

#[cfg(feature = "std")]
impl<'a> Entered<'a> {
#[inline]
fn current(&self) -> RefMut<'a, Dispatch> {
let mut default = self.0.default.borrow_mut();

if default.is::<NoSubscriber>() {
if let Some(global) = get_global() {
// don't redo this call on the next check
*default = global.clone();
}
}

default
}
}

#[cfg(feature = "std")]
impl<'a> Drop for Entered<'a> {
#[inline]
fn drop(&mut self) {
self.0.can_enter.set(true);
}
}

// ===== impl DefaultGuard =====
Expand Down
2 changes: 1 addition & 1 deletion tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ keywords = ["logging", "tracing", "metrics", "async"]
edition = "2018"

[dependencies]
tracing-core = { path = "../tracing-core", version = "0.1.14", default-features = false }
tracing-core = { path = "../tracing-core", version = "0.1.15", default-features = false }
log = { version = "0.4", optional = true }
tracing-attributes = { path = "../tracing-attributes", version = "0.1.10", optional = true }
cfg-if = "0.1.10"
Expand Down
89 changes: 60 additions & 29 deletions tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -907,9 +907,9 @@ pub mod subscriber;

#[doc(hidden)]
pub mod __macro_support {
pub use crate::callsite::Callsite as _;
pub use crate::callsite::Callsite;
use crate::stdlib::sync::atomic::{AtomicUsize, Ordering};
use crate::{subscriber::Interest, Callsite, Metadata};
use crate::{subscriber::Interest, Metadata};
use tracing_core::Once;

/// Callsite implementation used by macro-generated code.
Expand Down Expand Up @@ -938,59 +938,90 @@ pub mod __macro_support {
/// without warning.
pub const fn new(meta: &'static Metadata<'static>) -> Self {
Self {
interest: AtomicUsize::new(0),
interest: AtomicUsize::new(0xDEADFACED),
meta,
registration: Once::new(),
}
}

/// Returns `true` if the callsite is enabled by a cached interest, or
/// by the current `Dispatch`'s `enabled` method if the cached
/// `Interest` is `sometimes`.
/// Registers this callsite with the global callsite registry.
///
/// If the callsite is already registered, this does nothing.
///
/// /!\ WARNING: This is *not* a stable API! /!\
/// This method, and all code contained in the `__macro_support` module, is
/// 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(always)]
pub fn is_enabled(&self) -> bool {
let interest = self.interest();
if interest.is_always() {
return true;
}
if interest.is_never() {
return false;
#[inline(never)]
// This only happens once (or if the cached interest value was corrupted).
#[cold]
pub fn register(&'static self) -> Interest {
self.registration
.call_once(|| crate::callsite::register(self));
match self.interest.load(Ordering::Relaxed) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it actually worse here to call the inlined interest fn here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be fine for it to be inlined into this function, since this function shouldn't be inlined. The reason it doesn't is that the interest function calls register (this function) if the cached value is not 0, 1, or 2. That means that if we register the callsite and the cached interest value is still not one of those, we could recurse again, potentially infinitely.

This shouldn't happen ever, but if there's a bug elsewhere, I'd rather just assume the cached value is invalid and return Interest::sometimes() (which is what this method does), rather than overflowing the stack.

0 => Interest::never(),
2 => Interest::always(),
_ => Interest::sometimes(),
}

crate::dispatcher::get_default(|current| current.enabled(self.meta))
}

/// Registers this callsite with the global callsite registry.
///
/// If the callsite is already registered, this does nothing.
/// Returns the callsite's cached Interest, or registers it for the
hawkw marked this conversation as resolved.
Show resolved Hide resolved
/// 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(always)]
pub fn register(&'static self) {
self.registration
.call_once(|| crate::callsite::register(self));
}

#[inline(always)]
fn interest(&self) -> Interest {
#[inline]
pub fn interest(&'static self) -> Interest {
match self.interest.load(Ordering::Relaxed) {
0 => Interest::never(),
1 => Interest::sometimes(),
2 => Interest::always(),
_ => Interest::sometimes(),
_ => self.register(),
}
}

pub fn dispatch_event(&'static self, interest: Interest, f: impl FnOnce(&crate::Dispatch)) {
tracing_core::dispatcher::get_current(|current| {
if interest.is_always() || current.enabled(self.meta) {
f(current)
}
});
}

#[inline]
#[cfg(feature = "log")]
pub fn disabled_span(&self) -> crate::Span {
crate::Span::new_disabled(self.meta)
}

#[inline]
#[cfg(not(feature = "log"))]
pub fn disabled_span(&self) -> crate::Span {
crate::Span::none()
}

pub fn dispatch_span(
&'static self,
interest: Interest,
f: impl FnOnce(&crate::Dispatch) -> crate::Span,
) -> crate::Span {
if interest.is_never() {
return self.disabled_span();
}

tracing_core::dispatcher::get_current(|current| {
if interest.is_always() || current.enabled(self.meta) {
return f(current);
}
self.disabled_span()
})
.unwrap_or_else(|| self.disabled_span())
}
}

impl Callsite for MacroCallsite {
Expand Down
Loading