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