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.
This commit is contained in:
Eliza Weisman 2022-06-24 13:30:36 -07:00
parent 181bdbe1d8
commit ebea0e4cc0
No known key found for this signature in database
GPG Key ID: F9C1A595C3814436
14 changed files with 369 additions and 429 deletions

View File

@ -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]

View File

@ -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);

View File

@ -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);

View File

@ -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(&current);
})
})
});
}
criterion_group!(benches, bench);
criterion_main!(benches);

View File

@ -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);

View File

@ -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);

12
tracing/benches/event.rs Normal file
View File

@ -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);

View File

@ -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(&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);

View File

@ -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);

160
tracing/benches/shared.rs Normal file
View File

@ -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<String>);
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;
}
}

View File

@ -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);

View File

@ -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);

View File

@ -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);

View File

@ -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<String>);
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(&current);
})
})
});
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(&current);
})
})
})
});
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);