Add an interest cache for logs emitted through the log crate

tracing-core/src/callsite.rs

@@ -3,7 +3,8 @@
 use crate::stdlib::{
     fmt,
     hash::{Hash, Hasher},
-    sync::Mutex,
+    sync::{Mutex},
+    sync::atomic::{AtomicUsize, Ordering},
     vec::Vec,
 };
 use crate::{
@@ -19,6 +20,8 @@ lazy_static! {
     });
 }
 
+static EPOCH: AtomicUsize = AtomicUsize::new(0);
+
 struct Registry {
     callsites: Vec<&'static dyn Callsite>,
     dispatchers: Vec<dispatcher::Registrar>,
@@ -126,9 +129,15 @@ pub struct Identifier(
 /// [`Subscriber`]: ../subscriber/trait.Subscriber.html
 pub fn rebuild_interest_cache() {
     let mut registry = REGISTRY.lock().unwrap();
+    EPOCH.fetch_add(1, Ordering::SeqCst);
     registry.rebuild_interest();
 }
 
+#[doc(hidden)]
+pub fn _interest_cache_epoch() -> usize {
+    EPOCH.load(Ordering::SeqCst)
+}
+
 /// Register a new `Callsite` with the global registry.
 ///
 /// This should be called once per callsite after the callsite has been

tracing-log/Cargo.toml

@@ -21,19 +21,28 @@ default = ["log-tracer", "trace-logger", "std"]
 std = ["log/std"]
 log-tracer = []
 trace-logger = []
+interest-cache = ["lru", "ahash"]
 
 [dependencies]
 tracing-core = { path = "../tracing-core", version = "0.1.17"}
 log = { version = "0.4" }
 lazy_static = "1.3.0"
 env_logger = { version = "0.7", optional = true }
+lru = { version = "0.7.0", optional = true }
+ahash = { version = "0.7.4", optional = true }
 
 [dev-dependencies]
 tracing = { path = "../tracing", version = "0.1"}
+tracing-subscriber = { path = "../tracing-subscriber" }
+criterion = { version = "0.3", default_features = false }
 
 [badges]
 maintenance = { status = "actively-maintained" }
 
 [package.metadata.docs.rs]
 all-features = true
 rustdoc-args = ["--cfg", "docsrs"]
+
+[[bench]]
+name = "logging"
+harness = false

tracing-log/benches/logging.rs

@@ -0,0 +1,90 @@
+use criterion::{criterion_group, criterion_main, Criterion};
+use log::trace;
+use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering};
+use std::sync::Arc;
+use std::time::{Duration, Instant};
+use tracing_subscriber::{EnvFilter, FmtSubscriber};
+
+// This creates a bunch of threads and makes sure they start executing
+// a given callback almost exactly at the same time.
+fn run_on_many_threads<F, R>(thread_count: usize, callback: F) -> Vec<R>
+where
+    F: Fn() -> R + 'static + Send + Clone,
+    R: Send + 'static,
+{
+    let started_count = Arc::new(AtomicUsize::new(0));
+    let barrier = Arc::new(AtomicBool::new(false));
+    let threads: Vec<_> = (0..thread_count)
+        .map(|_| {
+            let started_count = started_count.clone();
+            let barrier = barrier.clone();
+            let callback = callback.clone();
+
+            std::thread::spawn(move || {
+                started_count.fetch_add(1, Ordering::SeqCst);
+                while !barrier.load(Ordering::SeqCst) {
+                    std::thread::yield_now();
+                }
+
+                callback()
+            })
+        })
+        .collect();
+
+    while started_count.load(Ordering::SeqCst) != thread_count {
+        std::thread::yield_now();
+    }
+    barrier.store(true, Ordering::SeqCst);
+
+    threads
+        .into_iter()
+        .map(|handle| handle.join())
+        .collect::<Result<Vec<R>, _>>()
+        .unwrap()
+}
+
+fn bench_logger(c: &mut Criterion) {
+    let env_filter = EnvFilter::default()
+        .add_directive("info".parse().unwrap())
+        .add_directive("ws=off".parse().unwrap())
+        .add_directive("yamux=off".parse().unwrap())
+        .add_directive("regalloc=off".parse().unwrap())
+        .add_directive("cranelift_codegen=off".parse().unwrap())
+        .add_directive("cranelift_wasm=warn".parse().unwrap())
+        .add_directive("hyper=warn".parse().unwrap())
+        .add_directive("dummy=trace".parse().unwrap());
+
+    let builder = tracing_log::LogTracer::builder().with_max_level(log::LevelFilter::Trace);
+
+    #[cfg(feature = "interest-cache")]
+    let builder = builder.with_interest_cache(Some(tracing_log::InterestCacheConfig::default()));
+
+    builder.init().unwrap();
+
+    let builder = FmtSubscriber::builder()
+        .with_env_filter(env_filter)
+        .with_filter_reloading();
+
+    let subscriber = builder.finish();
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+
+    const THREAD_COUNT: usize = 8;
+
+    c.bench_function("log_from_multiple_threads", |b| {
+        b.iter_custom(|count| {
+            let durations = run_on_many_threads(THREAD_COUNT, move || {
+                let start = Instant::now();
+                for _ in 0..count {
+                    trace!("A dummy log!");
+                }
+                start.elapsed()
+            });
+
+            let total_time: Duration = durations.into_iter().sum();
+            Duration::from_nanos((total_time.as_nanos() / THREAD_COUNT as u128) as u64)
+        })
+    });
+}
+
+criterion_group!(benches, bench_logger);
+criterion_main!(benches);