tokio-rs/tokio
1
0
Fork 0
mirror of https://github.com/tokio-rs/tokio.git synced 2026-08-15 00:00:15 +02:00
Code Issues Packages Projects Releases Wiki Activity

trace-core: Pass dispatcher by ref to dispatcher::with_default (#971)

Browse Source 
* trace-core: Pass dispatcher by ref to `dispatcher::with_default`

As requested by @carllerche in https://github.com/tokio-rs/tokio/pull/966#discussion_r264380005, this branch changes the
`dispatcher::with_default` function in `tokio-trace-core` to take the
dispatcher by ref and perform the clone internally. This makes this
function more consistant with other `with_default` functions in other
crates.

Signed-off-by: Eliza Weisman <[email protected]>

* trace: Don't set the default dispatcher on entering a span

Setting the default dispatcher on span entry is a relic of when spans
tracked their parent's ID. At that time, it was necessary to ensure that
any spans created inside a span were observed by the same subscriber
that originally provided the entered span with an ID, as otherwise, new
spans would be created with parent IDs that did not originate from that
subscriber.

Now that spans don't track their parent ID, this is no longer necessary.
However, removing this behavior does mean that if a span is entered
outside of the subscriber context it was created in, any subsequent
spans will be observed by the current default subscriber and thus will
not be part of the original span's trace tree. Since subscribers are not
expected to change frequently, and spans are not expected to move
between them, this is likely acceptable.

I've removed the tests for the old behavior.

Note that this change improves the performance of span entry/exit fairly
significantly. Here are the results of running a benchmark that enters
a span, does nothing, and immediately exits it, before this change:

```
test enter_span              ... bench:          93 ns/iter (+/- 14)
```

...and after:

```
test enter_span              ... bench:          51 ns/iter (+/- 9)
```

Signed-off-by: Eliza Weisman <[email protected]>
This commit is contained in:
Eliza Weisman
2019-03-11 15:29:00 -07:00
committed by GitHub
parent 4313d65b38
commit b8f63308d7
8 changed files with 47 additions and 114 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tokio-trace/benches/subscriber.rs
+7
View File
@@ -100,6 +100,13 @@ fn span_no_fields(b: &mut Bencher) {
tokio_trace::subscriber::with_default(EnabledSubscriber, || b.iter(|| span!("span")));
}
#[bench]
fn enter_span(b: &mut Bencher) {
tokio_trace::subscriber::with_default(EnabledSubscriber, || {
b.iter(|| test::black_box(span!("span").enter(|| {})))
});
}
#[bench]
fn span_repeatedly(b: &mut Bencher) {
#[inline]
tokio-trace/examples/sloggish/main.rs
+1 -1
View File
@@ -21,7 +21,7 @@ use self::sloggish_subscriber::SloggishSubscriber;
fn main() {
let subscriber = SloggishSubscriber::new(2);
tokio_trace::dispatcher::with_default(tokio_trace::Dispatch::new(subscriber), || {
tokio_trace::subscriber::with_default(subscriber, || {
span!("", version = &field::display(5.0)).enter(|| {
span!("server", host = "localhost", port = 8080).enter(|| {
info!("starting");
tokio-trace/src/span.rs
+2 -2
View File
@@ -292,12 +292,12 @@ impl<'a> Span<'a> {
/// Returns the result of evaluating `f`.
pub fn enter<F: FnOnce() -> T, T>(&mut self, f: F) -> T {
match self.inner.take() {
Some(inner) => dispatcher::with_default(inner.subscriber.clone(), || {
Some(inner) => {
let guard = inner.enter();
let result = f();
self.inner = guard.exit();
result
}),
}
None => f(),
}
}
tokio-trace/src/subscriber.rs
+1 -1
View File
@@ -15,5 +15,5 @@ pub fn with_default<T, S>(subscriber: S, f: impl FnOnce() -> T) -> T
where
S: Subscriber + Send + Sync + 'static,
{
::dispatcher::with_default(::Dispatch::new(subscriber), f)
::dispatcher::with_default(&::Dispatch::new(subscriber), f)
}
tokio-trace/tests/dispatcher.rs
-73
View File
@@ -1,73 +0,0 @@
#[macro_use]
extern crate tokio_trace;
mod support;
use self::support::*;
use tokio_trace::{dispatcher, Dispatch};
#[test]
fn dispatcher_is_sticky() {
// Test ensuring that entire trace trees are collected by the same
// dispatcher, even across dispatcher context switches.
let (subscriber1, handle1) = subscriber::mock()
.enter(span::mock().named("foo"))
.exit(span::mock().named("foo"))
.enter(span::mock().named("foo"))
.enter(span::mock().named("bar"))
.exit(span::mock().named("bar"))
.drop_span(span::mock().named("bar"))
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
let mut foo = dispatcher::with_default(Dispatch::new(subscriber1), || {
let mut foo = span!("foo");
foo.enter(|| {});
foo
});
dispatcher::with_default(Dispatch::new(subscriber::mock().done().run()), move || {
foo.enter(|| span!("bar").enter(|| {}))
});
handle1.assert_finished();
}
#[test]
fn dispatcher_isnt_too_sticky() {
// Test ensuring that new trace trees are collected by the current
// dispatcher.
let (subscriber1, handle1) = subscriber::mock()
.enter(span::mock().named("foo"))
.exit(span::mock().named("foo"))
.enter(span::mock().named("foo"))
.enter(span::mock().named("bar"))
.exit(span::mock().named("bar"))
.drop_span(span::mock().named("bar"))
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
let (subscriber2, handle2) = subscriber::mock()
.enter(span::mock().named("baz"))
.enter(span::mock().named("quux"))
.exit(span::mock().named("quux"))
.drop_span(span::mock().named("quux"))
.exit(span::mock().named("baz"))
.drop_span(span::mock().named("baz"))
.done()
.run_with_handle();
let mut foo = dispatcher::with_default(Dispatch::new(subscriber1), || {
let mut foo = span!("foo");
foo.enter(|| {});
foo
});
let mut baz = dispatcher::with_default(Dispatch::new(subscriber2), || span!("baz"));
dispatcher::with_default(Dispatch::new(subscriber::mock().done().run()), move || {
foo.enter(|| span!("bar").enter(|| {}));
baz.enter(|| span!("quux").enter(|| {}))
});
handle1.assert_finished();
handle2.assert_finished();
}
tokio-trace/tests/span.rs
+30 -32
View File
@@ -5,10 +5,9 @@ mod support;
use self::support::*;
use std::thread;
use tokio_trace::{
dispatcher,
field::{debug, display},
subscriber::with_default,
Dispatch, Level, Span,
Level, Span,
};
#[test]
@@ -22,7 +21,7 @@ fn closed_handle_cannot_be_entered() {
.exit(span::mock().named("foo"))
.run();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
span!("foo").enter(|| {
let bar = span!("bar");
let mut another_bar = bar.clone();
@@ -44,7 +43,7 @@ fn handles_to_the_same_span_are_equal() {
// `Subscriber::enabled`, so that the spans will be constructed. We
// won't enter any spans in this test, so the subscriber won't actually
// expect to see any spans.
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
with_default(subscriber::mock().run(), || {
let foo1 = span!("foo");
let foo2 = foo1.clone();
// Two handles that point to the same span are equal.
@@ -54,7 +53,7 @@ fn handles_to_the_same_span_are_equal() {
#[test]
fn handles_to_different_spans_are_not_equal() {
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
with_default(subscriber::mock().run(), || {
// Even though these spans have the same name and fields, they will have
// differing metadata, since they were created on different lines.
let foo1 = span!("foo", bar = 1u64, baz = false);
@@ -72,7 +71,7 @@ fn handles_to_different_spans_with_the_same_metadata_are_not_equal() {
span!("foo", bar = 1u64, baz = false)
}
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
with_default(subscriber::mock().run(), || {
let foo1 = make_span();
let foo2 = make_span();
@@ -89,18 +88,18 @@ fn spans_always_go_to_the_subscriber_that_tagged_them() {
.enter(span::mock().named("foo"))
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done();
let subscriber1 = Dispatch::new(subscriber1.run());
let subscriber2 = Dispatch::new(subscriber::mock().run());
.done()
.run();
let subscriber2 = subscriber::mock().run();
let mut foo = dispatcher::with_default(subscriber1, || {
let mut foo = with_default(subscriber1, || {
let mut foo = span!("foo");
foo.enter(|| {});
foo
});
// Even though we enter subscriber 2's context, the subscriber that
// tagged the span should see the enter/exit.
dispatcher::with_default(subscriber2, move || foo.enter(|| {}));
with_default(subscriber2, move || foo.enter(|| {}));
}
#[test]
@@ -111,9 +110,9 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
.enter(span::mock().named("foo"))
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done();
let subscriber1 = Dispatch::new(subscriber1.run());
let mut foo = dispatcher::with_default(subscriber1, || {
.done()
.run();
let mut foo = with_default(subscriber1, || {
let mut foo = span!("foo");
foo.enter(|| {});
foo
@@ -122,7 +121,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
// Even though we enter subscriber 2's context, the subscriber that
// tagged the span should see the enter/exit.
thread::spawn(move || {
dispatcher::with_default(Dispatch::new(subscriber::mock().run()), || {
with_default(subscriber::mock().run(), || {
foo.enter(|| {});
})
})
@@ -138,7 +137,7 @@ fn dropping_a_span_calls_drop_span() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let mut span = span!("foo");
span.enter(|| {});
drop(span);
@@ -156,7 +155,7 @@ fn span_closes_after_event() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
span!("foo").enter(|| {
event!(Level::DEBUG, {}, "my event!");
});
@@ -177,7 +176,7 @@ fn new_span_after_event() {
.drop_span(span::mock().named("bar"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
span!("foo").enter(|| {
event!(Level::DEBUG, {}, "my event!");
});
@@ -196,7 +195,7 @@ fn event_outside_of_span() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
debug!("my event!");
span!("foo").enter(|| {});
});
@@ -209,7 +208,7 @@ fn cloning_a_span_calls_clone_span() {
let (subscriber, handle) = subscriber::mock()
.clone_span(span::mock().named("foo"))
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let span = span!("foo");
let _span2 = span.clone();
});
@@ -224,7 +223,7 @@ fn drop_span_when_exiting_dispatchers_context() {
.drop_span(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let span = span!("foo");
let _span2 = span.clone();
drop(span);
@@ -244,17 +243,16 @@ fn clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span() {
.drop_span(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.run_with_handle();
let subscriber1 = Dispatch::new(subscriber1);
let subscriber2 = Dispatch::new(subscriber::mock().done().run());
let subscriber2 = subscriber::mock().done().run();
let mut foo = dispatcher::with_default(subscriber1, || {
let mut foo = with_default(subscriber1, || {
let mut foo = span!("foo");
foo.enter(|| {});
foo
});
// Even though we enter subscriber 2's context, the subscriber that
// tagged the span should see the enter/exit.
dispatcher::with_default(subscriber2, move || {
with_default(subscriber2, move || {
let foo2 = foo.clone();
foo.enter(|| {});
drop(foo);
@@ -272,7 +270,7 @@ fn span_closes_when_exited() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let mut foo = span!("foo");
assert!(!foo.is_closed());
@@ -296,7 +294,7 @@ fn entering_a_closed_span_again_is_a_no_op() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let mut foo = span!("foo");
foo.close();
@@ -324,7 +322,7 @@ fn moved_field() {
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let from = "my span";
let mut span = span!("foo", bar = display(format!("hello from {}", from)));
span.enter(|| {});
@@ -349,7 +347,7 @@ fn borrowed_field() {
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let from = "my span";
let mut message = format!("hello from {}", from);
let mut span = span!("foo", bar = display(&message));
@@ -389,7 +387,7 @@ fn move_field_out_of_struct() {
)
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let pos = Position {
x: 3.234,
y: -1.223,
@@ -421,7 +419,7 @@ fn add_field_after_new_span() {
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let mut span = span!("foo", bar = 5, baz);
span.record("baz", &true);
span.enter(|| {})
@@ -448,7 +446,7 @@ fn add_fields_only_after_new_span() {
.done()
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
let mut span = span!("foo", bar, baz);
span.record("bar", &5);
span.record("baz", &true);
tokio-trace/tests/subscriber.rs
+4 -4
View File
@@ -3,7 +3,7 @@ extern crate tokio_trace;
mod support;
use self::support::*;
use tokio_trace::{dispatcher, Dispatch};
use tokio_trace::subscriber::with_default;
use std::sync::{
atomic::{AtomicUsize, Ordering},
@@ -33,7 +33,7 @@ fn filters_are_not_reevaluated_for_the_same_span() {
})
.run_with_handle();
dispatcher::with_default(Dispatch::new(subscriber), move || {
with_default(subscriber, move || {
// Enter "alice" and then "bob". The dispatcher expects to see "bob" but
// not "alice."
let mut alice = span!("alice");
@@ -87,7 +87,7 @@ fn filters_are_reevaluated_for_different_call_sites() {
})
.run();
dispatcher::with_default(Dispatch::new(subscriber), move || {
with_default(subscriber, move || {
// Enter "charlie" and then "dave". The dispatcher expects to see "dave" but
// not "charlie."
let mut charlie = span!("charlie");
@@ -146,7 +146,7 @@ fn filter_caching_is_lexically_scoped() {
})
.run();
dispatcher::with_default(Dispatch::new(subscriber), || {
with_default(subscriber, || {
// Call the function once. The filter should be re-evaluated.
assert!(my_great_function());
assert_eq!(count.load(Ordering::Relaxed), 1);
tokio-trace/tokio-trace-core/src/dispatcher.rs
+2 -1
View File
@@ -33,7 +33,7 @@ thread_local! {
/// [span]: ../span/index.html
/// [`Subscriber`]: ../subscriber/trait.Subscriber.html
/// [`Event`]: ../event/struct.Event.html
pub fn with_default<T>(dispatcher: Dispatch, f: impl FnOnce() -> T) -> T {
pub fn with_default<T>(dispatcher: &Dispatch, f: impl FnOnce() -> T) -> T {
// A drop guard that resets CURRENT_DISPATCH to the prior dispatcher.
// Using this (rather than simply resetting after calling `f`) ensures
// that we always reset to the prior dispatcher even if `f` panics.
@@ -48,6 +48,7 @@ pub fn with_default<T>(dispatcher: Dispatch, f: impl FnOnce() -> T) -> T {
}
}
let dispatcher = dispatcher.clone();
let prior = CURRENT_DISPATCH.try_with(|current| current.replace(dispatcher));
let _guard = ResetGuard(prior.ok());
f()