tracing: reduce disabled span Drop overhead (#1974)

## Motivation

Disabled spans introduce a non-trivial amount of overhead, even when no
`tracing` subscriber is in use. This is primarily due to the need to
create and then drop the empty `Span` struct even when the span is
disabled.

While thinking about #1970 a bit, I noticed that one source of overhead
is that dropping a disabled span always causes a function call, even
when the span is empty. This could be avoided.

## Solution

In this branch, I've changed the `Drop` impls for `Span`, `Entered`, and
`EnteredSpan` to be `#[inline(always)]`. In the always-inlined
functions, we perform a check for whether or not the span is empty, and
if it is not empty, we call into the dispatcher method to drop the span
or guard. The dispatcher methods are no longer inlined. Now, the
function call only occurs when the span _is_ enabled, rather than always
occurring in the `Drop` call. This significantly reduces the overhead
for holding a disabled span, or a disabled `Entered` guard, in a scope.

Also, the `log` integration when dropping a span would always check if
the span had metadata, even when `log` is disabled. This means we would
do an extra branch that wasn't necessary. I moved that into the macro
that guards for whether or not the `log` crate is enabled, which also
significantly reduces overhead.

This change reduces the overhead of a disabled span by 50-70%, per the
`no_subscriber.rs` benchmarks.  I also improved those benchmarks a
bit to test more cases, in order to find the precise difference in overhead
between just constructing `Span::none()` and the actual `span!` macros.

<details>

<summary><code>no_subscriber.rs</code> benchmark results</summary>

```
no_subscriber/span      time:   [696.37 ps 696.53 ps 696.73 ps]
                        change: [-50.599% -50.577% -50.544%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) high mild
  4 (4.00%) high severe
no_subscriber/span_enter
                        time:   [465.58 ps 466.35 ps 467.61 ps]
                        change: [-71.350% -71.244% -71.138%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  4 (4.00%) high mild
  2 (2.00%) high severe
no_subscriber/empty_span
                        time:   [226.15 ps 226.73 ps 227.36 ps]
                        change: [-84.404% -84.045% -83.663%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  5 (5.00%) high mild
  1 (1.00%) high severe
no_subscriber/empty_struct
                        time:   [693.32 ps 693.76 ps 694.30 ps]
                        change: [+1.7164% +1.9701% +2.2540%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 8 outliers among 100 measurements (8.00%)
  5 (5.00%) high mild
  3 (3.00%) high severe
no_subscriber/event     time:   [294.32 ps 301.68 ps 310.85 ps]
                        change: [+0.3073% +2.1111% +4.1919%] (p = 0.03 < 0.05)
                        Change within noise threshold.
Found 16 outliers among 100 measurements (16.00%)
  2 (2.00%) high mild
  14 (14.00%) high severe
no_subscriber/relaxed_load
                        time:   [463.24 ps 463.74 ps 464.33 ps]
                        change: [+1.4046% +1.6735% +1.9366%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 16 outliers among 100 measurements (16.00%)
  1 (1.00%) low severe
  6 (6.00%) high mild
  9 (9.00%) high severe
no_subscriber/acquire_load
                        time:   [465.28 ps 465.68 ps 466.08 ps]
                        change: [+0.6837% +1.1755% +1.6034%] (p = 0.00 < 0.05)
                        Change within noise threshold.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) high mild
  4 (4.00%) high severe
no_subscriber/log       time:   [231.11 ps 231.27 ps 231.45 ps]
                        change: [-4.4700% -2.3810% -0.9164%] (p = 0.00 < 0.05)
                        Change within noise threshold.
Found 17 outliers among 100 measurements (17.00%)
  3 (3.00%) low mild
  8 (8.00%) high mild
  6 (6.00%) high severe

no_subscriber_field/span
                        time:   [1.6334 ns 1.6343 ns 1.6354 ns]
                        change: [-12.401% -12.337% -12.279%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild
no_subscriber_field/event
                        time:   [461.54 ps 461.84 ps 462.14 ps]
                        change: [-0.3654% +0.1235% +0.5557%] (p = 0.62 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  3 (3.00%) high mild
  3 (3.00%) high severe
no_subscriber_field/log time:   [463.52 ps 463.98 ps 464.49 ps]
                        change: [+0.3011% +0.8645% +1.6355%] (p = 0.01 < 0.05)
                        Change within noise threshold.
Found 18 outliers among 100 measurements (18.00%)
  4 (4.00%) low mild
  10 (10.00%) high mild
  4 (4.00%) high severe
```

</details>

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

tracing-core/src/dispatcher.rs

@@ -524,7 +524,6 @@ impl Dispatch {
     ///
     /// [`Subscriber`]: ../subscriber/trait.Subscriber.html
     /// [`enter`]: ../subscriber/trait.Subscriber.html#method.enter
-    #[inline]
     pub fn enter(&self, span: &span::Id) {
         self.subscriber.enter(span);
     }
@@ -536,7 +535,6 @@ impl Dispatch {
     ///
     /// [`Subscriber`]: ../subscriber/trait.Subscriber.html
     /// [`exit`]: ../subscriber/trait.Subscriber.html#method.exit
-    #[inline]
     pub fn exit(&self, span: &span::Id) {
         self.subscriber.exit(span);
     }
@@ -604,7 +602,6 @@ impl Dispatch {
     /// [`Subscriber`]: ../subscriber/trait.Subscriber.html
     /// [`try_close`]: ../subscriber/trait.Subscriber.html#method.try_close
     /// [`new_span`]: ../subscriber/trait.Subscriber.html#method.new_span
-    #[inline]
     pub fn try_close(&self, id: span::Id) -> bool {
         self.subscriber.try_close(id)
     }

tracing/benches/no_subscriber.rs

@@ -1,14 +1,54 @@
 use criterion::{black_box, criterion_group, criterion_main, Criterion};
 use tracing::Level;
 
+struct FakeEmptySpan {
+    inner: Option<(usize, std::sync::Arc<()>)>,
+    meta: Option<&'static ()>,
+}
+
+impl FakeEmptySpan {
+    fn new() -> Self {
+        Self {
+            inner: None,
+            meta: None,
+        }
+    }
+}
+
+impl Drop for FakeEmptySpan {
+    fn drop(&mut self) {
+        black_box(&self.inner);
+        black_box(&self.meta);
+    }
+}
+
 fn bench_no_subscriber(c: &mut Criterion) {
     use std::sync::atomic::{AtomicUsize, Ordering};
 
     let mut group = c.benchmark_group("no_subscriber");
 
     group.bench_function("span", |b| {
         b.iter(|| {
-            black_box(tracing::span!(Level::TRACE, "span"));
+            let span = tracing::span!(Level::TRACE, "span");
+            black_box(&span);
+        })
+    });
+    group.bench_function("span_enter", |b| {
+        b.iter(|| {
+            let span = tracing::span!(Level::TRACE, "span");
+            let _e = span.enter();
+        })
+    });
+    group.bench_function("empty_span", |b| {
+        b.iter(|| {
+            let span = tracing::span::Span::none();
+            black_box(&span);
+        });
+    });
+    group.bench_function("empty_struct", |b| {
+        b.iter(|| {
+            let span = FakeEmptySpan::new();
+            black_box(&span);
         })
     });
     group.bench_function("event", |b| {

tracing/src/span.rs

@@ -768,10 +768,10 @@ impl Span {
     /// info!("i'm outside the span!")
     /// ```
     ///
-    /// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
-    /// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
-    /// [`Id`]: ../struct.Id.html
-    #[inline]
+    /// [`Subscriber::enter`]: super::subscriber::Subscriber::enter()
+    /// [`Subscriber::exit`]: super::subscriber::Subscriber::exit()
+    /// [`Id`]: super::Id
+    #[inline(always)]
     pub fn enter(&self) -> Entered<'_> {
         self.do_enter();
         Entered { span: self }
@@ -878,10 +878,11 @@ impl Span {
     /// span.record("some_field", &"hello world!");
     /// ```
     ///
-    /// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
-    /// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
-    /// [`Id`]: ../struct.Id.html
-    #[inline]
+
+    /// [`Subscriber::enter`]: super::subscriber::Subscriber::enter()
+    /// [`Subscriber::exit`]: super::subscriber::Subscriber::exit()
+    /// [`Id`]: super::Id
+    #[inline(always)]
     pub fn entered(self) -> EnteredSpan {
         self.do_enter();
         EnteredSpan {
@@ -1020,7 +1021,7 @@ impl Span {
         self
     }
 
-    #[inline]
+    #[inline(always)]
     fn do_enter(&self) {
         if let Some(inner) = self.inner.as_ref() {
             inner.subscriber.enter(&inner.id);
@@ -1037,7 +1038,7 @@ impl Span {
     //
     // Running this behaviour on drop rather than with an explicit function
     // call means that spans may still be exited when unwinding.
-    #[inline]
+    #[inline(always)]
     fn do_exit(&self) {
         if let Some(inner) = self.inner.as_ref() {
             inner.subscriber.exit(&inner.id);
@@ -1438,6 +1439,7 @@ impl<'a> From<&'a EnteredSpan> for Option<Id> {
 }
 
 impl Drop for Span {
+    #[inline(always)]
     fn drop(&mut self) {
         if let Some(Inner {
             ref id,
@@ -1447,15 +1449,15 @@ impl Drop for Span {
             subscriber.try_close(id.clone());
         }
 
-        if let Some(_meta) = self.meta {
-            if_log_enabled! { crate::Level::TRACE, {
+        if_log_enabled! { crate::Level::TRACE, {
+            if let Some(meta) = self.meta {
                 self.log(
                     LIFECYCLE_LOG_TARGET,
                     log::Level::Trace,
-                    format_args!("-- {}", _meta.name()),
+                    format_args!("-- {}", meta.name()),
                 );
-            }}
-        }
+            }
+        }}
     }
 }
 
@@ -1547,14 +1549,14 @@ impl Deref for EnteredSpan {
 }
 
 impl<'a> Drop for Entered<'a> {
-    #[inline]
+    #[inline(always)]
     fn drop(&mut self) {
         self.span.do_exit()
     }
 }
 
 impl Drop for EnteredSpan {
-    #[inline]
+    #[inline(always)]
     fn drop(&mut self) {
         self.span.do_exit()
     }