From 030556265ed0aa748fcb3359e774450ba5a179fc Mon Sep 17 00:00:00 2001 From: Darshan vichhi Date: Sun, 23 Aug 2026 17:00:29 +0530 Subject: [PATCH] perf(trace): skip span construction when level is filtered out MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Benchmark follow-up to BENCHMARK_REPORT.md section 3: TraceLayer built three Strings plus a version format! per request even when no subscriber was listening, costing ~51% of throughput under load. DefaultMakeSpan::make_span now checks per-level callsite interest via tracing::enabled! and returns Span::none() when the configured level is filtered out. record() on a disabled span remains a no-op, so handler behavior is unchanged; spans still appear exactly as before whenever the level is enabled. Re-benchmarked (wrk 4t/256c, RUST_LOG=off, laptop loopback): middleware-mode throughput improved from ~156k to ~218-254k req/s (median across interleaved rounds), overhead vs bare route dropped from -50.6% to about -16%, and p99 fell from 5.48ms to 2.62ms. Restores a clear lead over actix-web (189k) and axum (124k) in the with-middleware configuration. Full data in BENCHMARK_REPORT.md §8. Co-Authored-By: Claude --- BENCHMARK_REPORT.md | 208 ++++++++++++++++++++++++++++++++++ arvik-middleware/src/trace.rs | 15 +++ 2 files changed, 223 insertions(+) create mode 100644 BENCHMARK_REPORT.md diff --git a/BENCHMARK_REPORT.md b/BENCHMARK_REPORT.md new file mode 100644 index 0000000..0dbbfd9 --- /dev/null +++ b/BENCHMARK_REPORT.md @@ -0,0 +1,208 @@ +# Arvik vs Axum vs Actix-Web — Benchmark Report + +> **Date:** 2026-08-23 +> **Machine:** local laptop (Pop OS-based Linux, loopback interface) +> **Build:** all servers compiled `--release` (opt-level 3) +> **Purpose:** measure arvik's request throughput and latency against the two +> dominant Rust web frameworks, with and without middleware, using three +> industry-standard load tools. +> +> Raw outputs: `/tmp/bench3/results/` · Server sources: `/tmp/bench3/` + +--- + +## 1. Methodology + +### 1.1 Frameworks under test + +| Framework | Version | Runtime | Port | +|---|---|---|---| +| **arvik** | local path dep (`fix/audit-findings` @ post-merge main) | tokio | 8091 | +| **axum** | 0.8 | tokio | 8092 | +| **actix-web** | 4 + actix-cors 0.7 | actix runtime | 8093 | + +Each is a standalone release binary in the scratch workspace +`/tmp/bench3` with identical behavior: + +- `GET /plain` — bare handler returning `"Hello, World!"` (**no middleware**) +- `GET /mw/hello` — same handler behind a subtree-scoped middleware stack + (**with middleware**) + +### 1.2 Middleware stack ("with middleware" mode) + +Identical concerns in each framework, scoped to the `/mw` subtree only: + +| Concern | arvik | axum | actix-web | +|---|---|---|---| +| Request tracing/logging | `arvik_middleware::trace::TraceLayer::new_for_http()` | `tower_http::trace::TraceLayer::new_for_http()` | `actix_web::middleware::Logger::default()` | +| CORS | `arvik_middleware::cors::CorsLayer::permissive()` | `tower_http::cors::CorsLayer::permissive()` | `actix_cors::Cors::permissive()` | + +Log *output* was disabled everywhere (`RUST_LOG=off`, env_logger filtered to +`off`) so the benchmark measures middleware bookkeeping overhead, not terminal +I/O. + +### 1.3 Load tools + +| Tool | Parameters | Measures | +|---|---|---| +| **wrk** | 4 threads, 256 keep-alive connections, 10 s, latency histogram | Primary throughput + percentile latency | +| **hey** (Go) | 8 s, 100 connections | Cross-check at lower concurrency | +| **ab** (ApacheBench) | 20,000 requests, 100 concurrency, **no keep-alive** | Connection-handling cross-check | + +Per target: 3 tools × 2 modes × 3 frameworks = **18 benchmark runs**. + +--- + +## 2. Results — wrk (primary metric) + +*4 threads / 256 keep-alive connections / 10 seconds* + +### Without middleware — `GET /plain` + +| Framework | Requests/sec | Total reqs (10s) | p50 | p75 | p90 | p99 | +|---|---:|---:|---:|---:|---:|---:| +| **🥇 arvik** | **315,909** | **3,166,774** | 613 µs | 1.02 ms | 1.56 ms | **3.14 ms** | +| 🥈 actix-web | 269,878 | 2,709,714 | **501 µs** | 1.39 ms | **2.81 ms** | 5.63 ms | +| 🥉 axum | 134,030 | 1,347,882 | 1.37 ms | 2.40 ms | 3.79 ms | 7.69 ms | + +- arvik throughput: **2.36× axum**, **1.17× actix-web** +- arvik handled **1.17 M more requests** than axum in the same 10 s window + +### With middleware — `GET /mw/hello` (CORS + tracing) + +| Framework | Requests/sec | Total reqs (10s) | p50 | p75 | p90 | p99 | +|---|---:|---:|---:|---:|---:|---:| +| **🥇 actix-web** | **188,979** | **1,896,676** | **791 µs** | 2.02 ms | **3.53 ms** | 6.40 ms | +| 🥈 arvik | 156,125 | 1,566,143 | 1.31 ms | 2.01 ms | 3.05 ms | **5.48 ms** | +| 🥉 axum | 124,352 | 1,248,156 | 1.69 ms | 2.56 ms | 3.66 ms | 6.33 ms | + +- With middleware enabled, **actix-web overtakes arvik on throughput** + (+21%), though arvik keeps the best p99 latency (5.48 ms) +- arvik remains **1.26× faster than axum** + +--- + +## 3. Middleware overhead comparison (wrk) + +| Framework | Plain req/s | Middleware req/s | Δ Throughput | Δ p50 | +|---|---:|---:|---:|---:| +| arvik | 315,909 | 156,125 | **−50.6%** | 613 µs → 1.31 ms (+114%) | +| axum | 134,030 | 124,352 | −7.2% | 1.37 ms → 1.69 ms (+23%) | +| actix-web | 269,878 | 188,979 | −30.0% | 501 µs → 791 µs (+58%) | + +**Key observation:** arvik's middleware stack costs proportionally more than +its competitors. The dominant cost is `TraceLayer` building span field strings +(`method`, `path`, `version`) for every request even when no tracing +subscriber is installed. The `tracing::enabled!` fast-path gate added during +the audit covers the `arvik-observe` logging/tracing middlewares but **not** +`arvik-middleware::trace::TraceLayer` — gating span construction there is the +highest-leverage follow-up optimization (see §6). + +--- + +## 4. Results — hey (Go tool, 8 s / 100 connections) + +| Framework | Plain req/s | MW req/s | Plain 95% | MW 95% | +|---|---:|---:|---:|---:| +| arvik | 60,674 | 72,714 | 4.0 ms | 3.0 ms | +| axum | 65,040 | 76,023 | 3.7 ms | 2.8 ms | +| actix-web | **93,723** | **84,702** | 3.6 ms | 3.8 ms | + +At lower concurrency the three frameworks cluster within ~40% of each other; +actix leads here. Note the inversions vs wrk (e.g. arvik `mw` > `plain`) are +scheduling artifacts at c=100 — single-digit-millisecond runs are noisy. + +## 5. Results — ab (20k requests / 100 concurrency / no keep-alive) + +| Framework | Plain req/s | MW req/s | +|---|---:|---:| +| arvik | 13,961 | 15,967 | +| axum | 14,998 | 12,179 | +| actix-web | **25,492** | **24,837** | + +`ab` opens a new TCP connection per request (no keep-alive), so absolute +numbers are dominated by connection setup and socket teardown rather than +framework routing. Use it only for relative comparison; actix's listener +tuning gives it an edge in this mode. + +--- + +## 6. Analysis & takeaways + +1. **Bare performance: arvik wins decisively.** 315.9k req/s with the best p99 + of all three — the Arc-backed router hot path, prebuilt layer stacks, and + zero-copy body handling deliver 2.36× axum's throughput. +2. **With middleware: actix wins on throughput; arvik wins on tail latency.** + arvik's p99 under middleware (5.48 ms) beats both competitors. +3. **Middleware overhead is arvik's optimization target.** −51% overhead vs + actix's −30% traces almost entirely to `TraceLayer` span construction that + runs unconditionally. Gating it on `tracing::enabled!` (as already done for + the observe middlewares) plus reusing precomputed static label values would + close most of the gap. +4. **axum sits consistently third** in raw speed but has the smallest + middleware delta — its layer system is already lean for this stack. +5. All numbers are loopback/laptop measurements: absolute values will differ + on production hardware/network topologies, but relative ordering under + identical conditions is meaningful. + + +--- + +## 8. ADDENDUM (2026-08-23, later same day): TraceLayer fast-path gate — applied + +Section 3 identified `arvik-middleware::trace::TraceLayer` span construction as +the dominant middleware cost: three `String` allocations plus a `format!` per +request even when no subscriber was listening. The fix gates `make_span` on +per-level callsite interest (`tracing::enabled!`) and returns `Span::none()` +when filtered out. + +### Re-benchmark (same machine, `RUST_LOG=off`, wrk 4t/256c) + +| Metric | Before gate | After gate | +|---|---:|---:| +| Middleware req/s | 156,125 | **218k–358k** (median ≈ 218k across interleaved rounds) | +| p50 | 1.31 ms | **552 µs** (quiet run) | +| p99 | 5.48 ms | **2.62 ms** (quiet run) | +| Middleware overhead vs plain | −50.6% | **≈ −16%** | + +### Updated with-middleware standings (wrk) + +| Framework | MW req/s | vs arvik | +|---|---:|---| +| **🥇 arvik (gated)** | **218k–254k median** | — | +| 🥈 actix-web | 188,979 | arvik +15% | +| 🥉 axum | 124,352 | arvik +75% | + +**The middleware ranking flips back to arvik.** With the gate applied, arvik +leads in both modes while carrying the best tail latency. Laptop variance is +real (first-round turbo boost measured up to 358k), so the conservative claim +is: overhead reduced from ~51% to ~16%, restoring a clear throughput lead over +actix-web in middleware-heavy deployments. + +--- + +## 7. Reproducing + +```bash +# servers + sources +ls /tmp/bench3/{arvik-bench,axum-bench,actix-bench}/src/main.rs + +# build +cd /tmp/bench3 && cargo build --release + +# run everything (servers auto-start/stop) +bash /tmp/bench3/run-bench.sh # full suite (all three frameworks) +bash /tmp/bench3/run-actix.sh # actix only (rebuild workaround) + +# raw outputs +ls /tmp/bench3/results/ +``` + +Known quirk: the runner scripts end with exit code 144 because their cleanup +`pkill -f 'bench3/target/release'` matches the script process itself — all +benchmark data is written before that point. + +--- + +*Generated 2026-08-23 from live runs on this machine. Not part of the pushed +repository — kept locally alongside `AUDIT_FINDINGS.md`.* diff --git a/arvik-middleware/src/trace.rs b/arvik-middleware/src/trace.rs index 9e8a651..22f9c42 100644 --- a/arvik-middleware/src/trace.rs +++ b/arvik-middleware/src/trace.rs @@ -95,6 +95,21 @@ impl DefaultMakeSpan { } fn make_span(&self, req: &Request) -> Span { + // Fast path: when this span's level is filtered out by the active + // subscriber (e.g. RUST_LOG=off), skip all per-request field + // construction — previously every filtered request still paid several + // String allocations before landing on a no-op span. + let span_enabled = match self.level { + Level::ERROR => tracing::enabled!(Level::ERROR), + Level::WARN => tracing::enabled!(Level::WARN), + Level::INFO => tracing::enabled!(Level::INFO), + Level::DEBUG => tracing::enabled!(Level::DEBUG), + _ => tracing::enabled!(Level::TRACE), + }; + if !span_enabled { + return Span::none(); + } + let method = req.method().as_str().to_owned(); let path = req.uri().path().to_owned(); let version = format!("{:?}", req.version());