mirror of
https://github.com/neondatabase/neon.git
synced 2026-01-14 00:42:54 +00:00
6621be6b7b
## Problem We recently added slow GetPage request logging. However, this unintentionally included the flush time when logging (which we already have separate logging for). It also logs at WARN level, which is a bit aggressive since we see this fire quite frequently. Follows https://github.com/neondatabase/neon/pull/10906. ## Summary of changes * Only log the request execution time, not the flush time. * Extract a `pagestream_dispatch_batched_message()` helper. * Rename `warn_slow()` to `log_slow()` and downgrade to INFO.
60 lines
1.9 KiB
Rust
60 lines
1.9 KiB
Rust
use std::time::Duration;
|
|
|
|
use criterion::{criterion_group, criterion_main, Bencher, Criterion};
|
|
use pprof::criterion::{Output, PProfProfiler};
|
|
use utils::id;
|
|
use utils::logging::log_slow;
|
|
|
|
// Register benchmarks with Criterion.
|
|
criterion_group!(
|
|
name = benches;
|
|
config = Criterion::default().with_profiler(PProfProfiler::new(100, Output::Flamegraph(None)));
|
|
targets = bench_id_stringify,
|
|
bench_log_slow,
|
|
);
|
|
criterion_main!(benches);
|
|
|
|
pub fn bench_id_stringify(c: &mut Criterion) {
|
|
// Can only use public methods.
|
|
let ttid = id::TenantTimelineId::generate();
|
|
|
|
c.bench_function("id.to_string", |b| {
|
|
b.iter(|| {
|
|
// FIXME measurement overhead?
|
|
//for _ in 0..1000 {
|
|
// ttid.tenant_id.to_string();
|
|
//}
|
|
ttid.tenant_id.to_string();
|
|
})
|
|
});
|
|
}
|
|
|
|
pub fn bench_log_slow(c: &mut Criterion) {
|
|
for enabled in [false, true] {
|
|
c.bench_function(&format!("log_slow/enabled={enabled}"), |b| {
|
|
run_bench(b, enabled).unwrap()
|
|
});
|
|
}
|
|
|
|
// The actual benchmark.
|
|
fn run_bench(b: &mut Bencher, enabled: bool) -> anyhow::Result<()> {
|
|
const THRESHOLD: Duration = Duration::from_secs(1);
|
|
|
|
// Use a multi-threaded runtime to avoid thread parking overhead when yielding.
|
|
let runtime = tokio::runtime::Builder::new_multi_thread()
|
|
.enable_all()
|
|
.build()?;
|
|
|
|
// Test both with and without log_slow, since we're essentially measuring Tokio scheduling
|
|
// performance too. Use a simple noop future that yields once, to avoid any scheduler fast
|
|
// paths for a ready future.
|
|
if enabled {
|
|
b.iter(|| runtime.block_on(log_slow("ready", THRESHOLD, tokio::task::yield_now())));
|
|
} else {
|
|
b.iter(|| runtime.block_on(tokio::task::yield_now()));
|
|
}
|
|
|
|
Ok(())
|
|
}
|
|
}
|