Skip to content

Commit

Permalink
tracing: move ValueSet construction out of closures (tokio-rs#987)
Browse files Browse the repository at this point in the history 
## Motivation

In PR tokio-rs#943, the construction of `ValueSet`s for events and spans was
moved out of the code expanded at the callsite and into a closure, in
order to reduce the amount of assembly generated in functions containing
tracing macros. However, this introduced an accidental breaking change
for some dependent crates. Borrowing values inside a closure meant that
when a field of a struct, array, or tuple was used as a field value, the
closure must borrow the _entire_ struct, array, or tuple, rather than
the individual field. This broke code where another unrelated field of
that struct, array, or tuple would then be mutably borrowed or moved
elsewhere. 

## Solution

This branch fixes the breaking change by moving `ValueSet` construction
back out of a closure and into the code expanded at the callsite. This
_does_ regress the amount of assembly generated a bit: a function
containing a single `event!` macro generates 32 instructions in release
mode on master, and after this change, it generates 83 instructions.
However, this is better than reverting PR tokio-rs#943 entirely, which generates
103 instructions for the same function. This change allows us to
continue to benefit from *some* of the changes made in tokio-rs#943, although we
no longer can benefit from the most significant one.

Rather than trying to further optimize the macro expanded code now, I
think we should wait for the `ValueSet` rework that will land in
`tracing` 0.2, where we could potentially generate significantly less
code by virtue of constructing a `ValueSet` with a much simpler array
literal (no `FieldSet` iteration required).

Fixes tokio-rs#954 
Closes tokio-rs#986

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw committed Sep 25, 2020
1 parent 6f01226 commit 216b98e
Show file tree
Hide file tree
Showing 3 changed files with 67 additions and 54 deletions.
27 changes: 3 additions & 24 deletions tracing/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1000,12 +1000,9 @@ pub mod __macro_support {
}
}

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)
}
});
pub fn is_enabled(&self, interest: Interest) -> bool {
interest.is_always()
|| crate::dispatcher::get_default(|default| default.enabled(self.meta))
}

#[inline]
Expand All @@ -1019,24 +1016,6 @@ pub mod __macro_support {
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
66 changes: 36 additions & 30 deletions tracing/src/macros.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,17 +32,17 @@ macro_rules! span {
fields: $($fields)*
};
let mut interest = $crate::subscriber::Interest::never();
if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{
CALLSITE.dispatch_span(interest, |current| {
let meta = CALLSITE.metadata();
// span with parent
$crate::Span::child_of_with(
$parent,
meta,
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*),
current,
)
})
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with explicit parent
$crate::Span::child_of(
$parent,
meta,
&$crate::valueset!(meta.fields(), $($fields)*),
)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! {{
Expand All @@ -63,15 +63,16 @@ macro_rules! span {
fields: $($fields)*
};
let mut interest = $crate::subscriber::Interest::never();
if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{
CALLSITE.dispatch_span(interest, |current| {
let meta = CALLSITE.metadata();
$crate::Span::new_with(
meta,
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*),
current,
)
})
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with contextual parent
$crate::Span::new(
meta,
&$crate::valueset!(meta.fields(), $($fields)*),
)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! {{
Expand Down Expand Up @@ -605,11 +606,14 @@ macro_rules! event {
fields: $($fields)*
};
let interest = CALLSITE.interest();
if !interest.is_never() {
CALLSITE.dispatch_event(interest, |current| {
let meta = CALLSITE.metadata();
current.event(&$crate::Event::new_child_of($parent, meta, &$crate::valueset!(meta.fields(), $($fields)*)))
});
if !interest.is_never() && CALLSITE.is_enabled(interest) {
let meta = CALLSITE.metadata();
// event with explicit parent
$crate::Event::child_of(
$parent,
meta,
&$crate::valueset!(meta.fields(), $($fields)*)
);
}
}
);
Expand Down Expand Up @@ -649,11 +653,13 @@ macro_rules! event {
fields: $($fields)*
};
let interest = CALLSITE.interest();
if !interest.is_never() {
CALLSITE.dispatch_event(interest, |current| {
let meta = CALLSITE.metadata();
current.event(&$crate::Event::new(meta, &$crate::valueset!(meta.fields(), $($fields)*)));
});
if !interest.is_never() && CALLSITE.is_enabled(interest) {
let meta = CALLSITE.metadata();
// event with contextual parent
$crate::Event::dispatch(
meta,
&$crate::valueset!(meta.fields(), $($fields)*)
);
}
}
});
Expand Down
28 changes: 28 additions & 0 deletions tracing/tests/macros.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -836,6 +836,34 @@ fn field_shorthand_only() {
event!(Level::TRACE, ?pos.x, ?pos.y);
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn borrow_val_events() {
// Reproduces https://github.com/tokio-rs/tracing/issues/954
let mut foo = (String::new(), String::new());
let zero = &mut foo.0;
trace!(one = ?foo.1);
debug!(one = ?foo.1);
info!(one = ?foo.1);
warn!(one = ?foo.1);
error!(one = ?foo.1);
zero.push_str("hello world");
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn borrow_val_spans() {
// Reproduces https://github.com/tokio-rs/tracing/issues/954
let mut foo = (String::new(), String::new());
let zero = &mut foo.0;
let _span = trace_span!("span", one = ?foo.1);
let _span = debug_span!("span", one = ?foo.1);
let _span = info_span!("span", one = ?foo.1);
let _span = warn_span!("span", one = ?foo.1);
let _span = error_span!("span", one = ?foo.1);
zero.push_str("hello world");
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn callsite_macro_api() {
Expand Down

0 comments on commit 216b98e

Please sign in to comment.