trace: Change `Span::enter` and `record` to take `&self` (#1029)

## Motivation

The `Span::enter` function previously required an `&mut` reference to
enter a span. This is a relic of an earlier design where span closure
logic was determined by dropping an inner span component, and is no
longer strictly necessary.

Requiring `&mut self` to enter a span leads to awkward patterns in cases
when a user wishes to enter a span and then call methods on the span
(such as recording field values). For example, we cannot say
```rust
let mut span = span!("foo", bar);
span.enter(|| {
    span.record("bar" &false);
});
```
since the span is mutably borrowed by `enter`. Instead, we must clone
the span, like so:
```rust
let mut span = span!("foo", bar);
span.clone().enter(|| {
    span.record("bar" &false);
});
```

Having to clone the span is somewhat less ergonomic, and it has
performance disadvantages as well: cloning a `Span` will clone the
span's `Dispatch` handle, requiring an `Arc` bump, as well as calling
the `Subscriber`'s `clone_span` and `drop_span` functions. If we can
enter spans without a mutable borrow, we don't have to update any of
these ref counts.

The other reason we may wish to require mutable borrows to enter a span
is if we want to disallow entering a span multiple times before exiting
it. However, it is trivially possible to re-enter a span on the same
thread regardless, by cloning the span and entering it twice. Besides,
there may be a valuable semantic meaning in entering a span from inside
itself, such as when a function is called recursively, so disallowing
this is not a goal.

## Solution

This branch rewrites the `Span::enter`, `Span::record`, and
`Span::record_all` functions to no longer require mutable borrows. 

In the case of `record` and `record_all`, this was trivial, as borrowing
mutably was not actually *necessary* for those functions. For `enter`,
the `Entered` guard type was reworked to consist of an `&'a Inner`
rather than an `Inner`, so it is no longer necessary to `take` the
span's `Inner`. 

## Notes

In addition to allowing spans to be entered without mutable borrows,
`Entered` was changed to exit the span automatically when the guard is
dropped, so we may now observe correct span exits even when unwinding.

Furthermore, this allows us to simplify the `enter` function a bit,
leading to a minor performance improvement when entering spans.

Before:
```
test enter_span              ... bench:          13 ns/iter (+/- 1)
```

...and after:
```
test enter_span              ... bench:           3 ns/iter (+/- 1)
```

Note that this branch also contains a change to make the
`subscriber::enter_span` benchmark more accurate. Previously, this
benchmark constructed a new span inside of `b.iter(|| {...})`. This
means that the benchmark was measuring not only the time taken to enter
a span, but the time taken to construct a `Span` handle as well.
However, we already have benchmarks for span construction, and the
intention of this particular benchmark was to measure the overhead of
constructing a span.

I've updated the benchmark by moving the span construction out of the
`iter` closure. Now, the span is constructed a single time and entered
on every iteration. This allows us to measure only the overhead of
actually entering a span. The "before" benchmark numbers above were
recorded after backporting this change to master, so they are "fair" to
the previous implementation. Prior to this change the benchmark took
approximately 53 ns.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

7 files changed, 64 insertions, 56 deletions

diff --git a/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs
index 34a73b8c..7f2a32f5 100644
--- a/tokio-trace/benches/subscriber.rs
+++ b/tokio-trace/benches/subscriber.rs
@@ -106,7 +106,8 @@ fn span_no_fields(b: &mut Bencher) {
 #[bench]
 fn enter_span(b: &mut Bencher) {
     tokio_trace::subscriber::with_default(EnabledSubscriber, || {
-        b.iter(|| test::black_box(span!(Level::TRACE, "span").enter(|| {})))
+        let span = span!(Level::TRACE, "span");
+        b.iter(|| test::black_box(span.enter(|| {})))
     });
 }
 
diff --git a/tokio-trace/examples/sloggish/main.rs b/tokio-trace/examples/sloggish/main.rs
index fcf48363..4aa7cf18 100644
--- a/tokio-trace/examples/sloggish/main.rs
+++ b/tokio-trace/examples/sloggish/main.rs
@@ -26,12 +26,12 @@ fn main() {
             span!(Level::TRACE, "server", host = "localhost", port = 8080).enter(|| {
                 info!("starting");
                 info!("listening");
-                let mut peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
+                let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
                 peer1.enter(|| {
                     debug!("connected");
                     debug!({ length = 2 }, "message received");
                 });
-                let mut peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
+                let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
                 peer2.enter(|| {
                     debug!("connected");
                 });
diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs
index 324dc8b1..fb8d2efb 100644
--- a/tokio-trace/src/lib.rs
+++ b/tokio-trace/src/lib.rs
@@ -159,7 +159,7 @@
 //! # use tokio_trace::Level;
 //! # fn main() {
 //! // Construct a new span named "my span" with trace log level.
-//! let mut span = span!(Level::TRACE, "my span");
+//! let span = span!(Level::TRACE, "my span");
 //! span.enter(|| {
 //!     // Any trace events in this closure or code called by it will occur within
 //!     // the span.
diff --git a/tokio-trace/src/macros.rs b/tokio-trace/src/macros.rs
index 5502a0c7..7ac62662 100644
--- a/tokio-trace/src/macros.rs
+++ b/tokio-trace/src/macros.rs
@@ -8,7 +8,7 @@
 /// # extern crate tokio_trace;
 /// # use tokio_trace::Level;
 /// # fn main() {
-/// let mut span = span!(Level::TRACE, "my span");
+/// let span = span!(Level::TRACE, "my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -64,7 +64,7 @@
 /// # extern crate tokio_trace;
 /// # use tokio_trace::Level;
 /// # fn main() {
-/// let mut my_span = span!(Level::TRACE, "my span", foo = 2, bar);
+/// let my_span = span!(Level::TRACE, "my span", foo = 2, bar);
 /// my_span.record("bar", &7);
 /// # }
 /// ```
@@ -230,7 +230,7 @@ macro_rules! span {
 /// # #[macro_use]
 /// # extern crate tokio_trace;
 /// # fn main() {
-/// let mut span = trace_span!("my span");
+/// let span = trace_span!("my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -319,7 +319,7 @@ macro_rules! trace_span {
 /// # #[macro_use]
 /// # extern crate tokio_trace;
 /// # fn main() {
-/// let mut span = debug_span!("my span");
+/// let span = debug_span!("my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -408,7 +408,7 @@ macro_rules! debug_span {
 /// # #[macro_use]
 /// # extern crate tokio_trace;
 /// # fn main() {
-/// let mut span = info_span!("my span");
+/// let span = info_span!("my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -497,7 +497,7 @@ macro_rules! info_span {
 /// # #[macro_use]
 /// # extern crate tokio_trace;
 /// # fn main() {
-/// let mut span = warn_span!("my span");
+/// let span = warn_span!("my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -585,7 +585,7 @@ macro_rules! warn_span {
 /// # #[macro_use]
 /// # extern crate tokio_trace;
 /// # fn main() {
-/// let mut span = error_span!("my span");
+/// let span = error_span!("my span");
 /// span.enter(|| {
 ///     // do work inside the span...
 /// });
@@ -1466,7 +1466,7 @@ macro_rules! __tokio_trace_log {
 #[macro_export]
 macro_rules! __tokio_trace_disabled_span {
     ($meta:expr, $valueset:expr) => {{
-        let mut span = $crate::Span::new_disabled($meta);
+        let span = $crate::Span::new_disabled($meta);
         span.record_all(&$valueset);
         span
     }};
diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs
index c392501d..57d3b8d9 100644
--- a/tokio-trace/src/span.rs
+++ b/tokio-trace/src/span.rs
@@ -15,7 +15,7 @@
 //! # use tokio_trace::Level;
 //! # fn main() {
 //! let my_var: u64 = 5;
-//! let mut my_span = span!(Level::TRACE, "my_span", my_var = &my_var);
+//! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var);
 //!
 //! my_span.enter(|| {
 //!     // perform some work in the context of `my_span`...
@@ -181,8 +181,8 @@ pub(crate) struct Inner {
 /// typically not need to interact with it directly.
 #[derive(Debug)]
 #[must_use = "once a span has been entered, it should be exited"]
-struct Entered {
-    inner: Inner,
+struct Entered<'a> {
+    inner: &'a Inner,
 }
 
 // ===== impl Span =====
@@ -270,17 +270,10 @@ impl Span {
     /// one).
     ///
     /// Returns the result of evaluating `f`.
-    pub fn enter<F: FnOnce() -> T, T>(&mut self, f: F) -> T {
+    pub fn enter<F: FnOnce() -> T, T>(&self, f: F) -> T {
         self.log(format_args!("-> {}", self.meta.name));
-        let result = match self.inner.take() {
-            Some(inner) => {
-                let guard = inner.enter();
-                let result = f();
-                self.inner = Some(guard.exit());
-                result
-            }
-            None => f(),
-        };
+        let _enter = self.inner.as_ref().map(Inner::enter);
+        let result = f();
         self.log(format_args!("<- {}", self.meta.name));
         result
     }
@@ -305,7 +298,7 @@ impl Span {
     }
 
     /// Visits that the field described by `field` has the value `value`.
-    pub fn record<Q: ?Sized, V>(&mut self, field: &Q, value: &V) -> &mut Self
+    pub fn record<Q: ?Sized, V>(&self, field: &Q, value: &V) -> &Self
     where
         Q: field::AsField,
         V: field::Value,
@@ -323,9 +316,9 @@ impl Span {
     }
 
     /// Visit all the fields in the span
-    pub fn record_all(&mut self, values: &field::ValueSet) -> &mut Self {
+    pub fn record_all(&self, values: &field::ValueSet) -> &Self {
         let record = Record::new(values);
-        if let Some(ref mut inner) = self.inner {
+        if let Some(ref inner) = self.inner {
             inner.record(&record);
         }
         self.log(format_args!("{}; {}", self.meta.name(), FmtValues(&record)));
@@ -456,7 +449,8 @@ impl Inner {
     /// This is used internally to implement `Span::enter`. It may be used for
     /// writing custom span handles, but should generally not be called directly
     /// when entering a span.
-    fn enter(self) -> Entered {
+    #[inline]
+    fn enter<'a>(&'a self) -> Entered<'a> {
         self.subscriber.enter(&self.id);
         Entered { inner: self }
     }
@@ -485,7 +479,7 @@ impl Inner {
         self.id.clone()
     }
 
-    fn record(&mut self, values: &Record) {
+    fn record(&self, values: &Record) {
         self.subscriber.record(&self.id, values)
     }
 
@@ -526,12 +520,14 @@ impl Clone for Inner {
 
 // ===== impl Entered =====
 
-impl Entered {
-    /// Exit the `Entered` guard, returning an `Inner` handle that may be used
-    /// to re-enter the span.
-    fn exit(self) -> Inner {
+impl<'a> Drop for Entered<'a> {
+    #[inline]
+    fn drop(&mut self) {
+        // Dropping the guard exits the span.
+        //
+        // Running this behaviour on drop rather than with an explicit function
+        // call means that spans may still be exited when unwinding.
         self.inner.subscriber.exit(&self.inner.id);
-        self.inner
     }
 }
 
@@ -608,3 +604,14 @@ impl<'a> AsId for &'a Option<Id> {
         self.as_ref()
     }
 }
+
+#[cfg(test)]
+mod test {
+    use super::*;
+
+    trait AssertSend: Send {}
+    impl AssertSend for Span {}
+
+    trait AssertSync: Sync {}
+    impl AssertSync for Span {}
+}
diff --git a/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs
index da96fd90..d66fcb6e 100644
--- a/tokio-trace/tests/span.rs
+++ b/tokio-trace/tests/span.rs
@@ -61,8 +61,8 @@ fn spans_always_go_to_the_subscriber_that_tagged_them() {
         .run();
     let subscriber2 = subscriber::mock().run();
 
-    let mut foo = with_default(subscriber1, || {
-        let mut foo = span!(Level::TRACE, "foo");
+    let foo = with_default(subscriber1, || {
+        let foo = span!(Level::TRACE, "foo");
         foo.enter(|| {});
         foo
     });
@@ -81,8 +81,8 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
         .drop_span(span::mock().named("foo"))
         .done()
         .run();
-    let mut foo = with_default(subscriber1, || {
-        let mut foo = span!(Level::TRACE, "foo");
+    let foo = with_default(subscriber1, || {
+        let foo = span!(Level::TRACE, "foo");
         foo.enter(|| {});
         foo
     });
@@ -107,7 +107,7 @@ fn dropping_a_span_calls_drop_span() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let mut span = span!(Level::TRACE, "foo");
+        let span = span!(Level::TRACE, "foo");
         span.enter(|| {});
         drop(span);
     });
@@ -214,8 +214,8 @@ fn clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span() {
         .run_with_handle();
     let subscriber2 = subscriber::mock().done().run();
 
-    let mut foo = with_default(subscriber1, || {
-        let mut foo = span!(Level::TRACE, "foo");
+    let foo = with_default(subscriber1, || {
+        let foo = span!(Level::TRACE, "foo");
         foo.enter(|| {});
         foo
     });
@@ -240,7 +240,7 @@ fn span_closes_when_exited() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let mut foo = span!(Level::TRACE, "foo");
+        let foo = span!(Level::TRACE, "foo");
 
         foo.enter(|| {});
 
@@ -267,7 +267,7 @@ fn moved_field() {
         .run_with_handle();
     with_default(subscriber, || {
         let from = "my span";
-        let mut span = span!(
+        let span = span!(
             Level::TRACE,
             "foo",
             bar = display(format!("hello from {}", from))
@@ -314,7 +314,7 @@ fn borrowed_field() {
     with_default(subscriber, || {
         let from = "my span";
         let mut message = format!("hello from {}", from);
-        let mut span = span!(Level::TRACE, "foo", bar = display(&message));
+        let span = span!(Level::TRACE, "foo", bar = display(&message));
         span.enter(|| {
             message.insert_str(10, " inside");
         });
@@ -360,8 +360,8 @@ fn move_field_out_of_struct() {
             x: 3.234,
             y: -1.223,
         };
-        let mut foo = span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y));
-        let mut bar = span!(Level::TRACE, "bar", position = debug(pos));
+        let foo = span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y));
+        let bar = span!(Level::TRACE, "bar", position = debug(pos));
         foo.enter(|| {});
         bar.enter(|| {});
     });
@@ -388,7 +388,7 @@ fn add_field_after_new_span() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let mut span = span!(Level::TRACE, "foo", bar = 5, baz);
+        let span = span!(Level::TRACE, "foo", bar = 5, baz);
         span.record("baz", &true);
         span.enter(|| {})
     });
@@ -415,7 +415,7 @@ fn add_fields_only_after_new_span() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let mut span = span!(Level::TRACE, "foo", bar, baz);
+        let span = span!(Level::TRACE, "foo", bar, baz);
         span.record("bar", &5);
         span.record("baz", &true);
         span.enter(|| {})
diff --git a/tokio-trace/tests/subscriber.rs b/tokio-trace/tests/subscriber.rs
index cce3090f..0e2dfb02 100644
--- a/tokio-trace/tests/subscriber.rs
+++ b/tokio-trace/tests/subscriber.rs
@@ -37,9 +37,9 @@ fn filters_are_not_reevaluated_for_the_same_span() {
     with_default(subscriber, move || {
         // Enter "alice" and then "bob". The dispatcher expects to see "bob" but
         // not "alice."
-        let mut alice = span!(Level::TRACE, "alice");
-        let mut bob = alice.enter(|| {
-            let mut bob = span!(Level::TRACE, "bob");
+        let alice = span!(Level::TRACE, "alice");
+        let bob = alice.enter(|| {
+            let bob = span!(Level::TRACE, "bob");
             bob.enter(|| ());
             bob
         });
@@ -91,9 +91,9 @@ fn filters_are_reevaluated_for_different_call_sites() {
     with_default(subscriber, move || {
         // Enter "charlie" and then "dave". The dispatcher expects to see "dave" but
         // not "charlie."
-        let mut charlie = span!(Level::TRACE, "charlie");
-        let mut dave = charlie.enter(|| {
-            let mut dave = span!(Level::TRACE, "dave");
+        let charlie = span!(Level::TRACE, "charlie");
+        let dave = charlie.enter(|| {
+            let dave = span!(Level::TRACE, "dave");
             dave.enter(|| {});
             dave
         });
@@ -111,7 +111,7 @@ fn filters_are_reevaluated_for_different_call_sites() {
 
         // A different span with the same name has a different call site, so it
         // should cause the filter to be reapplied.
-        let mut charlie2 = span!(Level::TRACE, "charlie");
+        let charlie2 = span!(Level::TRACE, "charlie");
         charlie.enter(|| {});
         assert_eq!(charlie_count.load(Ordering::Relaxed), 2);
         assert_eq!(dave_count.load(Ordering::Relaxed), 1);