From ef737e7d7c0b6d34c7703aec4a24bb4d416ab30e Mon Sep 17 00:00:00 2001 From: Folke Behrens Date: Thu, 6 Feb 2025 11:12:53 +0100 Subject: [PATCH] proxy: add benchmark for custom json logging vs official fmt logger --- Cargo.lock | 1 + proxy/Cargo.toml | 6 ++ proxy/benches/logging.rs | 127 +++++++++++++++++++++++++++++++++++++++ proxy/src/lib.rs | 2 +- proxy/src/logging.rs | 12 ++-- 5 files changed, 141 insertions(+), 7 deletions(-) create mode 100644 proxy/benches/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 3474211ac6..98b0cf42f6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5303,6 +5303,7 @@ dependencies = [ "clashmap", "compute_api", "consumption_metrics", + "criterion", "ecdsa 0.16.9", "ed25519-dalek", "env_logger", diff --git a/proxy/Cargo.toml b/proxy/Cargo.toml index 82fe6818e3..4ef685aad3 100644 --- a/proxy/Cargo.toml +++ b/proxy/Cargo.toml @@ -120,6 +120,7 @@ workspace_hack.workspace = true [dev-dependencies] assert-json-diff.workspace = true camino-tempfile.workspace = true +criterion.workspace = true fallible-iterator.workspace = true flate2.workspace = true tokio-tungstenite.workspace = true @@ -130,3 +131,8 @@ walkdir.workspace = true rand_distr = "0.4" tokio-postgres.workspace = true tracing-test = "0.2" + +[[bench]] +name = "logging" +harness = false + diff --git a/proxy/benches/logging.rs b/proxy/benches/logging.rs new file mode 100644 index 0000000000..fe5d1f9dc4 --- /dev/null +++ b/proxy/benches/logging.rs @@ -0,0 +1,127 @@ +use std::io; + +use criterion::{Criterion, criterion_group, criterion_main}; +use proxy::logging::{Clock, JsonLoggingLayer}; +use tracing_subscriber::prelude::*; + +struct DevNullWriter; + +impl proxy::logging::MakeWriter for DevNullWriter { + fn make_writer(&self) -> impl io::Write { + DevNullWriter + } +} + +impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for DevNullWriter { + type Writer = DevNullWriter; + fn make_writer(&'a self) -> Self::Writer { + DevNullWriter + } +} + +impl io::Write for DevNullWriter { + #[inline] + fn write(&mut self, buf: &[u8]) -> io::Result { + Ok(criterion::black_box(buf).len()) + } + + #[inline(always)] + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} + +struct FixedClock; + +impl Clock for FixedClock { + fn now(&self) -> chrono::DateTime { + const { chrono::DateTime::from_timestamp_nanos(1747859990_000_000_000).to_utc() } + } +} + +pub fn bench_logging(c: &mut Criterion) { + c.bench_function("text fmt current", |b| { + let registry = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_target(false) + .with_writer(DevNullWriter), + ); + + tracing::subscriber::with_default(registry, || { + tracing::info_span!("span1", a = 42, b = true, c = "string").in_scope(|| { + tracing::info_span!("span2", a = 42, b = true, c = "string").in_scope(|| { + b.iter(|| { + tracing::error!(a = 42, b = true, c = "string", "message field"); + }) + }); + }); + }); + }); + + c.bench_function("text fmt full", |b| { + let registry = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_level(true) + .with_file(true) + .with_line_number(true) + .with_target(true) + .with_thread_ids(true) + .with_writer(DevNullWriter), + ); + + tracing::subscriber::with_default(registry, || { + tracing::info_span!("span1", a = 42, b = true, c = "string").in_scope(|| { + tracing::info_span!("span2", a = 42, b = true, c = "string").in_scope(|| { + b.iter(|| { + tracing::error!(a = 42, b = true, c = "string", "message field"); + }) + }); + }); + }); + }); + + c.bench_function("json fmt", |b| { + let registry = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_level(true) + .with_file(true) + .with_line_number(true) + .with_target(true) + .with_thread_ids(true) + .with_writer(DevNullWriter) + .json(), + ); + + tracing::subscriber::with_default(registry, || { + tracing::info_span!("span1", a = 42, b = true, c = "string").in_scope(|| { + tracing::info_span!("span2", a = 42, b = true, c = "string").in_scope(|| { + b.iter(|| { + tracing::error!(a = 42, b = true, c = "string", "message field"); + }) + }); + }); + }); + }); + + c.bench_function("json custom", |b| { + let registry = tracing_subscriber::Registry::default().with(JsonLoggingLayer::new( + FixedClock, + DevNullWriter, + &["a"], + )); + + tracing::subscriber::with_default(registry, || { + tracing::info_span!("span1", a = 42, b = true, c = "string").in_scope(|| { + tracing::info_span!("span2", a = 42, b = true, c = "string").in_scope(|| { + b.iter(|| { + tracing::error!(a = 42, b = true, c = "string", "message field"); + }) + }); + }); + }); + }); +} + +criterion_group!(benches, bench_logging); +criterion_main!(benches); diff --git a/proxy/src/lib.rs b/proxy/src/lib.rs index 263d784e78..591c89f923 100644 --- a/proxy/src/lib.rs +++ b/proxy/src/lib.rs @@ -93,7 +93,7 @@ mod ext; mod http; mod intern; mod jemalloc; -mod logging; +pub mod logging; mod metrics; mod parse; mod pglb; diff --git a/proxy/src/logging.rs b/proxy/src/logging.rs index e608300bd2..36e48aab8c 100644 --- a/proxy/src/logging.rs +++ b/proxy/src/logging.rs @@ -148,11 +148,11 @@ impl LogFormat { } } -trait MakeWriter { +pub trait MakeWriter { fn make_writer(&self) -> impl io::Write; } -struct StderrWriter { +pub struct StderrWriter { stderr: io::Stderr, } @@ -164,11 +164,11 @@ impl MakeWriter for StderrWriter { } // TODO: move into separate module or even separate crate. -trait Clock { +pub trait Clock { fn now(&self) -> DateTime; } -struct RealClock; +pub struct RealClock; impl Clock for RealClock { #[inline] @@ -203,7 +203,7 @@ type CallsiteMap = papaya::HashMap>; /// Implements tracing layer to handle events specific to logging. -struct JsonLoggingLayer { +pub struct JsonLoggingLayer { clock: C, writer: W, @@ -217,7 +217,7 @@ struct JsonLoggingLayer { } impl JsonLoggingLayer { - fn new(clock: C, writer: W, extract_fields: &'static [&'static str]) -> Self { + pub fn new(clock: C, writer: W, extract_fields: &'static [&'static str]) -> Self { JsonLoggingLayer { clock, skipped_field_indices: CallsiteMap::default(),