From 59f30558a970729df7270f6ae5061cb013793241 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Feb 2020 11:14:33 -0800 Subject: [PATCH 1/5] add benchmarks for big and mixed filter groups Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/filter.rs | 86 +++++++++++++++++++++++++++- 1 file changed, 85 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/benches/filter.rs b/tracing-subscriber/benches/filter.rs index 25e5b54e0c..5542fac230 100644 --- a/tracing-subscriber/benches/filter.rs +++ b/tracing-subscriber/benches/filter.rs @@ -104,6 +104,66 @@ 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); b.iter_custom(|iters| { @@ -275,5 +335,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); From a5077f516bafc371991682527778d3f9ea6a27f6 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Feb 2020 14:24:47 -0800 Subject: [PATCH 2/5] add separate benchmarks for filtering `log` events Signed-off-by: Eliza Weisman --- tracing-subscriber/Cargo.toml | 4 + tracing-subscriber/benches/filter_log.rs | 370 +++++++++++++++++++++++ 2 files changed, 374 insertions(+) create mode 100644 tracing-subscriber/benches/filter_log.rs 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_log.rs b/tracing-subscriber/benches/filter_log.rs new file mode 100644 index 0000000000..978f896375 --- /dev/null +++ b/tracing-subscriber/benches/filter_log.rs @@ -0,0 +1,370 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use std::{ + sync::{Arc, Barrier}, + thread, + time::{Duration, Instant}, +}; +use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata}; +use tracing_subscriber::{prelude::*, EnvFilter}; + +/// 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; + } +} + +#[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 _ = 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 = tracing::dispatcher::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(); + log::info!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + log::debug!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + log::warn!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + 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 = tracing::dispatcher::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(); + log::info!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + log::debug!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + log::warn!(target: "static_filter", "hi"); + }) + .thread(|start| { + start.wait(); + 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 = tracing::dispatcher::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| { + let span = tracing::info_span!("foo"); + start.wait(); + let _ = span.enter(); + log::info!("hi"); + }) + .thread(|start| { + let span = tracing::info_span!("foo"); + start.wait(); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|start| { + let span = tracing::info_span!("bar"); + start.wait(); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|start| { + start.wait(); + log::trace!("hi"); + }) + .run(); + total += elapsed; + } + total + }) + }); + group.bench_function("multithreaded", |b| { + let filter = "[foo]=trace".parse::().expect("should parse"); + let dispatch = tracing::dispatcher::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| { + let span = tracing::info_span!("foo"); + start.wait(); + let _ = span.enter(); + log::info!("hi"); + }) + .thread(|start| { + let span = tracing::info_span!("foo"); + start.wait(); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|start| { + let span = tracing::info_span!("bar"); + start.wait(); + let _ = span.enter(); + log::debug!("hi"); + }) + .thread(|start| { + start.wait(); + 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); From 38b9a3144db160c704b630bfac54e157fa6c1aa4 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Feb 2020 14:47:45 -0800 Subject: [PATCH 3/5] reuse existing benchmark support code Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/filter.rs | 101 ++++++----------------- tracing-subscriber/benches/filter_log.rs | 93 +++++---------------- 2 files changed, 44 insertions(+), 150 deletions(-) diff --git a/tracing-subscriber/benches/filter.rs b/tracing-subscriber/benches/filter.rs index 5542fac230..44e0d3a8d0 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"); @@ -165,26 +128,22 @@ fn bench_static(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| { - 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(); @@ -197,26 +156,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(); @@ -261,32 +216,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(); @@ -297,32 +248,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(); diff --git a/tracing-subscriber/benches/filter_log.rs b/tracing-subscriber/benches/filter_log.rs index 978f896375..78e7cfabcb 100644 --- a/tracing-subscriber/benches/filter_log.rs +++ b/tracing-subscriber/benches/filter_log.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 _ = tracing_log::LogTracer::init(); @@ -173,20 +136,16 @@ fn bench_static(c: &mut Criterion) { for _ in 0..iters { let bench = MultithreadedBench::new(dispatch.clone()); let elapsed = bench - .thread(|start| { - start.wait(); + .thread(|| { log::info!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::debug!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::warn!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::warn!(target: "foo", "hi"); }) .run(); @@ -205,20 +164,16 @@ fn bench_static(c: &mut Criterion) { for _ in 0..iters { let bench = MultithreadedBench::new(dispatch.clone()); let elapsed = bench - .thread(|start| { - start.wait(); + .thread(|| { log::info!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::debug!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::warn!(target: "static_filter", "hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::warn!(target: "foo", "hi"); }) .run(); @@ -271,26 +226,22 @@ fn bench_dynamic(c: &mut Criterion) { 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(); log::info!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); log::debug!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("bar"); - start.wait(); let _ = span.enter(); log::debug!("hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::trace!("hi"); }) .run(); @@ -307,26 +258,22 @@ fn bench_dynamic(c: &mut Criterion) { 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(); log::info!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("foo"); - start.wait(); let _ = span.enter(); log::debug!("hi"); }) - .thread(|start| { + .thread(|| { let span = tracing::info_span!("bar"); - start.wait(); let _ = span.enter(); log::debug!("hi"); }) - .thread(|start| { - start.wait(); + .thread(|| { log::trace!("hi"); }) .run(); From a62d9dd4a8f1db8f2a1358589a4fdb880959f02f Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Feb 2020 15:13:22 -0800 Subject: [PATCH 4/5] rustfmt Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/filter.rs | 4 +--- tracing-subscriber/benches/filter_log.rs | 4 +--- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/tracing-subscriber/benches/filter.rs b/tracing-subscriber/benches/filter.rs index 44e0d3a8d0..91ab9c91d2 100644 --- a/tracing-subscriber/benches/filter.rs +++ b/tracing-subscriber/benches/filter.rs @@ -108,9 +108,7 @@ fn bench_static(c: &mut Criterion) { }); }); group.bench_function("disabled_one", |b| { - let filter = "foo=info" - .parse::() - .expect("should parse"); + let filter = "foo=info".parse::().expect("should parse"); tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { b.iter(|| { tracing::info!(target: "static_filter", "hi"); diff --git a/tracing-subscriber/benches/filter_log.rs b/tracing-subscriber/benches/filter_log.rs index 78e7cfabcb..cac44ff2ec 100644 --- a/tracing-subscriber/benches/filter_log.rs +++ b/tracing-subscriber/benches/filter_log.rs @@ -110,9 +110,7 @@ fn bench_static(c: &mut Criterion) { }); }); group.bench_function("disabled_one", |b| { - let filter = "foo=info" - .parse::() - .expect("should parse"); + let filter = "foo=info".parse::().expect("should parse"); tracing::subscriber::with_default(EnabledSubscriber.with(filter), || { b.iter(|| { log::info!(target: "static_filter", "hi"); From 5540d4b1631dbc6efc61b9a08eeea690193087be Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Feb 2020 15:24:24 -0800 Subject: [PATCH 5/5] fix unused import Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/filter_log.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/benches/filter_log.rs b/tracing-subscriber/benches/filter_log.rs index cac44ff2ec..4dcf3b4ec0 100644 --- a/tracing-subscriber/benches/filter_log.rs +++ b/tracing-subscriber/benches/filter_log.rs @@ -128,7 +128,7 @@ fn bench_static(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 { @@ -156,7 +156,7 @@ 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 { @@ -218,7 +218,7 @@ 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 { @@ -250,7 +250,7 @@ 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 {