Skip to content

Commit

Permalink
tracing: move macro callsite impls out of macro expansion (#869)
Browse files Browse the repository at this point in the history
## Motivation

Currently, every `tracing` macro generates a _new implementation_ of the
`Callsite` trait for a zero-sized struct created for that particular
callsite. This callsite accesses several statics defined in the macro
expansion.

This means that each tracing macro expands to a _lot_ of code — check
out the `cargo expand` output:

```
eliza on butterfly in tracing/examples on  master [$?] is v0.0.0 via ⚙️ v1.44.0
:; cargo expand --example all-levels | wc -l
    Checking tracing-examples v0.0.0 (/home/eliza/code/tracing/examples)
    Finished check [unoptimized + debuginfo] target(s) in 0.20s

463
```

More code in the macro expansion means more code in the function
*invoking* the macro, which may make that function harder for `rustc` to
optimize. This effects the performance of *other* code in the function,
not the `tracing` code, so this isn't necessarily visible in `tracing`'s
microbenchmarks, which only contain `tracing` code. 

In `rustc` itself, there is a small but noticeable performance impact
from switching from `log` to `tracing` even after making changes that
should make the filtering overhead equivalent:
rust-lang/rust#74726 (comment).
This appears to be due to more complex generated code impacting
optimizer behavior.

## Solution

This branch moves the callsite generated by each macro out of the macro
expansion and into a single `MacroCallsite` private API type in the
`__macro_support` module. Instead of creating a zero-sized `Callsite`
static and multiple statics for the `Metadata`, the `Once` cell for
registration, and the `Interest` atomic, these are all now fields on the
`Callsite` struct. This shouldn't result in any real change, but makes
the implementation simpler. All the hot filtering functions on
`MacroCallsite` are `#[inline(always)]`, so we shouldn't be adding stack
frames to code that was previously generated in the macro expansion.

After making this change, the expanded output is about half as long 
as it was before:

```
eliza on butterfly in tracing/examples on  eliza/smaller-macros [$?] is v0.0.0 via ⚙️ v1.44.0 
:; cargo expand --example all-levels | wc -l
    Checking tracing-examples v0.0.0 (/home/eliza/code/tracing/examples)
    Finished check [unoptimized + debuginfo] target(s) in 0.75s

233
```

This change appears to fix most of the remaining `rustc` performance
regressions:
rust-lang/rust#74726 (comment)

Additionally, it has some other side benefits. I imagine it probably
improves compile times a bit for crates using `tracing` (although I
haven't tested this), since the compiler is generating fewer callsite
implementations. Reducing the number of branches in the macro expansion
probably helps make the pesky `cognitive_complexity` Clippy lint show up
less often, and improves maintainability for the macros as well.


Signed-off-by: Eliza Weisman <[email protected]>
Co-authored-by: David Barsky <[email protected]>
  • Loading branch information
hawkw and davidbarsky authored Jul 31, 2020
1 parent ed803e1 commit 90dfcca
Show file tree
Hide file tree
Showing 2 changed files with 163 additions and 129 deletions.
109 changes: 100 additions & 9 deletions tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -893,16 +893,107 @@ pub mod subscriber;

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

#[doc(hidden)]
// resolves https://github.com/tokio-rs/tracing/issues/783 by forcing a monomorphization
// in tracing, not downstream crates.
#[inline]
pub fn is_enabled(meta: &crate::Metadata<'_>) -> bool {
crate::dispatcher::get_default(|current| current.enabled(meta))
/// Callsite implementation used by macro-generated code.
///
/// /!\ WARNING: This is *not* a stable API! /!\
/// This type, 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.
#[derive(Debug)]
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(0),
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`.
///
/// /!\ 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;
}

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.
///
/// /!\ 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 {
match self.interest.load(Ordering::Relaxed) {
0 => Interest::never(),
2 => Interest::always(),
_ => Interest::sometimes(),
}
}
}

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

mod sealed {
Expand Down
Loading

0 comments on commit 90dfcca

Please sign in to comment.