Skip to content

Commit 216b98e

Browse files
hawkwhawkw
authored
tracing: move ValueSet construction out of closures (#987)
## Motivation In PR #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 #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 #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 #954 Closes #986 Signed-off-by: Eliza Weisman <eliza@buoyant.io>
1 parent 6f01226 commit 216b98e

File tree

3 files changed

+67
-54
lines changed

3 files changed

+67
-54
lines changed

‎tracing/src/lib.rs‎

Lines changed: 3 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -1000,12 +1000,9 @@ pub mod __macro_support {
10001000
}
10011001
}
10021002

1003-
pub fn dispatch_event(&'static self, interest: Interest, f: impl FnOnce(&crate::Dispatch)) {
1004-
tracing_core::dispatcher::get_current(|current| {
1005-
if interest.is_always() || current.enabled(self.meta) {
1006-
f(current)
1007-
}
1008-
});
1003+
pub fn is_enabled(&self, interest: Interest) -> bool {
1004+
interest.is_always()
1005+
|| crate::dispatcher::get_default(|default| default.enabled(self.meta))
10091006
}
10101007

10111008
#[inline]
@@ -1019,24 +1016,6 @@ pub mod __macro_support {
10191016
pub fn disabled_span(&self) -> crate::Span {
10201017
crate::Span::none()
10211018
}
1022-
1023-
pub fn dispatch_span(
1024-
&'static self,
1025-
interest: Interest,
1026-
f: impl FnOnce(&crate::Dispatch) -> crate::Span,
1027-
) -> crate::Span {
1028-
if interest.is_never() {
1029-
return self.disabled_span();
1030-
}
1031-
1032-
tracing_core::dispatcher::get_current(|current| {
1033-
if interest.is_always() || current.enabled(self.meta) {
1034-
return f(current);
1035-
}
1036-
self.disabled_span()
1037-
})
1038-
.unwrap_or_else(|| self.disabled_span())
1039-
}
10401019
}
10411020

10421021
impl Callsite for MacroCallsite {

‎tracing/src/macros.rs‎

Lines changed: 36 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -32,17 +32,17 @@ macro_rules! span {
3232
fields: $($fields)*
3333
};
3434
let mut interest = $crate::subscriber::Interest::never();
35-
if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{
36-
CALLSITE.dispatch_span(interest, |current| {
37-
let meta = CALLSITE.metadata();
38-
// span with parent
39-
$crate::Span::child_of_with(
40-
$parent,
41-
meta,
42-
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*),
43-
current,
44-
)
45-
})
35+
if $crate::level_enabled!($lvl)
36+
&& { interest = CALLSITE.interest(); !interest.is_never() }
37+
&& CALLSITE.is_enabled(interest)
38+
{
39+
let meta = CALLSITE.metadata();
40+
// span with explicit parent
41+
$crate::Span::child_of(
42+
$parent,
43+
meta,
44+
&$crate::valueset!(meta.fields(), $($fields)*),
45+
)
4646
} else {
4747
let span = CALLSITE.disabled_span();
4848
$crate::if_log_enabled! {{
@@ -63,15 +63,16 @@ macro_rules! span {
6363
fields: $($fields)*
6464
};
6565
let mut interest = $crate::subscriber::Interest::never();
66-
if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() }{
67-
CALLSITE.dispatch_span(interest, |current| {
68-
let meta = CALLSITE.metadata();
69-
$crate::Span::new_with(
70-
meta,
71-
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*),
72-
current,
73-
)
74-
})
66+
if $crate::level_enabled!($lvl)
67+
&& { interest = CALLSITE.interest(); !interest.is_never() }
68+
&& CALLSITE.is_enabled(interest)
69+
{
70+
let meta = CALLSITE.metadata();
71+
// span with contextual parent
72+
$crate::Span::new(
73+
meta,
74+
&$crate::valueset!(meta.fields(), $($fields)*),
75+
)
7576
} else {
7677
let span = CALLSITE.disabled_span();
7778
$crate::if_log_enabled! {{
@@ -605,11 +606,14 @@ macro_rules! event {
605606
fields: $($fields)*
606607
};
607608
let interest = CALLSITE.interest();
608-
if !interest.is_never() {
609-
CALLSITE.dispatch_event(interest, |current| {
610-
let meta = CALLSITE.metadata();
611-
current.event(&$crate::Event::new_child_of($parent, meta, &$crate::valueset!(meta.fields(), $($fields)*)))
612-
});
609+
if !interest.is_never() && CALLSITE.is_enabled(interest) {
610+
let meta = CALLSITE.metadata();
611+
// event with explicit parent
612+
$crate::Event::child_of(
613+
$parent,
614+
meta,
615+
&$crate::valueset!(meta.fields(), $($fields)*)
616+
);
613617
}
614618
}
615619
);
@@ -649,11 +653,13 @@ macro_rules! event {
649653
fields: $($fields)*
650654
};
651655
let interest = CALLSITE.interest();
652-
if !interest.is_never() {
653-
CALLSITE.dispatch_event(interest, |current| {
654-
let meta = CALLSITE.metadata();
655-
current.event(&$crate::Event::new(meta, &$crate::valueset!(meta.fields(), $($fields)*)));
656-
});
656+
if !interest.is_never() && CALLSITE.is_enabled(interest) {
657+
let meta = CALLSITE.metadata();
658+
// event with contextual parent
659+
$crate::Event::dispatch(
660+
meta,
661+
&$crate::valueset!(meta.fields(), $($fields)*)
662+
);
657663
}
658664
}
659665
});

‎tracing/tests/macros.rs‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -836,6 +836,34 @@ fn field_shorthand_only() {
836836
event!(Level::TRACE, ?pos.x, ?pos.y);
837837
}
838838

839+
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
840+
#[test]
841+
fn borrow_val_events() {
842+
// Reproduces https://github.com/tokio-rs/tracing/issues/954
843+
let mut foo = (String::new(), String::new());
844+
let zero = &mut foo.0;
845+
trace!(one = ?foo.1);
846+
debug!(one = ?foo.1);
847+
info!(one = ?foo.1);
848+
warn!(one = ?foo.1);
849+
error!(one = ?foo.1);
850+
zero.push_str("hello world");
851+
}
852+
853+
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
854+
#[test]
855+
fn borrow_val_spans() {
856+
// Reproduces https://github.com/tokio-rs/tracing/issues/954
857+
let mut foo = (String::new(), String::new());
858+
let zero = &mut foo.0;
859+
let _span = trace_span!("span", one = ?foo.1);
860+
let _span = debug_span!("span", one = ?foo.1);
861+
let _span = info_span!("span", one = ?foo.1);
862+
let _span = warn_span!("span", one = ?foo.1);
863+
let _span = error_span!("span", one = ?foo.1);
864+
zero.push_str("hello world");
865+
}
866+
839867
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
840868
#[test]
841869
fn callsite_macro_api() {

0 commit comments

Comments
 (0)