subscriber: rm crossbeam-utils, make parking_lot opt-in (#348)

## Motivation

The `tracing-subscriber` currently depends on both the `crossbeam-util`
crate (for its `ShardedLock` type) and the `parking_lot` crate for it's
`RwLock` implementation. The Rust standard library also provides a
`RwLock` implementation, so these external dependencies are not strictly
necessary. In the past, using these crates was anecdotally observed to
result in a performance improvement, but the tradeoff is adding
additonal crates (and their transitive dependencies) to the user's
dependency tree.

## Solution

This branch removes the `crossbeam-util` dependency, and makes the
`parking_lot` dependency opt-in. The explicit use of
`parking_lot::RwLock` with a wrapper type that abstracts over the
`parking_lot::RwLock` and `std::sync::RwLock` types to provide a
matching API. This allows the `parking_lot` feature flag to
transparently replace the use of `std::sync::RwLock` with `parking_lot`,
rather than making it required for other features.

Additionally, I've added some new benchmarks for filtering performance
to `tracing-subscriber`.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

tracing-subscriber/Cargo.toml

@@ -22,15 +22,14 @@ keywords = ["logging", "tracing", "metrics", "subscriber"]
 
 default = ["env-filter", "smallvec", "fmt", "ansi", "chrono", "tracing-log"]
 env-filter = ["matchers", "regex", "lazy_static"]
-fmt = ["owning_ref", "parking_lot"]
+fmt = ["owning_ref"]
 ansi = ["fmt", "ansi_term"]
 
 # Alias for `env-filter`; renamed in version 0.1.2, and will be removed in 0.2.
 filter = ["env-filter"]
 
 [dependencies]
 tracing-core = "0.1.2"
-crossbeam-utils = "0.6"
 
 # only required by the filter feature
 matchers = { optional = true, version = "0.0.1" }
@@ -42,14 +41,21 @@ lazy_static = { optional = true, version = "1" }
 tracing-log = { version = "0.1", optional = true, default-features = false }
 ansi_term = { version = "0.11", optional = true }
 owning_ref = { version = "0.4.0", optional = true }
-parking_lot = { version = ">= 0.7, < 0.10", features = ["owning_ref"], optional = true }
 chrono = { version = "0.4", optional = true }
 
+# opt-in deps
+parking_lot = { version = ">= 0.7, < 0.10", features = ["owning_ref"], optional = true }
+
 [dev-dependencies]
 tracing = "0.1"
 log = "0.4"
 tracing-log = "0.1"
+criterion = { version = "0.3", default_features = false }
 
 [badges]
 azure-devops = { project = "tracing/tracing", pipeline = "tokio-rs.tracing", build = "1" }
 maintenance = { status = "experimental" }
+
+[[bench]]
+name = "filter"
+harness = false

tracing-subscriber/benches/filter.rs

@@ -0,0 +1,279 @@
+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(0xDEADFACE)
+    }
+
+    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<Barrier>,
+    end: Arc<Barrier>,
+    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");
+
+    group.bench_function("baseline_single_threaded", |b| {
+        tracing::subscriber::with_default(EnabledSubscriber, || {
+            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("single_threaded", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .expect("should parse");
+        tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
+            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("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();
+                        tracing::info!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::debug!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::warn!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::warn!(target: "foo", "hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        })
+    });
+    group.bench_function("multithreaded", |b| {
+        let filter = "static_filter=info"
+            .parse::<EnvFilter>()
+            .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();
+                        tracing::info!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::debug!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::warn!(target: "static_filter", "hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::warn!(target: "foo", "hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        });
+    });
+    group.finish();
+}
+
+fn bench_dynamic(c: &mut Criterion) {
+    let mut group = c.benchmark_group("dynamic");
+
+    group.bench_function("baseline_single_threaded", |b| {
+        tracing::subscriber::with_default(EnabledSubscriber, || {
+            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("single_threaded", |b| {
+        let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
+        tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
+            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 = 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();
+                        tracing::info!("hi");
+                    })
+                    .thread(|start| {
+                        let span = tracing::info_span!("foo");
+                        start.wait();
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|start| {
+                        let span = tracing::info_span!("bar");
+                        start.wait();
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::trace!("hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        })
+    });
+    group.bench_function("multithreaded", |b| {
+        let filter = "[foo]=trace".parse::<EnvFilter>().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();
+                        tracing::info!("hi");
+                    })
+                    .thread(|start| {
+                        let span = tracing::info_span!("foo");
+                        start.wait();
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|start| {
+                        let span = tracing::info_span!("bar");
+                        start.wait();
+                        let _ = span.enter();
+                        tracing::debug!("hi");
+                    })
+                    .thread(|start| {
+                        start.wait();
+                        tracing::trace!("hi");
+                    })
+                    .run();
+                total += elapsed;
+            }
+            total
+        })
+    });
+
+    group.finish();
+}
+
+criterion_group!(benches, bench_static, bench_dynamic);
+criterion_main!(benches);

tracing-subscriber/src/filter/env/mod.rs

@@ -14,9 +14,9 @@ mod field;
 use crate::{
     filter::LevelFilter,
     layer::{Context, Layer},
+    sync::RwLock,
     thread,
 };
-use crossbeam_utils::sync::ShardedLock;
 use std::{collections::HashMap, env, error::Error, fmt, str::FromStr};
 use tracing_core::{
     callsite,
@@ -44,8 +44,8 @@ pub struct EnvFilter {
     statics: directive::Statics,
     dynamics: directive::Dynamics,
 
-    by_id: ShardedLock<HashMap<span::Id, directive::SpanMatcher>>,
-    by_cs: ShardedLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
+    by_id: RwLock<HashMap<span::Id, directive::SpanMatcher>>,
+    by_cs: RwLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
 }
 
 type FieldMap<T> = HashMap<Field, T>;
@@ -181,8 +181,8 @@ impl EnvFilter {
             scope: thread::Local::new(),
             statics,
             dynamics,
-            by_id: ShardedLock::new(HashMap::new()),
-            by_cs: ShardedLock::new(HashMap::new()),
+            by_id: RwLock::new(HashMap::new()),
+            by_cs: RwLock::new(HashMap::new()),
         }
     }