tracing: fix macros "use of moved value" with log (#1823)

## Motivation

Fixes: #196, #1739

Previously, the `field` token trees would be substituted into the log
macro invocation and the `ValueSet`, potentially meaning they are
executed more than once.

## Solution

This changes the `event!` macro (and all the upstream macros like `info!`),
so that it only uses each field once when the log feature is enabled. It
does this by generating the log using the `ValueSet` meaning the token
trees are only substituted once.

Author: Skepfyr

tracing-core/src/field.rs

@@ -881,8 +881,8 @@ impl<'a> ValueSet<'a> {
 
     /// Visits all the fields in this `ValueSet` with the provided [visitor].
     ///
-    /// [visitor]: ../trait.Visit.html
-    pub(crate) fn record(&self, visitor: &mut dyn Visit) {
+    /// [visitor]: Visit
+    pub fn record(&self, visitor: &mut dyn Visit) {
         let my_callsite = self.callsite();
         for (field, value) in self.values {
             if field.callsite() != my_callsite {

tracing/benches/global_subscriber.rs

@@ -0,0 +1,137 @@
+use std::fmt::Write;
+
+use criterion::{black_box, criterion_group, criterion_main, Criterion};
+use tracing::Level;
+
+use tracing::{span, Event, Id, Metadata};
+use tracing_core::span::Current;
+
+/// A subscriber that is enabled but otherwise does nothing.
+struct EnabledSubscriber;
+
+impl tracing::Subscriber for EnabledSubscriber {
+    fn new_span(&self, span: &span::Attributes<'_>) -> Id {
+        let _ = span;
+        Id::from_u64(0xDEAD_FACE)
+    }
+
+    fn event(&self, event: &Event<'_>) {
+        let _ = event;
+    }
+
+    fn record(&self, span: &Id, values: &span::Record<'_>) {
+        let _ = (span, values);
+    }
+
+    fn record_follows_from(&self, span: &Id, follows: &Id) {
+        let _ = (span, follows);
+    }
+
+    fn enabled(&self, metadata: &Metadata<'_>) -> bool {
+        let _ = metadata;
+        true
+    }
+
+    fn enter(&self, span: &Id) {
+        let _ = span;
+    }
+
+    fn exit(&self, span: &Id) {
+        let _ = span;
+    }
+}
+
+const NOP_LOGGER: NopLogger = NopLogger;
+
+struct NopLogger;
+
+impl log::Log for NopLogger {
+    fn enabled(&self, _metadata: &log::Metadata) -> bool {
+        true
+    }
+
+    fn log(&self, record: &log::Record) {
+        if self.enabled(record.metadata()) {
+            let mut this = self;
+            let _ = write!(this, "{}", record.args());
+        }
+    }
+
+    fn flush(&self) {}
+}
+
+impl Write for &NopLogger {
+    fn write_str(&mut self, s: &str) -> std::fmt::Result {
+        black_box(s);
+        Ok(())
+    }
+}
+
+const N_SPANS: usize = 100;
+
+fn criterion_benchmark(c: &mut Criterion) {
+    let mut c = c.benchmark_group("global/subscriber");
+    let _ = tracing::subscriber::set_global_default(EnabledSubscriber);
+    let _ = log::set_logger(&NOP_LOGGER);
+    log::set_max_level(log::LevelFilter::Trace);
+    c.bench_function("span_no_fields", |b| b.iter(|| span!(Level::TRACE, "span")));
+
+    c.bench_function("event", |b| {
+        b.iter(|| {
+            tracing::event!(Level::TRACE, "hello");
+        })
+    });
+
+    c.bench_function("enter_span", |b| {
+        let span = span!(Level::TRACE, "span");
+        #[allow(clippy::unit_arg)]
+        b.iter(|| black_box(span.in_scope(|| {})))
+    });
+
+    c.bench_function("span_repeatedly", |b| {
+        #[inline]
+        fn mk_span(i: u64) -> tracing::Span {
+            span!(Level::TRACE, "span", i = i)
+        }
+
+        let n = black_box(N_SPANS);
+        b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64)))
+    });
+
+    c.bench_function("span_with_fields", |b| {
+        b.iter(|| {
+            span!(
+                Level::TRACE,
+                "span",
+                foo = "foo",
+                bar = "bar",
+                baz = 3,
+                quuux = tracing::field::debug(0.99)
+            )
+        });
+    });
+}
+
+fn bench_dispatch(c: &mut Criterion) {
+    let mut group = c.benchmark_group("global/dispatch");
+    let _ = tracing::subscriber::set_global_default(EnabledSubscriber);
+    let _ = log::set_logger(&NOP_LOGGER);
+    log::set_max_level(log::LevelFilter::Trace);
+    group.bench_function("get_ref", |b| {
+        b.iter(|| {
+            tracing::dispatcher::get_default(|current| {
+                black_box(&current);
+            })
+        })
+    });
+    group.bench_function("get_clone", |b| {
+        b.iter(|| {
+            let current = tracing::dispatcher::get_default(|current| current.clone());
+            black_box(current);
+        })
+    });
+    group.finish();
+}
+
+criterion_group!(benches, criterion_benchmark, bench_dispatch);
+criterion_main!(benches);

tracing/src/lib.rs

@@ -1089,6 +1089,68 @@ pub mod __macro_support {
                 .finish()
         }
     }
+
+    #[cfg(feature = "log")]
+    use tracing_core::field::{Field, ValueSet, Visit};
+
+    /// Utility to format [`ValueSet`] for logging, used by macro-generated code.
+    ///
+    /// /!\ WARNING: This is *not* a stable API! /!\
+    /// This type, and all code contained in the `__macro_support` module, is
+    /// a *private* API of `tracing`. It is exposed publicly because it is used
+    /// by the `tracing` macros, but it is not part of the stable versioned API.
+    /// Breaking changes to this module may occur in small-numbered versions
+    /// without warning.
+    #[cfg(feature = "log")]
+    #[allow(missing_debug_implementations)]
+    pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);
+
+    #[cfg(feature = "log")]
+    impl<'a> fmt::Display for LogValueSet<'a> {
+        fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+            let mut visit = LogVisitor {
+                f,
+                is_first: true,
+                result: Ok(()),
+            };
+            self.0.record(&mut visit);
+            visit.result
+        }
+    }
+
+    #[cfg(feature = "log")]
+    struct LogVisitor<'a, 'b> {
+        f: &'a mut fmt::Formatter<'b>,
+        is_first: bool,
+        result: fmt::Result,
+    }
+
+    #[cfg(feature = "log")]
+    impl Visit for LogVisitor<'_, '_> {
+        fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
+            let res = if self.is_first {
+                self.is_first = false;
+                if field.name() == "message" {
+                    write!(self.f, "{:?}", value)
+                } else {
+                    write!(self.f, "{}={:?}", field.name(), value)
+                }
+            } else {
+                write!(self.f, " {}={:?}", field.name(), value)
+            };
+            if let Err(err) = res {
+                self.result = self.result.and(Err(err));
+            }
+        }
+
+        fn record_str(&mut self, field: &Field, value: &str) {
+            if field.name() == "message" {
+                self.record_debug(field, &format_args!("{}", value))
+            } else {
+                self.record_debug(field, &value)
+            }
+        }
+    }
 }
 
 mod sealed {