diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index cd5911eefe..fd4c926cad 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -73,6 +73,10 @@ rustdoc-args = ["--cfg", "docsrs"] name = "filter" harness = false +[[bench]] +name = "filter_log" +harness = false + [[bench]] name = "fmt" harness = false diff --git a/tracing-subscriber/benches/filter.rs b/tracing-subscriber/benches/filter.rs index 25e5b54e0c..91ab9c91d2 100644 --- a/tracing-subscriber/benches/filter.rs +++ b/tracing-subscriber/benches/filter.rs @@ -1,12 +1,11 @@ use criterion::{criterion_group, criterion_main, Criterion}; -use std::{ - sync::{Arc, Barrier}, - thread, - time::{Duration, Instant}, -}; +use std::time::Duration; use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata}; use tracing_subscriber::{prelude::*, EnvFilter}; +mod support; +use support::MultithreadedBench; + /// A subscriber that is enabled but otherwise does nothing. struct EnabledSubscriber; @@ -42,42 +41,6 @@ impl tracing::Subscriber for EnabledSubscriber { } } -#[derive(Clone)] -struct MultithreadedBench { - start: Arc, - end: Arc, - dispatch: Dispatch, -} - -impl MultithreadedBench { - fn new(dispatch: Dispatch) -> Self { - Self { - start: Arc::new(Barrier::new(5)), - end: Arc::new(Barrier::new(5)), - dispatch, - } - } - - fn thread(&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 - } - - fn run(&self) -> Duration { - self.start.wait(); - let t0 = Instant::now(); - self.end.wait(); - t0.elapsed() - } -} - fn bench_static(c: &mut Criterion) { let mut group = c.benchmark_group("static"); @@ -104,27 +67,81 @@ fn bench_static(c: &mut Criterion) { }) }); }); + group.bench_function("enabled_one", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + 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::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_level_one", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + 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::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::trace!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_one", |b| { + let filter = "foo=info".parse::().expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + 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::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::info!(target: "static_filter", "hi"); + }) + }); + }); group.bench_function("baseline_multithreaded", |b| { - let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber); + let dispatch = Dispatch::new(EnabledSubscriber); 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(|start| { - start.wait(); + .thread(|| { tracing::info!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::debug!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::warn!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::warn!(target: "foo", "hi"); }) .run(); @@ -137,26 +154,22 @@ fn bench_static(c: &mut Criterion) { let filter = "static_filter=info" .parse::() .expect("should parse"); - let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber.with(filter)); + let dispatch = Dispatch::new(EnabledSubscriber.with(filter)); 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(|start| { - start.wait(); + .thread(|| { tracing::info!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::debug!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::warn!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::warn!(target: "foo", "hi"); }) .run(); @@ -201,32 +214,28 @@ fn bench_dynamic(c: &mut Criterion) { }); }); group.bench_function("baseline_multithreaded", |b| { - let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber); + let dispatch = Dispatch::new(EnabledSubscriber); 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(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); tracing::info!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); tracing::debug!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("bar"); - start.wait(); let _ = span.enter(); tracing::debug!("hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::trace!("hi"); }) .run(); @@ -237,32 +246,28 @@ fn bench_dynamic(c: &mut Criterion) { }); group.bench_function("multithreaded", |b| { let filter = "[foo]=trace".parse::().expect("should parse"); - let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber.with(filter)); + let dispatch = Dispatch::new(EnabledSubscriber.with(filter)); 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(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); tracing::info!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); tracing::debug!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("bar"); - start.wait(); let _ = span.enter(); tracing::debug!("hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { tracing::trace!("hi"); }) .run(); @@ -275,5 +280,29 @@ fn bench_dynamic(c: &mut Criterion) { group.finish(); } -criterion_group!(benches, bench_static, bench_dynamic); +fn bench_mixed(c: &mut Criterion) { + let mut group = c.benchmark_group("mixed"); + group.bench_function("disabled", |b| { + let filter = "[foo]=trace,bar[quux]=debug,[{baz}]=debug,asdf=warn,wibble=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_by_level", |b| { + let filter = "[foo]=info,bar[quux]=debug,asdf=warn,static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::trace!(target: "static_filter", "hi"); + }) + }); + }); +} + +criterion_group!(benches, bench_static, bench_dynamic, bench_mixed); criterion_main!(benches); diff --git a/tracing-subscriber/benches/filter_log.rs b/tracing-subscriber/benches/filter_log.rs new file mode 100644 index 0000000000..4dcf3b4ec0 --- /dev/null +++ b/tracing-subscriber/benches/filter_log.rs @@ -0,0 +1,315 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use std::time::Duration; +use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata}; +use tracing_subscriber::{prelude::*, EnvFilter}; + +mod support; +use support::MultithreadedBench; + +/// 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; + } +} + +fn bench_static(c: &mut Criterion) { + let _ = tracing_log::LogTracer::init(); + + let mut group = c.benchmark_group("log/static"); + + group.bench_function("baseline_single_threaded", |b| { + tracing::subscriber::with_default(EnabledSubscriber, || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + log::debug!(target: "static_filter", "hi"); + log::warn!(target: "static_filter", "hi"); + log::trace!(target: "foo", "hi"); + }) + }); + }); + group.bench_function("single_threaded", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + log::debug!(target: "static_filter", "hi"); + log::warn!(target: "static_filter", "hi"); + log::trace!(target: "foo", "hi"); + }) + }); + }); + group.bench_function("enabled_one", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::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::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_level_one", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::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::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::trace!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_one", |b| { + let filter = "foo=info".parse::().expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_many", |b| { + let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("baseline_multithreaded", |b| { + let dispatch = Dispatch::new(EnabledSubscriber); + 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(|| { + log::info!(target: "static_filter", "hi"); + }) + .thread(|| { + log::debug!(target: "static_filter", "hi"); + }) + .thread(|| { + log::warn!(target: "static_filter", "hi"); + }) + .thread(|| { + log::warn!(target: "foo", "hi"); + }) + .run(); + total += elapsed; + } + total + }) + }); + group.bench_function("multithreaded", |b| { + let filter = "static_filter=info" + .parse::() + .expect("should parse"); + let dispatch = Dispatch::new(EnabledSubscriber.with(filter)); + 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(|| { + log::info!(target: "static_filter", "hi"); + }) + .thread(|| { + log::debug!(target: "static_filter", "hi"); + }) + .thread(|| { + log::warn!(target: "static_filter", "hi"); + }) + .thread(|| { + log::warn!(target: "foo", "hi"); + }) + .run(); + total += elapsed; + } + total + }); + }); + group.finish(); +} + +fn bench_dynamic(c: &mut Criterion) { + let _ = tracing_log::LogTracer::init(); + + let mut group = c.benchmark_group("log/dynamic"); + + group.bench_function("baseline_single_threaded", |b| { + tracing::subscriber::with_default(EnabledSubscriber, || { + b.iter(|| { + tracing::info_span!("foo").in_scope(|| { + log::info!("hi"); + log::debug!("hi"); + }); + tracing::info_span!("bar").in_scope(|| { + log::warn!("hi"); + }); + log::trace!("hi"); + }) + }); + }); + group.bench_function("single_threaded", |b| { + let filter = "[foo]=trace".parse::().expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + tracing::info_span!("foo").in_scope(|| { + log::info!("hi"); + log::debug!("hi"); + }); + tracing::info_span!("bar").in_scope(|| { + log::warn!("hi"); + }); + log::trace!("hi"); + }) + }); + }); + group.bench_function("baseline_multithreaded", |b| { + let dispatch = Dispatch::new(EnabledSubscriber); + 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(); + log::info!("hi"); + }) + .thread(|| { + let span = tracing::info_span!("foo"); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|| { + let span = tracing::info_span!("bar"); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|| { + log::trace!("hi"); + }) + .run(); + total += elapsed; + } + total + }) + }); + group.bench_function("multithreaded", |b| { + let filter = "[foo]=trace".parse::().expect("should parse"); + let dispatch = Dispatch::new(EnabledSubscriber.with(filter)); + 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(); + log::info!("hi"); + }) + .thread(|| { + let span = tracing::info_span!("foo"); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|| { + let span = tracing::info_span!("bar"); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|| { + log::trace!("hi"); + }) + .run(); + total += elapsed; + } + total + }) + }); + + group.finish(); +} + +fn bench_mixed(c: &mut Criterion) { + let _ = tracing_log::LogTracer::init(); + + let mut group = c.benchmark_group("log/mixed"); + + group.bench_function("disabled", |b| { + let filter = "[foo]=trace,bar[quux]=debug,[{baz}]=debug,asdf=warn,wibble=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::info!(target: "static_filter", "hi"); + }) + }); + }); + group.bench_function("disabled_by_level", |b| { + let filter = "[foo]=info,bar[quux]=debug,asdf=warn,static_filter=info" + .parse::() + .expect("should parse"); + tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { + b.iter(|| { + log::trace!(target: "static_filter", "hi"); + }) + }); + }); +} + +criterion_group!(benches, bench_static, bench_dynamic, bench_mixed); +criterion_main!(benches);