Skip to content

Commit

Permalink
tracing: fix macros "use of moved value" with log (#1823)
Browse files Browse the repository at this point in the history
## 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.
  • Loading branch information
Skepfyr authored and hawkw committed Feb 4, 2022
1 parent e8636c5 commit f1cf1f1
Show file tree
Hide file tree
Showing 5 changed files with 287 additions and 164 deletions.
4 changes: 2 additions & 2 deletions tracing-core/src/field.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
136 changes: 136 additions & 0 deletions tracing/benches/global_subscriber.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,136 @@
use std::fmt::Write;

use criterion::{black_box, criterion_group, criterion_main, Criterion};
use tracing::Level;

use tracing::{span, Event, Id, Metadata};

/// 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);
62 changes: 62 additions & 0 deletions tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
Loading

0 comments on commit f1cf1f1

Please sign in to comment.