From b8f63308d78e66ce44965e57dff6b222fa1fddc8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Mon, 11 Mar 2019 15:29:00 -0700 Subject: [PATCH] trace-core: Pass dispatcher by ref to `dispatcher::with_default` (#971) * 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 * 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 --- tokio-trace/benches/subscriber.rs | 7 ++ tokio-trace/examples/sloggish/main.rs | 2 +- tokio-trace/src/span.rs | 4 +- tokio-trace/src/subscriber.rs | 2 +- tokio-trace/tests/dispatcher.rs | 73 ------------------- tokio-trace/tests/span.rs | 62 ++++++++-------- tokio-trace/tests/subscriber.rs | 8 +- .../tokio-trace-core/src/dispatcher.rs | 3 +- 8 files changed, 47 insertions(+), 114 deletions(-) delete mode 100644 tokio-trace/tests/dispatcher.rs diff --git a/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs index 295a1f5bb..18ece466c 100644 --- a/tokio-trace/benches/subscriber.rs +++ b/tokio-trace/benches/subscriber.rs @@ -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] diff --git a/tokio-trace/examples/sloggish/main.rs b/tokio-trace/examples/sloggish/main.rs index fb26a8350..443fb341d 100644 --- a/tokio-trace/examples/sloggish/main.rs +++ b/tokio-trace/examples/sloggish/main.rs @@ -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"); diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs index 7d28e16e4..978cdb1e7 100644 --- a/tokio-trace/src/span.rs +++ b/tokio-trace/src/span.rs @@ -292,12 +292,12 @@ impl<'a> Span<'a> { /// Returns the result of evaluating `f`. pub fn enter 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(), } } diff --git a/tokio-trace/src/subscriber.rs b/tokio-trace/src/subscriber.rs index e1c8c457b..07ee29727 100644 --- a/tokio-trace/src/subscriber.rs +++ b/tokio-trace/src/subscriber.rs @@ -15,5 +15,5 @@ pub fn with_default(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) } diff --git a/tokio-trace/tests/dispatcher.rs b/tokio-trace/tests/dispatcher.rs deleted file mode 100644 index 816968f2b..000000000 --- a/tokio-trace/tests/dispatcher.rs +++ /dev/null @@ -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(); -} diff --git a/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs index 1fb3a530b..5627a4e3d 100644 --- a/tokio-trace/tests/span.rs +++ b/tokio-trace/tests/span.rs @@ -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); diff --git a/tokio-trace/tests/subscriber.rs b/tokio-trace/tests/subscriber.rs index 21a8a480b..eee276ca6 100644 --- a/tokio-trace/tests/subscriber.rs +++ b/tokio-trace/tests/subscriber.rs @@ -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); diff --git a/tokio-trace/tokio-trace-core/src/dispatcher.rs b/tokio-trace/tokio-trace-core/src/dispatcher.rs index 9c17c48bf..590980c45 100644 --- a/tokio-trace/tokio-trace-core/src/dispatcher.rs +++ b/tokio-trace/tokio-trace-core/src/dispatcher.rs @@ -33,7 +33,7 @@ thread_local! { /// [span]: ../span/index.html /// [`Subscriber`]: ../subscriber/trait.Subscriber.html /// [`Event`]: ../event/struct.Event.html -pub fn with_default(dispatcher: Dispatch, f: impl FnOnce() -> T) -> T { +pub fn with_default(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(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()