Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add an interest cache for logs emitted through the log crate #1636

Merged
merged 6 commits into from
Oct 18, 2021
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions tracing-log/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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
91 changes: 91 additions & 0 deletions tracing-log/benches/logging.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,91 @@
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));
#[allow(clippy::needless_collect)]
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);
Loading