From ebea0e4cc0838ea1438cbcbb693eb135606169be Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 24 Jun 2022 13:30:36 -0700 Subject: [PATCH] tracing: reorganize benchmarks for comparability (#2178) Currently, `tracing`'s benchmark suite benchmarks the same behaviors (e.g. creating a span, recording an event, etc) across a handful of cases: with no default dispatcher, with a global default, and with a scoped (thread-local) default. We use criterion's `benchmark_group` to represent each kind of dispatcher, and `bench_function` for each behavior being measured. This is actually kind of backwards relative to how Criterion is _supposed_ to be used. `bench_function` is intended for comparing different implementations of the *same* thing, with the `benchmark_group` representing what's being compared. If we inverted the structure of these benchmarks, Criterion would give us nicer plots that would allow comparing the performance of each dispatch type on the same task. This PR reorganizes the benchmarks so that each behavior being tested (such as entering a span or recording an event) is a `benchmark_group`, and each dispatch type (none, global, or scoped) is a `bench_function` within that group. Now, Criterion will generate plots for each group comparing the performance of each dispatch type in that benchmark. For example, we now get nice comparisons like this: ![image](https://user-images.githubusercontent.com/2796466/175659314-835664ac-a8cf-4b07-91ee-f8cfee77bfbb.png) Unfortunately, this required splitting each benchmark type out into its own file. This is because, once we set the global default dispatcher within one benchmark group, it would remain set for the entire lifetime of the process --- there would be no way to test something else with no global default. But, I think this is fine, even though it means we now have a bunch of tiny files: it also allows us to run an individual benchmark against every combination of dispatch types, without having to run unrelated benches. This is potentially useful if (for example) someone is changing only the code for recording events, and not spans. --- tracing/Cargo.toml | 30 +++- tracing/benches/baseline.rs | 24 ++++ tracing/benches/dispatch_get_clone.rs | 15 ++ tracing/benches/dispatch_get_ref.rs | 16 +++ tracing/benches/empty_span.rs | 43 ++++++ tracing/benches/enter_span.rs | 16 +++ tracing/benches/event.rs | 12 ++ tracing/benches/global_subscriber.rs | 136 ------------------ tracing/benches/no_subscriber.rs | 101 -------------- tracing/benches/shared.rs | 160 ++++++++++++++++++++++ tracing/benches/span_fields.rs | 23 ++++ tracing/benches/span_no_fields.rs | 13 ++ tracing/benches/span_repeated.rs | 20 +++ tracing/benches/subscriber.rs | 189 -------------------------- 14 files changed, 369 insertions(+), 429 deletions(-) create mode 100644 tracing/benches/baseline.rs create mode 100644 tracing/benches/dispatch_get_clone.rs create mode 100644 tracing/benches/dispatch_get_ref.rs create mode 100644 tracing/benches/empty_span.rs create mode 100644 tracing/benches/enter_span.rs create mode 100644 tracing/benches/event.rs delete mode 100644 tracing/benches/global_subscriber.rs delete mode 100644 tracing/benches/no_subscriber.rs create mode 100644 tracing/benches/shared.rs create mode 100644 tracing/benches/span_fields.rs create mode 100644 tracing/benches/span_no_fields.rs create mode 100644 tracing/benches/span_repeated.rs delete mode 100644 tracing/benches/subscriber.rs diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index 6e122de01e..be4139245d 100644 --- a/tracing/Cargo.toml +++ b/tracing/Cargo.toml @@ -68,15 +68,39 @@ attributes = ["tracing-attributes"] valuable = ["tracing-core/valuable"] [[bench]] -name = "subscriber" +name = "baseline" harness = false [[bench]] -name = "no_subscriber" +name = "dispatch_get_clone" harness = false [[bench]] -name = "global_subscriber" +name = "dispatch_get_ref" +harness = false + +[[bench]] +name = "empty_span" +harness = false + +[[bench]] +name = "enter_span" +harness = false + +[[bench]] +name = "event" +harness = false + +[[bench]] +name = "span_fields" +harness = false + +[[bench]] +name = "span_no_fields" +harness = false + +[[bench]] +name = "span_repeated" harness = false [badges] diff --git a/tracing/benches/baseline.rs b/tracing/benches/baseline.rs new file mode 100644 index 0000000000..93c14f422c --- /dev/null +++ b/tracing/benches/baseline.rs @@ -0,0 +1,24 @@ +use criterion::{black_box, criterion_group, criterion_main, Criterion}; + +fn bench(c: &mut Criterion) { + use std::sync::atomic::{AtomicUsize, Ordering}; + + let mut group = c.benchmark_group("comparison"); + group.bench_function("relaxed_load", |b| { + let foo = AtomicUsize::new(1); + b.iter(|| black_box(foo.load(Ordering::Relaxed))); + }); + group.bench_function("acquire_load", |b| { + let foo = AtomicUsize::new(1); + b.iter(|| black_box(foo.load(Ordering::Acquire))) + }); + group.bench_function("log", |b| { + b.iter(|| { + log::log!(log::Level::Info, "log"); + }) + }); + group.finish(); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/dispatch_get_clone.rs b/tracing/benches/dispatch_get_clone.rs new file mode 100644 index 0000000000..15577c6969 --- /dev/null +++ b/tracing/benches/dispatch_get_clone.rs @@ -0,0 +1,15 @@ +use criterion::{black_box, criterion_group, criterion_main, Criterion}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_dispatches(&mut c.benchmark_group("Dispatch::get_clone"), |b| { + b.iter(|| { + let current = tracing::dispatcher::get_default(|current| current.clone()); + black_box(current); + }) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/dispatch_get_ref.rs b/tracing/benches/dispatch_get_ref.rs new file mode 100644 index 0000000000..a59c343795 --- /dev/null +++ b/tracing/benches/dispatch_get_ref.rs @@ -0,0 +1,16 @@ +use criterion::{black_box, criterion_group, criterion_main, Criterion}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_dispatches(&mut c.benchmark_group("Dispatch::get_ref"), |b| { + b.iter(|| { + tracing::dispatcher::get_default(|current| { + black_box(¤t); + }) + }) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/empty_span.rs b/tracing/benches/empty_span.rs new file mode 100644 index 0000000000..fb38b08e15 --- /dev/null +++ b/tracing/benches/empty_span.rs @@ -0,0 +1,43 @@ +use criterion::{black_box, criterion_group, criterion_main, Criterion}; + +mod shared; + +fn bench(c: &mut Criterion) { + let mut group = c.benchmark_group("empty_span"); + shared::for_all_dispatches(&mut group, |b| { + b.iter(|| { + let span = tracing::span::Span::none(); + black_box(&span); + }) + }); + group.bench_function("baseline_struct", |b| { + b.iter(|| { + let span = FakeEmptySpan::new(); + black_box(&span); + }) + }); +} + +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); + } +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/enter_span.rs b/tracing/benches/enter_span.rs new file mode 100644 index 0000000000..757350a539 --- /dev/null +++ b/tracing/benches/enter_span.rs @@ -0,0 +1,16 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use tracing::{span, Level}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_dispatches(&mut c.benchmark_group("enter_span"), |b| { + let span = span!(Level::TRACE, "span"); + b.iter(|| { + let _span = span.enter(); + }) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/event.rs b/tracing/benches/event.rs new file mode 100644 index 0000000000..1649325482 --- /dev/null +++ b/tracing/benches/event.rs @@ -0,0 +1,12 @@ +use criterion::{criterion_group, criterion_main, Criterion}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_recording(&mut c.benchmark_group("event"), |b| { + b.iter(|| tracing::info!("hello world!")) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/global_subscriber.rs b/tracing/benches/global_subscriber.rs deleted file mode 100644 index 83519610a8..0000000000 --- a/tracing/benches/global_subscriber.rs +++ /dev/null @@ -1,136 +0,0 @@ -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(¤t); - }) - }) - }); - 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); diff --git a/tracing/benches/no_subscriber.rs b/tracing/benches/no_subscriber.rs deleted file mode 100644 index e0f82b56a0..0000000000 --- a/tracing/benches/no_subscriber.rs +++ /dev/null @@ -1,101 +0,0 @@ -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(|| { - 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| { - b.iter(|| { - tracing::event!(Level::TRACE, "hello"); - }) - }); - group.bench_function("relaxed_load", |b| { - let foo = AtomicUsize::new(1); - b.iter(|| black_box(foo.load(Ordering::Relaxed))); - }); - group.bench_function("acquire_load", |b| { - let foo = AtomicUsize::new(1); - b.iter(|| black_box(foo.load(Ordering::Acquire))) - }); - group.bench_function("log", |b| { - b.iter(|| { - log::log!(log::Level::Info, "log"); - }) - }); - group.finish(); -} - -fn bench_fields(c: &mut Criterion) { - let mut group = c.benchmark_group("no_subscriber_field"); - group.bench_function("span", |b| { - b.iter(|| { - black_box(tracing::span!( - Level::TRACE, - "span", - foo = tracing::field::display(format!("bar {:?}", 2)) - )); - }) - }); - group.bench_function("event", |b| { - b.iter(|| { - tracing::event!( - Level::TRACE, - foo = tracing::field::display(format!("bar {:?}", 2)) - ); - }) - }); - group.bench_function("log", |b| { - b.iter(|| log::log!(log::Level::Trace, "{}", format!("bar {:?}", 2))) - }); - group.finish(); -} - -criterion_group!(benches, bench_no_subscriber, bench_fields); -criterion_main!(benches); diff --git a/tracing/benches/shared.rs b/tracing/benches/shared.rs new file mode 100644 index 0000000000..56508c4ab7 --- /dev/null +++ b/tracing/benches/shared.rs @@ -0,0 +1,160 @@ +#![allow(dead_code)] +use criterion::{black_box, measurement::WallTime, Bencher}; +use tracing::{field, span, Event, Id, Metadata}; + +use std::{ + fmt::{self, Write}, + sync::{Mutex, MutexGuard}, +}; + +pub fn for_all_recording( + group: &mut criterion::BenchmarkGroup<'_, WallTime>, + mut iter: impl FnMut(&mut Bencher<'_, WallTime>), +) { + // first, run benchmarks with no subscriber + group.bench_function("none", &mut iter); + + // then, run benchmarks with a scoped default subscriber + tracing::subscriber::with_default(EnabledSubscriber, || { + group.bench_function("scoped", &mut iter) + }); + + let subscriber = VisitingSubscriber(Mutex::new(String::from(""))); + tracing::subscriber::with_default(subscriber, || { + group.bench_function("scoped_recording", &mut iter); + }); + + // finally, set a global default subscriber, and run the benchmarks again. + tracing::subscriber::set_global_default(EnabledSubscriber) + .expect("global default should not have already been set!"); + let _ = log::set_logger(&NOP_LOGGER); + log::set_max_level(log::LevelFilter::Trace); + group.bench_function("global", &mut iter); +} + +pub fn for_all_dispatches( + group: &mut criterion::BenchmarkGroup<'_, WallTime>, + mut iter: impl FnMut(&mut Bencher<'_, WallTime>), +) { + // first, run benchmarks with no subscriber + group.bench_function("none", &mut iter); + + // then, run benchmarks with a scoped default subscriber + tracing::subscriber::with_default(EnabledSubscriber, || { + group.bench_function("scoped", &mut iter) + }); + + // finally, set a global default subscriber, and run the benchmarks again. + tracing::subscriber::set_global_default(EnabledSubscriber) + .expect("global default should not have already been set!"); + let _ = log::set_logger(&NOP_LOGGER); + log::set_max_level(log::LevelFilter::Trace); + group.bench_function("global", &mut iter); +} + +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(()) + } +} + +/// Simulates a subscriber that records span data. +struct VisitingSubscriber(Mutex); + +struct Visitor<'a>(MutexGuard<'a, String>); + +impl<'a> field::Visit for Visitor<'a> { + fn record_debug(&mut self, _field: &field::Field, value: &dyn fmt::Debug) { + let _ = write!(&mut *self.0, "{:?}", value); + } +} + +impl tracing::Subscriber for VisitingSubscriber { + fn new_span(&self, span: &span::Attributes<'_>) -> Id { + let mut visitor = Visitor(self.0.lock().unwrap()); + span.record(&mut visitor); + Id::from_u64(0xDEAD_FACE) + } + + fn record(&self, _span: &Id, values: &span::Record<'_>) { + let mut visitor = Visitor(self.0.lock().unwrap()); + values.record(&mut visitor); + } + + fn event(&self, event: &Event<'_>) { + let mut visitor = Visitor(self.0.lock().unwrap()); + event.record(&mut visitor); + } + + 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; + } +} + +/// 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; + } +} diff --git a/tracing/benches/span_fields.rs b/tracing/benches/span_fields.rs new file mode 100644 index 0000000000..5ad8289826 --- /dev/null +++ b/tracing/benches/span_fields.rs @@ -0,0 +1,23 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use tracing::{span, Level}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_recording(&mut c.benchmark_group("span_fields"), |b| { + b.iter(|| { + let span = span!( + Level::TRACE, + "span", + foo = "foo", + bar = "bar", + baz = 3, + quuux = tracing::field::debug(0.99) + ); + criterion::black_box(span) + }) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/span_no_fields.rs b/tracing/benches/span_no_fields.rs new file mode 100644 index 0000000000..8a1ff6e041 --- /dev/null +++ b/tracing/benches/span_no_fields.rs @@ -0,0 +1,13 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use tracing::{span, Level}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_recording(&mut c.benchmark_group("span_no_fields"), |b| { + b.iter(|| span!(Level::TRACE, "span")) + }); +} + +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/span_repeated.rs b/tracing/benches/span_repeated.rs new file mode 100644 index 0000000000..4c6ac409d8 --- /dev/null +++ b/tracing/benches/span_repeated.rs @@ -0,0 +1,20 @@ +use criterion::{black_box, criterion_group, criterion_main, Criterion}; +use tracing::{span, Level}; + +mod shared; + +fn bench(c: &mut Criterion) { + shared::for_all_recording(&mut c.benchmark_group("span_repeated"), |b| { + let n = black_box(N_SPANS); + b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64))) + }); +} + +#[inline] +fn mk_span(i: u64) -> tracing::Span { + span!(Level::TRACE, "span", i = i) +} + +const N_SPANS: usize = 100; +criterion_group!(benches, bench); +criterion_main!(benches); diff --git a/tracing/benches/subscriber.rs b/tracing/benches/subscriber.rs deleted file mode 100644 index c6418010f4..0000000000 --- a/tracing/benches/subscriber.rs +++ /dev/null @@ -1,189 +0,0 @@ -use criterion::{black_box, criterion_group, criterion_main, Criterion}; -use tracing::Level; - -use std::{ - fmt, - sync::{Mutex, MutexGuard}, -}; -use tracing::{field, 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; - } -} - -/// Simulates a subscriber that records span data. -struct VisitingSubscriber(Mutex); - -struct Visitor<'a>(MutexGuard<'a, String>); - -impl<'a> field::Visit for Visitor<'a> { - fn record_debug(&mut self, _field: &field::Field, value: &dyn fmt::Debug) { - use std::fmt::Write; - let _ = write!(&mut *self.0, "{:?}", value); - } -} - -impl tracing::Subscriber for VisitingSubscriber { - fn new_span(&self, span: &span::Attributes<'_>) -> Id { - let mut visitor = Visitor(self.0.lock().unwrap()); - span.record(&mut visitor); - Id::from_u64(0xDEAD_FACE) - } - - fn record(&self, _span: &Id, values: &span::Record<'_>) { - let mut visitor = Visitor(self.0.lock().unwrap()); - values.record(&mut visitor); - } - - fn event(&self, event: &Event<'_>) { - let mut visitor = Visitor(self.0.lock().unwrap()); - event.record(&mut visitor); - } - - 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 N_SPANS: usize = 100; - -fn criterion_benchmark(c: &mut Criterion) { - c.bench_function("span_no_fields", |b| { - tracing::subscriber::with_default(EnabledSubscriber, || { - b.iter(|| span!(Level::TRACE, "span")) - }); - }); - - c.bench_function("enter_span", |b| { - tracing::subscriber::with_default(EnabledSubscriber, || { - 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); - tracing::subscriber::with_default(EnabledSubscriber, || { - b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64))) - }); - }); - - c.bench_function("span_with_fields", |b| { - tracing::subscriber::with_default(EnabledSubscriber, || { - b.iter(|| { - span!( - Level::TRACE, - "span", - foo = "foo", - bar = "bar", - baz = 3, - quuux = tracing::field::debug(0.99) - ) - }) - }); - }); - - c.bench_function("span_with_fields_record", |b| { - let subscriber = VisitingSubscriber(Mutex::new(String::from(""))); - tracing::subscriber::with_default(subscriber, || { - 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("dispatch"); - group.bench_function("no_dispatch_get_ref", |b| { - b.iter(|| { - tracing::dispatcher::get_default(|current| { - black_box(¤t); - }) - }) - }); - group.bench_function("no_dispatch_get_clone", |b| { - b.iter(|| { - let current = tracing::dispatcher::get_default(|current| current.clone()); - black_box(current); - }) - }); - group.bench_function("get_ref", |b| { - tracing::subscriber::with_default(EnabledSubscriber, || { - b.iter(|| { - tracing::dispatcher::get_default(|current| { - black_box(¤t); - }) - }) - }) - }); - group.bench_function("get_clone", |b| { - tracing::subscriber::with_default(EnabledSubscriber, || { - 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);