subscriber: add benchmarks for fmt subscriber

These benchmarks were originally written for assessing before/after
performance on a branch that was not merged. However, they are probably
generally useful for other fmt subscriber changes (e.g. #420).

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

tracing-subscriber/Cargo.toml

@@ -68,3 +68,7 @@ all-features = true
 [[bench]]
 name = "filter"
 harness = false
+
+[[bench]]
+name = "fmt"
+harness = false

tracing-subscriber/benches/fmt.rs

@@ -0,0 +1,263 @@
+use criterion::{criterion_group, criterion_main, BenchmarkId, Criterion, Throughput};
+use std::{
+    io,
+    sync::{Arc, Barrier},
+    thread,
+    time::{Duration, Instant},
+};
+use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata};
+use tracing_subscriber::{prelude::*, EnvFilter};
+
+mod support;
+use support::MultithreadedBench;
+
+/// A fake writer that doesn't actually do anything.
+///
+/// We want to measure the subscriber's overhead, *not* the performance of
+/// stdout/file writers. Using a no-op Write implementation lets us only measure
+/// the subscriber's overhead.
+struct NoWriter;
+
+impl io::Write for NoWriter {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        Ok(buf.len())
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        Ok(())
+    }
+}
+
+impl NoWriter {
+    fn new() -> Self {
+        Self
+    }
+}
+
+fn bench_new_span(c: &mut Criterion) {
+    bench_thrpt(c, "new_span", |group, i| {
+        group.bench_with_input(BenchmarkId::new("single_thread", i), i, |b, &i| {
+            tracing::dispatcher::with_default(&mk_dispatch(), || {
+                b.iter(|| {
+                    for n in 0..i {
+                        let _span = tracing::info_span!("span", n);
+                    }
+                })
+            });
+        });
+        group.bench_with_input(BenchmarkId::new("multithreaded", i), i, |b, &i| {
+            b.iter_custom(|iters| {
+                let mut total = Duration::from_secs(0);
+                for _ in 0..iters {
+                    let bench = MultithreadedBench::new(mk_dispatch());
+                    let elapsed = bench
+                        .thread(move || {
+                            for n in 0..i {
+                                let _span = tracing::info_span!("span", n);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                let _span = tracing::info_span!("span", n);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                let _span = tracing::info_span!("span", i);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                let _span = tracing::info_span!("span", n);
+                            }
+                        })
+                        .run();
+                    total += elapsed;
+                }
+                total
+            })
+        });
+    });
+}
+
+type Group<'a> = criterion::BenchmarkGroup<'a, criterion::measurement::WallTime>;
+fn bench_thrpt(c: &mut Criterion, name: &'static str, mut f: impl FnMut(&mut Group<'_>, &usize)) {
+    const N_SPANS: &'static [usize] = &[1, 10, 50];
+
+    let mut group = c.benchmark_group(name);
+    for spans in N_SPANS {
+        group.throughput(Throughput::Elements(*spans as u64));
+        f(&mut group, spans);
+    }
+    group.finish();
+}
+
+fn mk_dispatch() -> tracing::Dispatch {
+    let subscriber = tracing_subscriber::FmtSubscriber::builder()
+        .with_writer(NoWriter::new)
+        .finish();
+    tracing::Dispatch::new(subscriber)
+}
+
+fn bench_event(c: &mut Criterion) {
+    bench_thrpt(c, "event", |group, i| {
+        group.bench_with_input(BenchmarkId::new("root/single_threaded", i), i, |b, &i| {
+            tracing::dispatcher::with_default(&mk_dispatch(), || {
+                b.iter(|| {
+                    for n in 0..i {
+                        tracing::info!(n);
+                    }
+                })
+            });
+        });
+        group.bench_with_input(BenchmarkId::new("root/multithreaded", i), i, |b, &i| {
+            b.iter_custom(|iters| {
+                let mut total = Duration::from_secs(0);
+                for _ in 0..iters {
+                    let bench = MultithreadedBench::new(mk_dispatch());
+                    let elapsed = bench
+                        .thread(move || {
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        })
+                        .thread(move || {
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        })
+                        .run();
+                    total += elapsed;
+                }
+                total
+            })
+        });
+        group.bench_with_input(
+            BenchmarkId::new("unique_parent/single_threaded", i),
+            i,
+            |b, &i| {
+                tracing::dispatcher::with_default(&mk_dispatch(), || {
+                    let span = tracing::info_span!("unique_parent", foo = false);
+                    let _guard = span.enter();
+                    b.iter(|| {
+                        for n in 0..i {
+                            tracing::info!(n);
+                        }
+                    })
+                });
+            },
+        );
+        group.bench_with_input(
+            BenchmarkId::new("unique_parent/multithreaded", i),
+            i,
+            |b, &i| {
+                b.iter_custom(|iters| {
+                    let mut total = Duration::from_secs(0);
+                    for _ in 0..iters {
+                        let bench = MultithreadedBench::new(mk_dispatch());
+                        let elapsed = bench
+                            .thread_with_setup(move |start| {
+                                let span = tracing::info_span!("unique_parent", foo = false);
+                                let _guard = span.enter();
+                                start.wait();
+                                for n in 0..i {
+                                    tracing::info!(n);
+                                }
+                            })
+                            .thread_with_setup(move |start| {
+                                let span = tracing::info_span!("unique_parent", foo = false);
+                                let _guard = span.enter();
+                                start.wait();
+                                for n in 0..i {
+                                    tracing::info!(n);
+                                }
+                            })
+                            .thread_with_setup(move |start| {
+                                let span = tracing::info_span!("unique_parent", foo = false);
+                                let _guard = span.enter();
+                                start.wait();
+                                for n in 0..i {
+                                    tracing::info!(n);
+                                }
+                            })
+                            .thread_with_setup(move |start| {
+                                let span = tracing::info_span!("unique_parent", foo = false);
+                                let _guard = span.enter();
+                                start.wait();
+                                for n in 0..i {
+                                    tracing::info!(n);
+                                }
+                            })
+                            .run();
+                        total += elapsed;
+                    }
+                    total
+                })
+            },
+        );
+        group.bench_with_input(
+            BenchmarkId::new("shared_parent/multithreaded", i),
+            i,
+            |b, &i| {
+                b.iter_custom(|iters| {
+                    let mut total = Duration::from_secs(0);
+                    for _ in 0..iters {
+                        let dispatch = mk_dispatch();
+                        let parent = tracing::dispatcher::with_default(&dispatch, || {
+                            tracing::info_span!("shared_parent", foo = "hello world")
+                        });
+                        let bench = MultithreadedBench::new(dispatch);
+                        let parent2 = parent.clone();
+                        bench.thread_with_setup(move |start| {
+                            let _guard = parent2.enter();
+                            start.wait();
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        });
+                        let parent2 = parent.clone();
+                        bench.thread_with_setup(move |start| {
+                            let _guard = parent2.enter();
+                            start.wait();
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        });
+                        let parent2 = parent.clone();
+                        bench.thread_with_setup(move |start| {
+                            let _guard = parent2.enter();
+                            start.wait();
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        });
+                        let parent2 = parent.clone();
+                        bench.thread_with_setup(move |start| {
+                            let _guard = parent2.enter();
+                            start.wait();
+                            for n in 0..i {
+                                tracing::info!(n);
+                            }
+                        });
+                        let elapsed = bench.run();
+                        total += elapsed;
+                    }
+                    total
+                })
+            },
+        );
+    });
+}
+
+criterion_group!(benches, bench_new_span, bench_event);
+criterion_main!(benches);

tracing-subscriber/benches/support/mod.rs

@@ -0,0 +1,49 @@
+use std::{
+    sync::{Arc, Barrier},
+    thread,
+    time::{Duration, Instant},
+};
+use tracing::dispatcher::Dispatch;
+
+#[derive(Clone)]
+pub(super) struct MultithreadedBench {
+    start: Arc<Barrier>,
+    end: Arc<Barrier>,
+    dispatch: Dispatch,
+}
+
+impl MultithreadedBench {
+    pub(super) fn new(dispatch: Dispatch) -> Self {
+        Self {
+            start: Arc::new(Barrier::new(5)),
+            end: Arc::new(Barrier::new(5)),
+            dispatch,
+        }
+    }
+
+    pub(super) fn thread(&self, f: impl FnOnce() + Send + 'static) -> &Self {
+        self.thread_with_setup(|start| {
+            start.wait();
+            f()
+        })
+    }
+
+    pub(super) fn thread_with_setup(&self, f: impl FnOnce(&Barrier) + Send + 'static) -> &Self {
+        let this = self.clone();
+        thread::spawn(move || {
+            let dispatch = this.dispatch.clone();
+            tracing::dispatcher::with_default(&dispatch, move || {
+                f(&*this.start);
+                this.end.wait();
+            })
+        });
+        self
+    }
+
+    pub(super) fn run(&self) -> Duration {
+        self.start.wait();
+        let t0 = Instant::now();
+        self.end.wait();
+        t0.elapsed()
+    }
+}