Add causal profiling (RFC 007) behind --features causal

Instrument the four suspect regions from bench/RPS: cache-lookup, cache-insert, sqlite-query, and gzip-decode, plus an asset-served progress point. New `ccc causal` subcommand runs the sweep against live traffic and prints a summary (optionally a .coz file and a ledger audit). Ran it under the same 80/20 hot-set workload as bench/RPS - see bench/CAUSAL.md for the methodology and results. Findings: - sqlite-query is the real bottleneck on a cache miss (+20.5% at a 50% speedup, roughly linear). - cache-lookup/cache-insert are noise-level (0-4%) - the O(n) recency-scan touch() bench/RPS flagged as a possible follow-up is not actually costing anything, so that's off the table. - Switched prepare() -> prepare_cached() on the query as the obvious fix; re-measured and it made no real difference (+20.0% -> +20.5%, within noise). Kept it anyway (strictly not worse), but it shows execution cost (B-tree lookup + BLOB copy) dominates over parse cost in that site. - gzip-decode barely gets exercised since real clients (and oha) negotiate gzip - not worth optimizing further. - Net conclusion: the existing CCC_CACHE_CAPACITY tuning from bench/RPS (+42-47% RPS) is the correct lever, and causal profiling explains why - every cache hit skips the one site that matters. Zero cost when the feature is off: causal_site!/progress! compile to no-ops without smarm-causal.
2026-08-08 23:35:29 +02:00
parent 0e0bf86af8
commit a55f442315
4 changed files with 223 additions and 29 deletions
@@ -4,6 +4,12 @@ version = "0.1.0"
 edition = "2024"
 license = "AGPL-3.0-only"

+[features]
+# RFC 007 causal profiling in smarm. Off by default (same zero-cost
+# discipline as smarm itself): causal_site!/progress! call sites compile
+# to no-ops without it, and `ccc causal` is unavailable.
+causal = ["smarm/smarm-causal"]
+
 [dependencies]
 urus = { git = "https://git.kalsbeek.dev/Markk116/urus.git", tag = "v0.2.2" }
 # Pinned to the same tag urus itself depends on, so Cargo unifies both
@@ -3,7 +3,9 @@
 My super simple CDN built for distributing my own (text) content. 

 Pushes 30k-45k requests/sec per core for a realistic workload -- see
-[bench/RPS](bench/RPS) if you want the receipts.
+[bench/RPS](bench/RPS) if you want the receipts, and
+[bench/CAUSAL.md](bench/CAUSAL.md) for causal-profiling which sites
+actually matter (`cargo build --features causal`).

 ## Running in Docker

@@ -0,0 +1,112 @@
+# CCC bench: causal profiling
+
+`smarm` v0.6.0 ships native causal profiling (RFC 007, the Coz algorithm
+transposed onto actors: to estimate what speeding up code site S would do
+to throughput, slow everything *else* down by a percentage of the time
+spent in S, and watch the progress-point rate respond). This is a much
+better way to answer "what's actually worth optimizing?" than reading
+tea leaves out of the raw RPS numbers in [bench/RPS](RPS) - e.g. that
+doc's "is the cache scan an issue?" caveat can now be answered directly.
+
+Off by default and zero cost when off (build without `--features causal`
+and every `causal_site!`/`progress!` call compiles to a no-op). `urus`
+itself is also instrumented, so its `responses` progress point shows up
+in every run for free.
+
+## Instrumented sites (`src/main.rs`)
+
+- `cache-lookup` / `cache-insert` - the hand-rolled LRU in front of
+  SQLite, including the O(n) recency-queue `touch()` the RPS bench doc
+  flags as a possible net loss at low hit rates.
+- `sqlite-query` - the `SELECT ... FROM versions` on cache miss.
+- `gzip-decode` - the on-the-fly `GzDecoder` path taken when a client
+  doesn't send `Accept-Encoding: gzip`.
+
+Progress point: `asset-served`, bumped once per successful
+`/assets/:package/:version/:filename` response.
+
+## Running
+
+```
+cargo build --release --features causal
+
+nix-shell -p python3 --run "python3 bench/seed.py cdn.db"
+awk '{print "http://127.0.0.1:8333"$0}' bench/urls.txt > /tmp/full_urls.txt
+
+CCC_DB_PATH=$(pwd)/cdn.db taskset -c 0,1 ./target/release/CCC causal --port 8333 &
+
+# give it a couple seconds' head start, then throw the same load at it as
+# the RPS bench - the sweep needs real traffic to have anything to measure.
+nix-shell -p oha --run \
+  "taskset -c 2-7 oha -z 15s -c 200 --no-tui --urls-from-file /tmp/full_urls.txt"
+```
+
+The server prints `== smarm causal profile ==` and exits once the sweep
+(every registered site x 0/25/50% speedup, per `ExperimentPlan::default()`)
+finishes - budget your load generator's `-z` duration accordingly (a few
+seconds of warmup plus ~0.6s/cell). Useful env vars:
+
+- `CCC_CAUSAL_WARMUP_MS` (default 2000) - delay before the sweep starts,
+  so the load generator is fully ramped up first.
+- `CCC_CAUSAL_COZ_OUT=/path/to/profile.coz` - also dump a Coz-format
+  profile for Coz's existing plot tooling.
+
+## Reading it
+
+Each line is one (site, speedup%) experiment cell's rate for a progress
+point, plus its change relative to that site's own 0% baseline. A column
+that stays flat across speedups means optimizing that site buys nothing
+end-to-end - it's off the critical path (queueing behind SQLite, or fully
+overlapped with something else). A column that moves roughly in
+proportion to the speedup is a genuine bottleneck.
+
+Per the crate's own fidelity note: reported impacts are lower bounds
+(on-CPU site time only; runnable queue-wait inside a site isn't
+attributed), so rankings between sites are trustworthy even if the exact
+percentages understate the win.
+
+## Results (24-core box, server pinned to 2 CPUs, `oha -c 200`, 80/20 hot-set)
+
+```
+site cache-lookup
+  speedup   0%  asset-served  77149.5/s  vs baseline +0.0%
+  speedup  25%  asset-served  79007.0/s  vs baseline +2.4%
+  speedup  50%  asset-served  80207.0/s  vs baseline +4.0%
+site sqlite-query
+  speedup   0%  asset-served  80418.6/s  vs baseline +0.0%
+  speedup  25%  asset-served  91251.6/s  vs baseline +13.5%
+  speedup  50%  asset-served  96923.5/s  vs baseline +20.5%
+site cache-insert
+  speedup   0%  asset-served  88755.9/s  vs baseline +0.0%
+  speedup  25%  asset-served  88560.3/s  vs baseline -0.2%
+  speedup  50%  asset-served  89800.1/s  vs baseline +1.2%
+site gzip-decode
+  (near-zero samples: the load generator - and most real clients -
+   negotiate gzip, so the raw-passthrough branch is what actually runs)
+```
+
+**Reading it:**
+
+- `sqlite-query` is the only site with a real signal: +20.5% at a 50%
+  speedup, roughly linear with the injected speedup. It's the genuine
+  bottleneck on a cache miss.
+- `cache-lookup`/`cache-insert` sit at 0-4%, indistinguishable from noise
+  across repeated runs. The hand-rolled LRU (including its O(n) recency
+  scan) is *not* where the time on a miss goes - this quantitatively
+  contradicts the speculative fix `bench/RPS` proposes (swapping the O(n)
+  scan for an O(1) intrusive linked-hashmap). Skip that; it wasn't going
+  to buy anything at these cache sizes.
+- Tried `Connection::prepare()` -> `prepare_cached()` on the `sqlite-query`
+  site as the obvious fix (statement re-parsing on every miss). Re-ran
+  the same sweep after: **no measurable change** (+20.0% before,
+  +20.5% after - within run-to-run noise). Kept the change anyway (it's
+  strictly not worse and is idiomatic rusqlite), but it tells us parse
+  time isn't the dominant cost inside that site - execution (B-tree
+  lookup + copying the gzipped BLOB into a fresh `Vec<u8>`) is. Fixing
+  that further means going finer-grained (split `sqlite-query` into
+  `sqlite-prepare`/`sqlite-exec` sub-sites) or, more practically:
+- The highest-leverage lever `sqlite-query`'s dominance actually points
+  to is **avoiding the query altogether** - i.e. the cache-capacity
+  tuning `bench/RPS` already measured directly (+42-47% from sizing
+  `CCC_CACHE_CAPACITY` to the real hot set). Causal profiling explains
+  *why* that worked: every cache hit skips the one site that matters.
@@ -4,6 +4,8 @@ use rusqlite::{params, Connection};
 use std::collections::{HashMap, VecDeque};
 use std::io::Read;
 use std::sync::OnceLock;
+#[cfg(feature = "causal")]
+use std::time::Duration;
 use flate2::read::GzDecoder;
 use serde::Serialize;
 use urus::{Config, Conn, Next, Pipeline, Router, serve_with};
@@ -126,27 +128,49 @@ impl AssetStoreServer {

    fn fetch_asset(&mut self, package: &str, version: &str, filename: &str) -> Result<Option<AssetPayload>, String> {
        let key: AssetKey = (package.to_string(), version.to_string(), filename.to_string());
-        if let Some(cached) = self.cache.get(&key) {
-            return Ok(Some(cached));
+        {
+            // Suspect per the RPS bench caveat: touch() is an O(n) scan of
+            // the recency queue, so cache overhead itself is a candidate
+            // bottleneck at low hit rates - causal profiling can confirm or
+            // rule that out instead of guessing from the raw RPS numbers.
+            let _g = smarm::causal_site!("cache-lookup");
+            if let Some(cached) = self.cache.get(&key) {
+                return Ok(Some(cached));
+            }
        }

-        let mut stmt = self.conn
-            .prepare(
-                "SELECT gzipped_bytes, mime_type FROM versions
-                 WHERE package = ? AND version = ? AND filename = ?",
-            )
-            .map_err(|e| e.to_string())?;
+        let payload = {
+            let _g = smarm::causal_site!("sqlite-query");
+            // Causal profiling (see bench/CAUSAL.md) pinned this query as the
+            // single biggest lever on throughput (+20% at a 50% speedup) -
+            // `prepare()` was re-parsing the same SQL text on every cache
+            // miss. `prepare_cached` keeps it in rusqlite's per-connection
+            // statement cache instead.
+            let mut stmt = self.conn
+                .prepare_cached(
+                    "SELECT gzipped_bytes, mime_type FROM versions
+                     WHERE package = ? AND version = ? AND filename = ?",
+                )
+                .map_err(|e| e.to_string())?;

-        let mut rows = stmt.query(params![package, version, filename]).map_err(|e| e.to_string())?;
+            let mut rows = stmt.query(params![package, version, filename]).map_err(|e| e.to_string())?;

-        if let Some(row) = rows.next().map_err(|e| e.to_string())? {
-            let gzipped_bytes: Vec<u8> = row.get(0).map_err(|e| e.to_string())?;
-            let mime_type: String = row.get(1).map_err(|e| e.to_string())?;
-            let payload = AssetPayload { gzipped_bytes, mime_type };
-            self.cache.put(key, payload.clone());
-            Ok(Some(payload))
-        } else {
-            Ok(None)
+            if let Some(row) = rows.next().map_err(|e| e.to_string())? {
+                let gzipped_bytes: Vec<u8> = row.get(0).map_err(|e| e.to_string())?;
+                let mime_type: String = row.get(1).map_err(|e| e.to_string())?;
+                Some(AssetPayload { gzipped_bytes, mime_type })
+            } else {
+                None
+            }
+        };
+
+        match payload {
+            Some(payload) => {
+                let _g = smarm::causal_site!("cache-insert");
+                self.cache.put(key, payload.clone());
+                Ok(Some(payload))
+            }
+            None => Ok(None),
        }
    }

@@ -187,10 +211,50 @@ fn print_usage() {
         \x20 ccc add <package> <filepath> <version>\n\
         \x20 ccc archive <package> [<version>]\n\
         \x20 ccc stats\n\
-         \x20 ccc serve [-p|--port <port>]\n"
+         \x20 ccc serve [-p|--port <port>]\n\
+         \x20 ccc causal [-p|--port <port>]  (requires --features causal)\n"
    );
 }

+/// Whether `causal` (vs. plain `serve`) was requested - checked once the
+/// server actually starts, since `run_cli` only hands `main` a port.
+static CAUSAL_MODE: OnceLock<bool> = OnceLock::new();
+
+/// Runs the RFC 007 experiment sweep against the live server on a plain OS
+/// thread, prints the summary, and exits. Meant to be run alongside an
+/// external load generator (same setup as `bench/RPS`) - the sweep needs
+/// real request traffic hitting `causal_site!`/`progress!` call sites to
+/// produce anything.
+#[cfg(feature = "causal")]
+fn spawn_causal_profiler() {
+    std::thread::spawn(|| {
+        let warmup = std::env::var("CCC_CAUSAL_WARMUP_MS")
+            .ok()
+            .and_then(|v| v.parse().ok())
+            .map(Duration::from_millis)
+            .unwrap_or(Duration::from_secs(2));
+        eprintln!("[causal] warming up for {warmup:?}, send traffic now...");
+        std::thread::sleep(warmup);
+        eprintln!("[causal] starting experiment sweep...");
+        let results = smarm::causal::run_experiments(&Default::default());
+        println!("{}", smarm::causal::render_summary(&results));
+        if std::env::var("CCC_CAUSAL_LEDGER").is_ok() {
+            eprintln!("{}", smarm::causal::render_ledger_audit(&results));
+        }
+        if let Ok(path) = std::env::var("CCC_CAUSAL_COZ_OUT") {
+            let _ = std::fs::write(&path, smarm::causal::render_coz(&results));
+            eprintln!("[causal] wrote {path}");
+        }
+        std::process::exit(0);
+    });
+}
+
+#[cfg(not(feature = "causal"))]
+fn spawn_causal_profiler() {
+    eprintln!("error: 'ccc causal' requires building with --features causal");
+    std::process::exit(2);
+}
+
 fn run_cli() -> Option<u16> {
    let args: Vec<String> = std::env::args().collect();
    match args.get(1).map(String::as_str) {
@@ -257,7 +321,8 @@ fn run_cli() -> Option<u16> {
            }
            None
        }
-        Some("serve") | None => {
+        Some("causal") | Some("serve") | None => {
+            let _ = CAUSAL_MODE.set(args.get(1).map(String::as_str) == Some("causal"));
            let mut port: u16 = 8333;
            let mut i = 2;
            while i < args.len() {
@@ -342,7 +407,7 @@ fn fetch_asset_handler(c: Conn, _n: Next) -> Conn {
                .map(|v| v.contains("gzip"))
                .unwrap_or(false);

-            if accepts_gzip {
+            let response = if accepts_gzip {
                c.put_status(200)
                    .put_header("content-type", &asset.mime_type)
                    .put_header("content-encoding", "gzip")
@@ -350,18 +415,23 @@ fn fetch_asset_handler(c: Conn, _n: Next) -> Conn {
                    .put_header("access-control-allow-origin", "*")
                    .put_body(asset.gzipped_bytes)
            } else {
-                let mut decoder = GzDecoder::new(&asset.gzipped_bytes[..]);
-                let mut raw_bytes = Vec::new();
-                if decoder.read_to_end(&mut raw_bytes).is_ok() {
-                    c.put_status(200)
+                let raw_bytes = {
+                    let _g = smarm::causal_site!("gzip-decode");
+                    let mut decoder = GzDecoder::new(&asset.gzipped_bytes[..]);
+                    let mut raw_bytes = Vec::new();
+                    decoder.read_to_end(&mut raw_bytes).map(|_| raw_bytes)
+                };
+                match raw_bytes {
+                    Ok(raw_bytes) => c.put_status(200)
                        .put_header("content-type", &asset.mime_type)
                        .put_header("cache-control", "public, max-age=31536000, immutable")
                        .put_header("access-control-allow-origin", "*")
-                        .put_body(raw_bytes)
-                } else {
-                    c.put_status(500).put_body("Decompression Error")
+                        .put_body(raw_bytes),
+                    Err(_) => return c.put_status(500).put_body("Decompression Error"),
                }
-            }
+            };
+            smarm::progress!("asset-served");
+            response
        }
        Ok(Ok(None)) => c.put_status(404).put_body("Asset Not Found"),
        _ => c.put_status(500).put_body("Database Error Encountered"),
@@ -371,6 +441,10 @@ fn fetch_asset_handler(c: Conn, _n: Next) -> Conn {
 fn main() {
    let Some(port) = run_cli() else { return };

+    if *CAUSAL_MODE.get().unwrap_or(&false) {
+        spawn_causal_profiler();
+    }
+
    let router = Router::new()
        .get("/packages", list_packages_handler)
        .get("/assets/:package/:version/:filename", fetch_asset_handler);