subscriber: Benches for reloadable collectors (#1090)

## Motivation

The docs state that using the `reload` module inflicts a performance
penalty but there was no further data about how big the penalty is. This
PR adds `_reload` variants to the filter benchmarks. Results are a bit
inconclusive but the tl;dr is "yes, there is a performance impact and
yes, in some cases it's significant. Generally the more complex the
collector the less it matters.".

The benchmarks after this PR are a bit noisy; happy to rework this but
wasn't sure what the preferred way was. There's already a fair bit of
duplication in the benchmarks but this PR isn't helping with that.

tracing-subscriber/Cargo.toml

@@ -73,6 +73,9 @@ maintenance = { status = "experimental" }
 all-features = true
 rustdoc-args = ["--cfg", "docsrs"]
 
+[lib]
+bench = false
+
 [[bench]]
 name = "filter"
 harness = false
@@ -88,3 +91,7 @@ harness = false
 [[bench]]
 name = "enter"
 harness = false
+
+[[bench]]
+name = "reload"
+harness = false

tracing-subscriber/benches/filter.rs

@@ -1,7 +1,7 @@
 use criterion::{criterion_group, criterion_main, Criterion};
 use std::time::Duration;
 use tracing::{dispatch::Dispatch, span, Event, Id, Metadata};
-use tracing_subscriber::{prelude::*, EnvFilter};
+use tracing_subscriber::{prelude::*, reload, EnvFilter};
 
 mod support;
 use support::MultithreadedBench;
@@ -54,6 +54,7 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+
     group.bench_function("single_threaded", |b| {
         let filter = "static_filter=info"
             .parse::<EnvFilter>()
@@ -67,6 +68,25 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+
+    group.bench_function("single_threaded_reload", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "static_filter", "hi");
+                tracing::debug!(target: "static_filter", "hi");
+                tracing::warn!(target: "static_filter", "hi");
+                tracing::trace!(target: "foo", "hi");
+            })
+        });
+    });
+
     group.bench_function("enabled_one", |b| {
         let filter = "static_filter=info"
             .parse::<EnvFilter>()
@@ -77,6 +97,21 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+
+    group.bench_function("enabled_one_reload", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("enabled_many", |b| {
         let filter = "foo=debug,bar=trace,baz=error,quux=warn,static_filter=info"
             .parse::<EnvFilter>()
@@ -87,6 +122,19 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("enabled_many_reload", |b| {
+        let filter = "foo=debug,bar=trace,baz=error,quux=warn,static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("disabled_level_one", |b| {
         let filter = "static_filter=info"
             .parse::<EnvFilter>()
@@ -97,6 +145,19 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("disabled_level_one_reload", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::debug!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("disabled_level_many", |b| {
         let filter = "foo=debug,bar=info,baz=error,quux=warn,static_filter=info"
             .parse::<EnvFilter>()
@@ -107,6 +168,19 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("disabled_level_many_reload", |b| {
+        let filter = "foo=debug,bar=info,baz=error,quux=warn,static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::trace!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("disabled_one", |b| {
         let filter = "foo=info".parse::<EnvFilter>().expect("should parse");
         tracing::collect::with_default(EnabledSubscriber.with(filter), || {
@@ -115,6 +189,17 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("disabled_one_reload", |b| {
+        let filter = "foo=info".parse::<EnvFilter>().expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("disabled_many", |b| {
         let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info"
             .parse::<EnvFilter>()
@@ -125,6 +210,19 @@ fn bench_static(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("disabled_many_reload", |b| {
+        let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "static_filter", "hi");
+            })
+        });
+    });
     group.bench_function("baseline_multithreaded", |b| {
         let dispatch = Dispatch::new(EnabledSubscriber);
         b.iter_custom(|iters| {
@@ -178,6 +276,39 @@ fn bench_static(c: &mut Criterion) {
             total
         });
     });
+    group.bench_function("multithreaded_reload", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+
+        let dispatch = Dispatch::new(collector);
+        b.iter_custom(|iters| {
+            let mut total = Duration::from_secs(0);
+            for _ in 0..iters {
+                let bench = MultithreadedBench::new(dispatch.clone());
+                let elapsed = bench
+                    .thread(|| {
+                        tracing::info!(target: "static_filter", "hi");
+                    })
+                    .thread(|| {
+                        tracing::debug!(target: "static_filter", "hi");
+                    })
+                    .thread(|| {
+                        tracing::warn!(target: "static_filter", "hi");
+                    })
+                    .thread(|| {
+                        tracing::warn!(target: "foo", "hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        });
+    });
     group.finish();
 }
 
@@ -213,6 +344,25 @@ fn bench_dynamic(c: &mut Criterion) {
             })
         });
     });
+    group.bench_function("single_threaded_reload", |b| {
+        let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info_span!("foo").in_scope(|| {
+                    tracing::info!("hi");
+                    tracing::debug!("hi");
+                });
+                tracing::info_span!("bar").in_scope(|| {
+                    tracing::warn!("hi");
+                });
+                tracing::trace!("hi");
+            })
+        });
+    });
     group.bench_function("baseline_multithreaded", |b| {
         let dispatch = Dispatch::new(EnabledSubscriber);
         b.iter_custom(|iters| {
@@ -277,6 +427,42 @@ fn bench_dynamic(c: &mut Criterion) {
         })
     });
 
+    group.bench_function("multithreaded_reload", |b| {
+        let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
+        let (reloadeable_filter, h) = reload::Subscriber::new(filter);
+        let collector = EnabledSubscriber.with(reloadeable_filter);
+        criterion::black_box(h);
+        let dispatch = Dispatch::new(collector);
+        b.iter_custom(|iters| {
+            let mut total = Duration::from_secs(0);
+            for _ in 0..iters {
+                let bench = MultithreadedBench::new(dispatch.clone());
+                let elapsed = bench
+                    .thread(|| {
+                        let span = tracing::info_span!("foo");
+                        let _ = span.enter();
+                        tracing::info!("hi");
+                    })
+                    .thread(|| {
+                        let span = tracing::info_span!("foo");
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|| {
+                        let span = tracing::info_span!("bar");
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|| {
+                        tracing::trace!("hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        })
+    });
+
     group.finish();
 }
 

tracing-subscriber/benches/fmt.rs

@@ -1,31 +1,8 @@
 use criterion::{criterion_group, criterion_main, BenchmarkId, Criterion, Throughput};
-use std::{io, time::Duration};
+use std::time::Duration;
 
 mod support;
-use support::MultithreadedBench;
-
-/// A fake writer that doesn't actually do anything.
-///
-/// We want to measure the collectors's overhead, *not* the performance of
-/// stdout/file writers. Using a no-op Write implementation lets us only measure
-/// the collectors'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
-    }
-}
+use support::{MultithreadedBench, NoWriter};
 
 fn bench_new_span(c: &mut Criterion) {
     bench_thrpt(c, "new_span", |group, i| {

tracing-subscriber/benches/reload.rs

@@ -0,0 +1,70 @@
+use criterion::{criterion_group, criterion_main, Criterion};
+use tracing_subscriber::{
+    filter::LevelFilter,
+    fmt::{
+        format::{DefaultFields, Format, Full},
+        time::ChronoLocal,
+        Collector, CollectorBuilder,
+    },
+    EnvFilter,
+};
+
+mod support;
+use support::NoWriter;
+
+/// Prepare a real-world-inspired collector and use it to  measure the performance impact of
+/// reloadable collectors.
+
+fn mk_builder(
+) -> CollectorBuilder<DefaultFields, Format<Full, ChronoLocal>, EnvFilter, fn() -> NoWriter> {
+    let filter = EnvFilter::default()
+        .add_directive("this=off".parse().unwrap())
+        .add_directive("also=off".parse().unwrap())
+        .add_directive("this_too=off".parse().unwrap())
+        .add_directive("stuff=warn".parse().unwrap())
+        .add_directive("moar=warn".parse().unwrap())
+        .add_directive(LevelFilter::INFO.into());
+
+    Collector::builder()
+        .with_env_filter(filter)
+        .with_writer(NoWriter::new as _)
+        .with_timer(ChronoLocal::with_format(
+            "%Y-%m-%d %H:%M:%S%.3f".to_string(),
+        ))
+        .with_ansi(true)
+        .with_target(true)
+        .with_level(true)
+        .with_thread_names(true)
+}
+
+fn bench_reload(c: &mut Criterion) {
+    let mut group = c.benchmark_group("reload");
+    group.bench_function("complex-collector", |b| {
+        let builder = mk_builder();
+        let collector = builder.finish();
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "this", "hi");
+                tracing::debug!(target: "enabled", "hi");
+                tracing::warn!(target: "hepp", "hi");
+                tracing::trace!(target: "stuff", "hi");
+            })
+        });
+    });
+    group.bench_function("complex-collector-reloadable", |b| {
+        let builder = mk_builder().with_filter_reloading();
+        let _handle = builder.reload_handle();
+        let collector = builder.finish();
+        tracing::collect::with_default(collector, || {
+            b.iter(|| {
+                tracing::info!(target: "this", "hi");
+                tracing::debug!(target: "enabled", "hi");
+                tracing::warn!(target: "hepp", "hi");
+                tracing::trace!(target: "stuff", "hi");
+            })
+        });
+    });
+    group.finish();
+}
+criterion_group!(benches, bench_reload);
+criterion_main!(benches);