From 6ebae37c513bd9f6f16f4fc4746c1ea37d2cdd7d Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Fri, 13 Nov 2026 23:59:00 -0500 Subject: [PATCH 01/14] feat(storage): add the benchmark rig for the LMDB and Postgres backends --- .changeset/benchmark-rig.md | 2 + .github/workflows/checks.yml | 7 + Cargo.lock | 1 + crates/nostream-storage/Cargo.toml | 9 + crates/nostream-storage/examples/bench.rs | 1103 +++++++++++++++++++++ 5 files changed, 1122 insertions(+) create mode 100644 .changeset/benchmark-rig.md create mode 100644 crates/nostream-storage/examples/bench.rs diff --git a/.changeset/benchmark-rig.md b/.changeset/benchmark-rig.md new file mode 100644 index 000000000..a845151cc --- /dev/null +++ b/.changeset/benchmark-rig.md @@ -0,0 +1,2 @@ +--- +--- diff --git a/.github/workflows/checks.yml b/.github/workflows/checks.yml index fff0fe613..8244f0e7a 100644 --- a/.github/workflows/checks.yml +++ b/.github/workflows/checks.yml @@ -279,6 +279,13 @@ jobs: env: PARITY_ADMIN_URL: postgres://postgres:postgres@localhost:5432/postgres run: cargo test -p nostream-storage --test migrations --test parity --test migration_pg -- --ignored --test-threads=1 + # The benchmark rig's Postgres column: the same workload and the same `--verify` the LMDB + # arm runs, against the scratch database it drops and recreates. The dev profile is + # deliberate — this proves the path and the counts, and its timings are cited nowhere. + - name: Benchmark harness against Postgres + env: + PARITY_ADMIN_URL: postgres://postgres:postgres@localhost:5432/postgres + run: cargo run -p nostream-storage --example bench -- --backend postgres --events 2000 --seed 7 --verify --out /tmp/bench-postgres.json - name: Storage builds without the Postgres driver run: cargo check -p nostream-storage --no-default-features --all-targets - name: Release build diff --git a/Cargo.lock b/Cargo.lock index 062a8c2f0..44bbdc173 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1347,6 +1347,7 @@ name = "nostream-storage" version = "0.1.0" dependencies = [ "chrono", + "clap", "futures-core", "heed", "nostream-config", diff --git a/crates/nostream-storage/Cargo.toml b/crates/nostream-storage/Cargo.toml index 516868329..7a1fdbaff 100644 --- a/crates/nostream-storage/Cargo.toml +++ b/crates/nostream-storage/Cargo.toml @@ -32,8 +32,17 @@ tracing = { workspace = true, optional = true } uuid = { workspace = true, optional = true } [dev-dependencies] +clap.workspace = true serde_yaml.workspace = true tempfile.workspace = true +# The benchmark rig (`docs/rewrite/benchmarks.md`). Both features are required: the harness holds +# either backend behind one `EventRepository`, so a build that turns one off has nothing to +# measure. The requirement is also what keeps CI's `--no-default-features --all-targets` check +# from compiling it. +[[example]] +name = "bench" +required-features = ["lmdb", "postgres"] + [lints] workspace = true diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs new file mode 100644 index 000000000..21061bff2 --- /dev/null +++ b/crates/nostream-storage/examples/bench.rs @@ -0,0 +1,1103 @@ +//! The benchmark rig: one deterministic workload, measured through `Arc` +//! against the LMDB store or a scratch Postgres database. +//! +//! `docs/rewrite/benchmarks.md` cites the artifact this writes and nothing else, so the workload +//! lives here as named constants rather than in a file that could drift away from the harness: +//! +//! ```text +//! cargo run --release -p nostream-storage --example bench -- \ +//! --backend lmdb --events 50000 --seed 7 --out /tmp/bench.json --verify +//! ``` +//! +//! Timings are never asserted and counts always are: `--verify` checks that the artifact records +//! the corpus it was asked for, so a run that measured a partial corpus, a filter that matched +//! nothing or a page that stopped early fails, while a slow host only makes the numbers large. +//! Everything that can differ between two runs of one command sits under the single `volatile` +//! key, which is what makes two runs comparable as `jq -S 'del(.volatile)'`. + +use std::collections::BTreeMap; +use std::error::Error; +use std::fmt; +use std::path::PathBuf; +use std::process::ExitCode; +use std::sync::Arc; +use std::time::Instant; + +use clap::{Parser, ValueEnum}; +use nostream_core::{Event, EventId, Filter, Kind, Pubkey, Signature}; +use nostream_storage::LmdbBackend; +use nostream_storage::backend::{store_exists, store_file}; +use nostream_storage::postgres::PostgresBackend; +use nostream_storage::repositories::{EventRecord, EventRepository, collect_records}; +use serde_json::{Map, Value, json}; +use sqlx::Executor; +use sqlx::postgres::PgPool; + +/// The corpus holds this many authors (`j = index % AUTHOR_COUNT`). +const AUTHOR_COUNT: u64 = 200; + +/// The kind each corpus event takes, in order: `KIND_CYCLE[index % KIND_CYCLE.len()]`. +/// +/// Replaceable kinds are absent on purpose: the relay writes kind 3 with `upsert` +/// (`strategies/contact_list.rs`), which is a different path from the `create` this measures. +const KIND_CYCLE: [u64; 10] = [1, 1, 1, 1, 1, 1, 1, 1, 7, 7]; + +/// The corpus content's length in bytes: 64 hex characters of the index, then `x`. +const CONTENT_LEN: usize = 256; + +/// How many distinct `["t", "bench-"]` values the corpus carries. +const TAG_VALUE_COUNT: u64 = 20; + +/// The newest `created_at` any corpus event carries. +const CREATED_AT_ANCHOR_UNIX: i64 = 1_700_000_000; + +/// The `created_at` spread below the anchor, and the window every read walks. +const CREATED_AT_WINDOW_SECS: i64 = 2_592_000; + +/// Events per `create_many` call: corpus loading, not ingest. +const WRITE_BATCH: usize = 500; + +/// The corpus tail ingested one `create` per call, which is the relay's own ingest shape +/// (`crates/nostream-relay/src/strategies/default.rs`). +const INGEST_EVENTS: u64 = 1_000; + +/// Iterations of each of the four filter read shapes. +const READ_ITERATIONS: u64 = 200; + +/// Iterations of the `count` shape, which is the expensive read. +const COUNT_ITERATIONS: u64 = 50; + +const BY_ID_LIMIT: u64 = 1; +const AUTHOR_KIND_LIMIT: u64 = 100; +const KIND_SINCE_LIMIT: u64 = 500; +const TAG_LIMIT: u64 = 100; + +/// The corpus ceiling a run may not cross without `--allow-large-corpus`. A 1M-event corpus is +/// about 1.4 GB of `data.mdb`, so the default refusal is what keeps a mistyped `--events` from +/// filling a measuring host's disk. +const MAX_CORPUS_EVENTS: u64 = 200_000; + +/// The per-event disk projection the large-corpus refusal prints: twice the worst measured +/// 2.1 KB/event, so the printed figure overstates rather than understates. +const BYTES_PER_EVENT_CEILING: u64 = 4_096; + +/// The scratch database the Postgres arm drops and recreates on every run. +const SCRATCH_DATABASE: &str = "nostream_bench_rust"; + +const DEFAULT_SEED: u64 = 7; + +/// `by_id` targets event `(seed * 7_919 + i * 7_919 + 13) % events`. +const BY_ID_STRIDE: u64 = 7_919; +const BY_ID_OFFSET: u64 = 13; + +#[derive(Clone, Copy, PartialEq, Eq, ValueEnum)] +enum Backend { + /// The embedded LMDB store, opened under `--store`. + Lmdb, + /// A scratch Postgres database, dropped and recreated through `PARITY_ADMIN_URL`. + Postgres, +} + +impl Backend { + fn name(self) -> &'static str { + match self { + Self::Lmdb => "lmdb", + Self::Postgres => "postgres", + } + } +} + +/// One command line and one workload; everything the artifact records is fixed here. +#[derive(Parser)] +#[command( + about = "Measures one deterministic workload against the LMDB store or a scratch Postgres database", + after_help = "The Postgres arm drops and recreates the scratch database named above on the server \ + PARITY_ADMIN_URL points at, so run it only where that name is expendable. \ + --store is refused with --backend postgres: the data lives in Postgres." +)] +struct Arguments { + /// The store to measure. + #[arg(long, value_enum)] + backend: Backend, + + /// The corpus size; the ingest phase takes the last 1000 events of it. + #[arg(long)] + events: u64, + + /// The corpus seed: one seed produces one corpus and one set of read targets. + #[arg(long, default_value_t = DEFAULT_SEED)] + seed: u64, + + /// Where the JSON artifact is written. + #[arg(long)] + out: PathBuf, + + /// Check that the artifact records the corpus it was asked for. + #[arg(long)] + verify: bool, + + /// The store root for --backend lmdb; a fresh temporary directory when absent. + #[arg(long)] + store: Option, + + /// Measure a corpus above the ceiling anyway. + #[arg(long)] + allow_large_corpus: bool, + + /// Measure beside a running compiler anyway. + #[arg(long)] + allow_busy_host: bool, +} + +/// Where the store's data lives, resolved once so the refusal and the open cannot disagree. +enum Store { + Temporary, + Given(PathBuf), +} + +/// The command line, after every refusal has been answered: no store has been touched yet. +struct Plan { + backend: Backend, + events: u64, + seed: u64, + out: PathBuf, + verify: bool, + store: Store, + admin_url: Option, +} + +/// How the run stopped: a refusal or a failure on stderr and exit 2, a verify failure exit 1. +#[derive(Debug)] +struct Refusal(String); + +impl fmt::Display for Refusal { + fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + formatter.write_str(&self.0) + } +} + +impl Error for Refusal {} + +type Fallible = Result>; + +fn refusal(message: impl Into) -> Box { + Box::new(Refusal(message.into())) +} + +/// One shape's row accounting: how many operations were issued and what they returned. +#[derive(Clone, Copy)] +struct ShapeCounts { + name: &'static str, + count: u64, + rows: u64, +} + +/// One shape's per-operation samples, reduced to the artifact's five fields. +struct Timing { + ops: u64, + p50_us: u64, + p95_us: u64, + p99_us: u64, + per_second: u64, +} + +impl Timing { + fn from_samples(samples: &[u64]) -> Self { + let mut sorted = samples.to_vec(); + sorted.sort_unstable(); + let total: u64 = sorted.iter().sum(); + let ops = sorted.len() as u64; + Self { + ops, + p50_us: nearest_rank(&sorted, 50), + p95_us: nearest_rank(&sorted, 95), + p99_us: nearest_rank(&sorted, 99), + // One operation's own rate: the whole shape's operations against the time they took. + per_second: ops.saturating_mul(1_000_000) / total.max(1), + } + } +} + +/// The percentile the sample list carries: nearest rank over the sorted samples, index +/// `ceil(p/100 * n) - 1` clamped into the list, in whole microseconds. +fn nearest_rank(sorted: &[u64], p: u64) -> u64 { + let len = sorted.len() as u64; + if len == 0 { + return 0; + } + let rank = (p * len).div_ceil(100).saturating_sub(1); + sorted[rank.min(len - 1) as usize] +} + +/// What one measured run leaves behind, before the machine and the store size are added. +struct Run { + event_count_read_back: u64, + shapes: Vec, + timings: BTreeMap<&'static str, Vec>, +} + +/// The artifact, minus `volatile`: everything here is identical between two runs of one command. +struct Report { + backend: String, + seed: u64, + events: u64, + event_count_read_back: u64, + shapes: Vec, + timings: BTreeMap, +} + +/// One failed integrity check, reported as `verify failed: : expected , got `. +struct VerifyFailure { + field: String, + expected: String, + got: String, +} + +impl fmt::Display for VerifyFailure { + fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + let Self { + field, + expected, + got, + } = self; + write!( + formatter, + "verify failed: {field}: expected {expected}, got {got}" + ) + } +} + +/// The `data.mdb` reading, which only the LMDB arm has. +struct StoreSize { + data_bytes: u64, + bytes_per_event: u64, +} + +#[tokio::main] +async fn main() -> ExitCode { + match run().await { + Ok(code) => code, + Err(error) => { + eprintln!("{error}"); + ExitCode::from(2) + } + } +} + +async fn run() -> Fallible { + let arguments = Arguments::parse(); + let plan = Plan::resolve(&arguments)?; + + let (root, _temporary) = match &plan.store { + Store::Given(path) => (path.clone(), None), + Store::Temporary => { + let directory = tempfile::tempdir()?; + let path = directory.path().to_path_buf(); + (path, Some(directory)) + } + }; + + let store: Arc = match plan.backend { + Backend::Lmdb => Arc::new(LmdbBackend::open(&root).await?), + Backend::Postgres => { + let admin_url = plan + .admin_url + .as_deref() + .ok_or_else(|| refusal("--backend postgres needs PARITY_ADMIN_URL"))?; + Arc::new(postgres_backend(admin_url).await?) + } + }; + + let measured = measure(store.as_ref(), plan.events, plan.seed).await?; + + let store_size = match plan.backend { + Backend::Lmdb => { + let data_bytes = std::fs::metadata(store_file(&root))?.len(); + Some(StoreSize { + data_bytes, + bytes_per_event: data_bytes / plan.events, + }) + } + Backend::Postgres => None, + }; + + let report = Report::new(plan.backend, plan.seed, plan.events, measured); + let artifact = report.artifact(volatile_json(&report.timings, store_size.as_ref())); + std::fs::write( + &plan.out, + format!("{}\n", serde_json::to_string_pretty(&artifact)?), + )?; + + if plan.verify { + let failures = verify(&report); + for failure in &failures { + eprintln!("{failure}"); + } + return Ok(ExitCode::from(verify_exit_code(&failures))); + } + + Ok(ExitCode::SUCCESS) +} + +impl Plan { + /// Answers every refusal before a store is opened, so a refused run leaves nothing behind. + fn resolve(arguments: &Arguments) -> Fallible { + if arguments.events < INGEST_EVENTS { + return Err(refusal(format!( + "--events {} is below the minimum of {INGEST_EVENTS}: the ingest phase measures \ + the last {INGEST_EVENTS} events", + arguments.events + ))); + } + + if arguments.events > MAX_CORPUS_EVENTS && !arguments.allow_large_corpus { + return Err(refusal(format!( + "--events {} is above the ceiling of {MAX_CORPUS_EVENTS} events, and the store \ + would be about {} bytes at {BYTES_PER_EVENT_CEILING} bytes per event; pass \ + --allow-large-corpus to measure it anyway", + arguments.events, + arguments.events.saturating_mul(BYTES_PER_EVENT_CEILING) + ))); + } + + if !arguments.allow_busy_host + && let Some(process) = compiling_process() + { + return Err(refusal(format!( + "a compile is running: process {process} is rustc, and a build on this box \ + distorts a measurement about threefold; wait for it to finish or pass \ + --allow-busy-host" + ))); + } + + if arguments.backend == Backend::Postgres && arguments.store.is_some() { + return Err(refusal( + "--store names an LMDB store and is only meaningful with --backend lmdb", + )); + } + + let admin_url = match arguments.backend { + Backend::Postgres => Some(admin_url()?), + Backend::Lmdb => None, + }; + + let store = match &arguments.store { + Some(path) => { + if store_exists(path) { + return Err(refusal(format!( + "--store {} already holds a store: {} exists. Choose another --store or \ + remove it", + path.display(), + store_file(path).display() + ))); + } + Store::Given(path.clone()) + } + None => Store::Temporary, + }; + + Ok(Self { + backend: arguments.backend, + events: arguments.events, + seed: arguments.seed, + out: arguments.out.clone(), + verify: arguments.verify, + store, + admin_url, + }) + } +} + +/// The administrative URL the Postgres arm creates its scratch database through, in the wording +/// `tests/parity.rs` and `tests/migrations.rs` already use. +fn admin_url() -> Fallible { + std::env::var("PARITY_ADMIN_URL").map_err(|_| { + refusal( + "PARITY_ADMIN_URL must name an administrative database, e.g. \ + postgres://postgres:postgres@host:5432/postgres", + ) + }) +} + +/// The id of the first `rustc` in `/proc`, if one is alive: a build beside the measurement holds +/// the cores and distorts the numbers about threefold. `/proc` absent means no compiler to see. +fn compiling_process() -> Option { + for entry in std::fs::read_dir("/proc").ok()?.flatten() { + let Some(process) = entry + .file_name() + .to_str() + .and_then(|name| name.parse::().ok()) + else { + continue; + }; + let comm = std::fs::read_to_string(entry.path().join("comm")).unwrap_or_default(); + if comm.trim() == "rustc" { + return Some(process); + } + } + None +} + +/// Drops the scratch database, creates it again, connects a backend to it and migrates it — the +/// sequence `tests/parity.rs` uses, duplicated here because an `examples/` target cannot import a +/// `tests/` module. +async fn postgres_backend(admin_url: &str) -> Fallible { + let admin = PgPool::connect(admin_url).await?; + admin + .execute(sqlx::AssertSqlSafe(format!( + "DROP DATABASE IF EXISTS {SCRATCH_DATABASE} WITH (FORCE)" + ))) + .await?; + admin + .execute(sqlx::AssertSqlSafe(format!( + "CREATE DATABASE {SCRATCH_DATABASE}" + ))) + .await?; + drop(admin); + + let backend = PostgresBackend::connect(&with_database(admin_url, SCRATCH_DATABASE)).await?; + backend.migrate().await?; + Ok(backend) +} + +/// Replaces the database segment of a URL, keeping scheme, authority and parameters +/// (`tests/parity.rs`'s helper). +fn with_database(url: &str, database: &str) -> String { + let (prefix, query) = match url.split_once('?') { + Some((prefix, query)) => (prefix, Some(query)), + None => (url, None), + }; + let base = match prefix.rfind('/') { + Some(index) if index > "postgres://".len() => &prefix[..index], + _ => prefix, + }; + match query { + Some(query) => format!("{base}/{database}?{query}"), + None => format!("{base}/{database}"), + } +} + +/// Event `index` of the corpus, for seed `seed`: identical input, identical bytes. +fn corpus_event(index: u64, seed: u64) -> Event { + Event { + id: event_id(index, seed), + pubkey: author_pubkey(index % AUTHOR_COUNT, seed), + created_at: CREATED_AT_ANCHOR_UNIX - (index % CREATED_AT_WINDOW_SECS as u64) as i64, + kind: Kind(KIND_CYCLE[(index % KIND_CYCLE.len() as u64) as usize]), + tags: vec![vec![ + "t".to_owned(), + format!("bench-{}", index % TAG_VALUE_COUNT), + ]], + // 64 hex characters of the index, then `x` to CONTENT_LEN: a fixed-width content that is + // never a real note but costs what one costs to store. + content: format!("{index:064x}{}", "x".repeat(CONTENT_LEN - 64)), + // Nothing on the store path verifies a signature (`lmdb/events.rs` writes the record as + // given), and signing would add a dependency to the timed path's build for no measurement. + sig: Signature::from_byte_array([0; 64]), + } +} + +fn event_id(index: u64, seed: u64) -> EventId { + let mut bytes = [0u8; 32]; + bytes[..8].copy_from_slice(&index.to_le_bytes()); + bytes[8..16].copy_from_slice(&seed.to_le_bytes()); + EventId::from_byte_array(bytes) +} + +fn author_pubkey(author: u64, seed: u64) -> Pubkey { + let mut bytes = [0u8; 32]; + bytes[..2].copy_from_slice(&(author as u16).to_le_bytes()); + bytes[2..10].copy_from_slice(&seed.to_le_bytes()); + Pubkey::from_byte_array(bytes) +} + +/// Runs R4's phases in order and records one sample per operation. +async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallible { + let bulk_events = events - INGEST_EVENTS; + let mut timings: BTreeMap<&'static str, Vec> = BTreeMap::new(); + let mut shapes = Vec::new(); + + // 1. Bulk load: the first `events - INGEST_EVENTS` events, one `create_many` per batch. + let mut samples = Vec::new(); + let mut rows = 0; + let mut count = 0; + let mut index = 0; + while index < bulk_events { + let end = (index + WRITE_BATCH as u64).min(bulk_events); + let batch: Vec = (index..end) + .map(|event| EventRecord::from_event(&corpus_event(event, seed))) + .collect(); + let started = Instant::now(); + rows += store.create_many(&batch).await?; + samples.push(elapsed_us(started)); + count += 1; + index = end; + } + timings.insert("create_many", samples); + shapes.push(ShapeCounts { + name: "create_many", + count, + rows, + }); + + // 2. Ingest: the corpus tail, one `create` per call, which is the relay's own write. + let mut samples = Vec::new(); + let mut rows = 0; + for index in bulk_events..events { + let record = EventRecord::from_event(&corpus_event(index, seed)); + let started = Instant::now(); + rows += store.create(&record).await?; + samples.push(elapsed_us(started)); + } + timings.insert("create", samples); + shapes.push(ShapeCounts { + name: "create", + count: INGEST_EVENTS, + rows, + }); + + // 3. Read the whole corpus back once, which is what the unbounded count costs. + let started = Instant::now(); + let event_count_read_back = store.count_by_filters(&[Filter::default()]).await?; + timings.insert("read_back", vec![elapsed_us(started)]); + + // 4. The five read shapes, every target and window derived from the iteration and the seed. + let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { + let target = (seed * BY_ID_STRIDE + iteration * BY_ID_STRIDE + BY_ID_OFFSET) % events; + vec![Filter { + ids: Some(vec![event_id(target, seed).to_string()]), + limit: Some(BY_ID_LIMIT), + ..Filter::default() + }] + }) + .await?; + timings.insert("by_id", samples); + shapes.push(ShapeCounts { + name: "by_id", + count, + rows, + }); + + let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { + vec![Filter { + authors: Some(vec![ + author_pubkey(iteration % AUTHOR_COUNT, seed).to_string(), + ]), + kinds: Some(vec![Kind::TEXT_NOTE]), + limit: Some(AUTHOR_KIND_LIMIT), + ..Filter::default() + }] + }) + .await?; + timings.insert("author_kind", samples); + shapes.push(ShapeCounts { + name: "author_kind", + count, + rows, + }); + + let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { + let since = CREATED_AT_ANCHOR_UNIX - CREATED_AT_WINDOW_SECS + + (iteration as i64) * CREATED_AT_WINDOW_SECS / READ_ITERATIONS as i64; + vec![Filter { + kinds: Some(vec![Kind::TEXT_NOTE]), + since: Some(since), + limit: Some(KIND_SINCE_LIMIT), + ..Filter::default() + }] + }) + .await?; + timings.insert("kind_since", samples); + shapes.push(ShapeCounts { + name: "kind_since", + count, + rows, + }); + + let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { + let tag_index = iteration % TAG_VALUE_COUNT; + let mut tags = BTreeMap::new(); + tags.insert("#t".to_owned(), vec![format!("bench-{tag_index}")]); + vec![Filter { + tags, + limit: Some(TAG_LIMIT), + ..Filter::default() + }] + }) + .await?; + timings.insert("tag", samples); + shapes.push(ShapeCounts { + name: "tag", + count, + rows, + }); + + let mut samples = Vec::new(); + let mut rows = 0; + for iteration in 0..COUNT_ITERATIONS { + let until = CREATED_AT_ANCHOR_UNIX + - (iteration as i64) * CREATED_AT_WINDOW_SECS / COUNT_ITERATIONS as i64; + let filters = [Filter { + kinds: Some(vec![Kind::TEXT_NOTE]), + until: Some(until), + ..Filter::default() + }]; + let started = Instant::now(); + rows += store.count_by_filters(&filters).await?; + samples.push(elapsed_us(started)); + } + timings.insert("count", samples); + shapes.push(ShapeCounts { + name: "count", + count: COUNT_ITERATIONS, + rows, + }); + + Ok(Run { + event_count_read_back, + shapes, + timings, + }) +} + +/// One filter read shape: `iterations` calls, each page drained to rows so the sample covers the +/// whole read. Returns the operations issued, the rows drained and one sample per call. +async fn read_shape( + store: &dyn EventRepository, + iterations: u64, + filters: impl Fn(u64) -> Vec, +) -> Fallible<(u64, u64, Vec)> { + let mut samples = Vec::with_capacity(iterations as usize); + let mut rows = 0; + for iteration in 0..iterations { + let filters = filters(iteration); + let started = Instant::now(); + let records = collect_records(store.find_by_filters(&filters).await?).await?; + samples.push(elapsed_us(started)); + rows += records.len() as u64; + } + Ok((iterations, rows, samples)) +} + +fn elapsed_us(started: Instant) -> u64 { + u64::try_from(started.elapsed().as_micros()).unwrap_or(u64::MAX) +} + +impl Report { + fn new(backend: Backend, seed: u64, events: u64, run: Run) -> Self { + let timings = run + .timings + .into_iter() + .map(|(name, samples)| (name.to_owned(), Timing::from_samples(&samples))) + .collect(); + Self { + backend: backend.name().to_owned(), + seed, + events, + event_count_read_back: run.event_count_read_back, + shapes: run.shapes, + timings, + } + } + + fn artifact(&self, volatile: Value) -> Value { + let shapes: Vec = self + .shapes + .iter() + .map(|shape| { + json!({ + "shape": shape.name, + "count": shape.count, + "rows": shape.rows, + }) + }) + .collect(); + json!({ + "backend": self.backend, + "seed": self.seed, + "events": self.events, + "event_count_read_back": self.event_count_read_back, + "workload": workload_json(), + "shapes": shapes, + "volatile": volatile, + }) + } +} + +/// The workload the run measured, echoed so the artifact carries its own definition. +fn workload_json() -> Value { + json!({ + "corpus": { + "authors": AUTHOR_COUNT, + "kind_cycle": KIND_CYCLE, + "content_len": CONTENT_LEN, + "tag_value_count": TAG_VALUE_COUNT, + "created_at_anchor_unix": CREATED_AT_ANCHOR_UNIX, + "created_at_window_secs": CREATED_AT_WINDOW_SECS, + }, + "writes": { + "create_many_batch": WRITE_BATCH, + "ingest_events": INGEST_EVENTS, + }, + "reads": { + "iterations": READ_ITERATIONS, + "counts": COUNT_ITERATIONS, + "limits": { + "by_id": BY_ID_LIMIT, + "author_kind": AUTHOR_KIND_LIMIT, + "kind_since": KIND_SINCE_LIMIT, + "tag": TAG_LIMIT, + }, + }, + "concurrency": 1, + }) +} + +/// Everything that can differ between two runs: the host, the store's size and the timings. +fn volatile_json(timings: &BTreeMap, store: Option<&StoreSize>) -> Value { + let mut entries = Map::new(); + for (name, timing) in timings { + entries.insert( + name.clone(), + json!({ + "ops": timing.ops, + "p50_us": timing.p50_us, + "p95_us": timing.p95_us, + "p99_us": timing.p99_us, + "per_second": timing.per_second, + }), + ); + } + json!({ + "machine": { + "cpu_count": cpu_count(), + "cpu_model": cpu_model(), + "os": std::env::consts::OS, + "arch": std::env::consts::ARCH, + "profile": if cfg!(debug_assertions) { "debug" } else { "release" }, + "load_1min": load_1min(), + }, + "store": match store { + Some(size) => json!({ + "data_bytes": size.data_bytes, + "bytes_per_event": size.bytes_per_event, + }), + None => json!({ + "data_bytes": Value::Null, + "bytes_per_event": Value::Null, + }), + }, + "timings": entries, + }) +} + +fn cpu_count() -> u64 { + std::thread::available_parallelism() + .map(|count| count.get() as u64) + .unwrap_or(0) +} + +/// `/proc/cpuinfo`'s `model name`, absent where `/proc` is. +fn cpu_model() -> Option { + let info = std::fs::read_to_string("/proc/cpuinfo").ok()?; + info.lines().find_map(|line| { + let rest = line.strip_prefix("model name")?; + let (_, value) = rest.split_once(':')?; + Some(value.trim().to_owned()) + }) +} + +/// `/proc/loadavg`'s one-minute figure, absent where `/proc` is. +fn load_1min() -> Option { + let load = std::fs::read_to_string("/proc/loadavg").ok()?; + load.split_whitespace().next()?.parse().ok() +} + +/// Every integrity check `--verify` makes; an empty list means the run recorded what it asked for. +fn verify(report: &Report) -> Vec { + let mut failures = Vec::new(); + let mut check = |field: String, expected: u64, got: u64| { + if expected != got { + failures.push(VerifyFailure { + field, + expected: expected.to_string(), + got: got.to_string(), + }); + } + }; + + check( + "event_count_read_back".to_owned(), + report.events, + report.event_count_read_back, + ); + + let bulk_events = report.events - INGEST_EVENTS; + let create_many = shape(report, "create_many"); + let create = shape(report, "create"); + + check( + "shapes[create_many].rows + shapes[create].rows".to_owned(), + report.events, + create_many.rows + create.rows, + ); + check("shapes[create].rows".to_owned(), create.count, create.rows); + // R6's `create_many.rows == count * create_many_batch` is this: every call wrote the batch it + // was given. A bulk load that is not a whole number of batches ends in a short one, so the + // expected total is the bulk event count, which is `count * batch` whenever it divides. + check( + "shapes[create_many].rows".to_owned(), + bulk_events, + create_many.rows, + ); + check( + "shapes[create_many].count".to_owned(), + bulk_events.div_ceil(WRITE_BATCH as u64), + create_many.count, + ); + + for (name, iterations) in [ + ("by_id", READ_ITERATIONS), + ("author_kind", READ_ITERATIONS), + ("kind_since", READ_ITERATIONS), + ("tag", READ_ITERATIONS), + ("count", COUNT_ITERATIONS), + ] { + let measured = shape(report, name); + check(format!("shapes[{name}].count"), iterations, measured.count); + } + + for measured in &report.shapes { + if measured.rows == 0 { + failures.push(VerifyFailure { + field: format!("shapes[{}].rows", measured.name), + expected: "> 0".to_owned(), + got: measured.rows.to_string(), + }); + } + } + + for (name, timing) in &report.timings { + let ordered = timing.p99_us >= timing.p95_us && timing.p95_us >= timing.p50_us; + if !ordered { + failures.push(VerifyFailure { + field: format!("volatile.timings[{name}]"), + expected: "p99_us >= p95_us >= p50_us".to_owned(), + got: format!( + "{} >= {} >= {}", + timing.p99_us, timing.p95_us, timing.p50_us + ), + }); + } + } + + failures +} + +fn shape(report: &Report, name: &str) -> ShapeCounts { + report + .shapes + .iter() + .find(|shape| shape.name == name) + .copied() + .unwrap_or(ShapeCounts { + name: "", + count: 0, + rows: 0, + }) +} + +/// A verify failure is exit 1; a run that verifies is exit 0. +fn verify_exit_code(failures: &[VerifyFailure]) -> u8 { + if failures.is_empty() { 0 } else { 1 } +} + +#[cfg(test)] +#[allow(clippy::unwrap_used, clippy::expect_used, clippy::panic)] +mod tests { + use super::*; + + fn valid_report() -> Report { + let mut timings = BTreeMap::new(); + for name in [ + "create_many", + "create", + "by_id", + "author_kind", + "kind_since", + "tag", + "count", + "read_back", + ] { + timings.insert( + name.to_owned(), + Timing { + ops: 10, + p50_us: 10, + p95_us: 20, + p99_us: 30, + per_second: 1_000, + }, + ); + } + Report { + backend: "lmdb".to_owned(), + seed: DEFAULT_SEED, + events: 50_000, + event_count_read_back: 50_000, + shapes: vec![ + ShapeCounts { + name: "create_many", + count: 98, + rows: 49_000, + }, + ShapeCounts { + name: "create", + count: 1_000, + rows: 1_000, + }, + ShapeCounts { + name: "by_id", + count: READ_ITERATIONS, + rows: 200, + }, + ShapeCounts { + name: "author_kind", + count: READ_ITERATIONS, + rows: 20_000, + }, + ShapeCounts { + name: "kind_since", + count: READ_ITERATIONS, + rows: 50_000, + }, + ShapeCounts { + name: "tag", + count: READ_ITERATIONS, + rows: 20_000, + }, + ShapeCounts { + name: "count", + count: COUNT_ITERATIONS, + rows: 1_000_000, + }, + ], + timings, + } + } + + #[test] + fn a_consistent_report_verifies() { + let failures = verify(&valid_report()); + assert!(failures.is_empty(), "{} failures", failures.len()); + } + + #[test] + fn percentiles_use_nearest_rank() { + let samples: Vec = (1..=200).collect(); + let timing = Timing::from_samples(&samples); + assert_eq!(timing.p50_us, 100); + assert_eq!(timing.p95_us, 190); + assert_eq!(timing.p99_us, 198); + assert_eq!(timing.ops, 200); + assert_eq!(timing.per_second, 200 * 1_000_000 / 20_100); + } + + #[test] + fn corpus_is_identical_for_a_seed() { + let first: Vec = (0..1_000).map(|index| corpus_event(index, 7)).collect(); + let second: Vec = (0..1_000).map(|index| corpus_event(index, 7)).collect(); + assert_eq!(first, second); + + let left = serde_json::to_string(&first).unwrap(); + let right = serde_json::to_string(&second).unwrap(); + assert_eq!(left, right); + + let ids: std::collections::BTreeSet<_> = first.iter().map(|event| event.id).collect(); + assert_eq!(ids.len(), first.len(), "the corpus ids are distinct"); + } + + #[test] + fn a_different_seed_changes_the_corpus() { + assert_ne!(corpus_event(0, 7).id, corpus_event(0, 8).id); + assert_ne!(corpus_event(0, 7).pubkey, corpus_event(0, 8).pubkey); + } + + #[test] + fn verify_rejects_a_short_read_back() { + let mut report = valid_report(); + report.event_count_read_back = 49_999; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "event_count_read_back"); + assert_eq!(failures[0].expected, "50000"); + assert_eq!(failures[0].got, "49999"); + assert_eq!( + failures[0].to_string(), + "verify failed: event_count_read_back: expected 50000, got 49999" + ); + } + + #[test] + fn verify_rejects_a_p95_below_p50() { + let mut report = valid_report(); + let timing = report.timings.get_mut("by_id").expect("a by_id timing"); + timing.p50_us = 500; + timing.p95_us = 400; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "volatile.timings[by_id]"); + } + + #[test] + fn verify_rejects_a_shape_with_no_rows() { + let mut report = valid_report(); + let shape = report + .shapes + .iter_mut() + .find(|shape| shape.name == "tag") + .expect("a tag shape"); + shape.rows = 0; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "shapes[tag].rows"); + assert_eq!(failures[0].expected, "> 0"); + assert_eq!(failures[0].got, "0"); + } + + #[test] + fn a_verify_failure_exits_one() { + let mut report = valid_report(); + report.event_count_read_back = 0; + let failures = verify(&report); + assert_eq!(verify_exit_code(&failures), 1); + assert_eq!(verify_exit_code(&verify(&valid_report())), 0); + } + + #[test] + fn the_corpus_uses_only_kinds_in_the_cycle() { + for index in 0..10_000 { + let event = corpus_event(index, 7); + assert!( + KIND_CYCLE.contains(&event.kind.0), + "event {index} has kind {}", + event.kind + ); + } + } + + #[test] + fn the_corpus_content_is_the_configured_length() { + for index in 0..10_000 { + let event = corpus_event(index, 7); + assert_eq!( + event.content.len(), + CONTENT_LEN, + "event {index} has {} bytes of content", + event.content.len() + ); + assert_eq!(event.tags.len(), 1); + assert_eq!(event.tags[0][0], "t"); + } + } +} From c3acc1394768d03b7d135a2e3717718b8749ff23 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Fri, 13 Nov 2026 23:59:00 -0500 Subject: [PATCH 02/14] docs: record the benchmark rig's LMDB run and amend ADR 0012 --- docs/rewrite/benchmarks.md | 178 ++++++++++++++++++ docs/rewrite/benchmarks/lmdb-50k-seed7.json | 151 +++++++++++++++ .../decisions/0012-pg-to-lmdb-migration.md | 5 +- 3 files changed, 332 insertions(+), 2 deletions(-) create mode 100644 docs/rewrite/benchmarks.md create mode 100644 docs/rewrite/benchmarks/lmdb-50k-seed7.json diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md new file mode 100644 index 000000000..1af9ccd32 --- /dev/null +++ b/docs/rewrite/benchmarks.md @@ -0,0 +1,178 @@ +# Benchmarks: the LMDB store on the rig's workload + +The numbers in this document come from one command on one host, and from the artifact that +command wrote, which is committed beside this document: + +`docs/rewrite/benchmarks/lmdb-50k-seed7.json` + +Nothing else is cited. The rig is `crates/nostream-storage/examples/bench.rs`: one workload, +held as named constants in that file and echoed into the artifact's `workload` object, run +through `Arc` so the same call sites measure either backend. + +Two columns are deliberately absent, and the sections below say why: the Rust/Postgres column, +which needs a database this host does not have, and the TypeScript/Postgres column, which is +#1132's job. Neither carries a figure here. + +## The recorded run + +| | | +|---|---| +| Date | 2026-11-13 | +| Machine | 4 CPUs, `Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz` | +| Load average, one minute | 43.34 | +| Free disk at run time | 19 GB (`df -h /`) | +| Profile | `release` | +| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --verify --out /tmp/bench-lmdb-1.json` | +| Artifact | `docs/rewrite/benchmarks/lmdb-50k-seed7.json` | + +The machine, the load average and the store's size are `volatile.machine` and `volatile.store` +in that artifact. The load figure matters: this host is shared, and two runs of the same command +have differed by several times on the write shapes, whose cost is LMDB's synchronous commit. + +## The LMDB numbers + +One row per shape, from the artifact's `shapes` and `volatile.timings`. + +| shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | per_second | +|---|---|---|---|---|---|---| +| `create_many` | 98 | 49000 | 27.3 | 39.5 | 48.5 | 35 | +| `create` | 1000 | 1000 | 3.9 | 4.7 | 5.4 | 254 | +| `by_id` | 200 | 200 | 0.0 | 0.0 | 0.1 | 46674 | +| `author_kind` | 200 | 16000 | 0.3 | 0.4 | 0.6 | 3610 | +| `kind_since` | 200 | 100000 | 1.5 | 1.7 | 2.3 | 663 | +| `tag` | 200 | 20000 | 0.3 | 0.3 | 0.4 | 3594 | +| `count` | 50 | 40000 | 0.0 | 0.0 | 18.4 | 2654 | +| `read_back` | 1 | 50000 | 19.2 | 19.2 | 19.2 | 52 | + +The `count` and `rows` columns are the artifact's integers printed as-is (rule a), and so is +`per_second`; the three percentile columns are the artifact's microsecond integers printed in +milliseconds with exactly one decimal, half-up (rule b). `read_back` carries no `shapes` entry: +it is the single unbounded count the corpus is read back with, and its `rows` is +`event_count_read_back`. + +| events | data_bytes | bytes_per_event | +|---|---|---| +| 50000 | 94191616 | 1883.8 | + +`events` and `data_bytes` are the artifact's integers as-is (rule a); `bytes_per_event` is +`data_bytes / events` rounded to one decimal (rule c), which is why it is not the artifact's own +truncated integer. + +The percentiles are nearest-rank over the per-call samples, so `p50` of a shape with one +operation is that operation. `per_second` is the shape's operations against the time they took. + +## The workload + +### D1 The corpus + +Generated, not loaded: event `i` of `N` at seed `s` has an id of `i` and `s` little-endian in +its first bytes, an author of `i % 200` over 200 authors, a kind from the cycle +`[1,1,1,1,1,1,1,1,7,7]`, `created_at = 1700000000 - (i % 2592000)`, a 256-byte content of the +index in hex then `x`, and one tag `["t", "bench-{i % 20}"]` over 20 values. The run recorded +here used seed 7. Identical input produces identical bytes, which is what makes two runs +comparable: the second run's artifact, with `volatile` removed, is identical to this one. The +signature is zero bytes, because nothing on the store path verifies one. + +### D2 The two write shapes + +`create_many` is corpus loading: the first 49000 events, 500 per call, one commit per batch. +`create` is ingest: the last 1000 events, one call per event, and it is the shape the relay +itself uses — `crates/nostream-relay/src/strategies/default.rs:36` is +`context.stores.events.create(&record)`. A rig that loaded the corpus with `create_many` and +called that ingest would measure an API the relay never calls, which is why the two are separate +rows and only `create` speaks for ingest. + +### D3 The five read shapes, and the access path each reaches + +Each shape is one filter through `find_by_filters`, drained to rows with `collect_records`, so +the measurement covers the whole page and not just its first batch. The LMDB planner picks the +path in `crates/nostream-storage/src/lmdb/events.rs`: + +- `by_id` — `ids`, limit 1: the `events` key is the id, so the range runs in id order + (`events.rs:1303-1316`). +- `author_kind` — one author and kind 1, limit 100: the author × kind index + (`events.rs:1317-1334`, ranges built by `author_kind_ranges`). +- `kind_since` — kind 1 from a moving `since`, limit 500: the created-at index + (`events.rs:1345-1351`). +- `tag` — one `["t", …]` value, limit 100: the tags index (`events.rs:1353-1362`). +- `count` — kind 1 to a moving `until`, no limit: `count_by_filters`, which reads only the fixed + header of each candidate (`docs/rewrite/decisions/0011-lmdb-backend.md:61-73`) and therefore + scales with the number of matches rather than with the page. + +`count` is the shape that shows the difference: its median is a fraction of a millisecond while +its tail is the width of the corpus, because the first iterations count every kind-1 event. + +### D4 Concurrency, warm-up, and what a timing is + +Concurrency is 1: one writer and one reader, no concurrent load, no background traffic. There +is no warm-up pass and the first iteration counts, so the figures include the cost a cold page +cache adds. A timing is the repository call alone — one `create`, one `create_many` batch, one +filter query, one count — measured around the await at the call site, with the corpus generation +outside it. Nothing here is a socket round trip: the wire is out of scope. + +The write shapes measure LMDB's synchronous commit, since the environment is opened with default +flags (`crates/nostream-storage/src/backend.rs`). On this shared host they vary between runs of +one command by several times; the figures above are one recorded run, not a bound, and a reader +comparing two hosts should compare the read shapes first. + +### D5 The corpora measured, and the ones that were not + +Measured here: 50000 events, seed 7, on the store the harness creates under a temporary +directory. The harness's default ceiling is what keeps a mistyped corpus from filling a disk: a +run above it is refused before the store is touched, with the projected store size printed in +bytes and `--allow-large-corpus` named as the override. + +The gate's 1M and 10M corpora (#868) were not measured here: this host had 19 GB free at run +time, and the store's own measurement projects: + +projection: 1M events (#868) x 1883.8 bytes/event = 1883800000 bytes +projection: 10M events (#868) x 1883.8 bytes/event = 18838000000 bytes + +Both are projections from this run's bytes per event, not measurements, and the 1M run alone +(#868) would need the `--allow-large-corpus` override on a host with room for it. + +### D6 The Rust/Postgres column: not measured in this environment + +The second Rust backend is the same `EventRepository` over the same workload, run with +`--backend postgres`. It is not measured in this environment: the measuring host has no Docker +daemon, no `psql` and no Postgres server, so the harness refuses the run rather than skipping it +(`PARITY_ADMIN_URL must name an administrative database, …`). + +CI reaches it, because CI's `Rust Checks` job already runs a Postgres service. The step is named +`Benchmark harness against Postgres` in `.github/workflows/checks.yml`, and it runs the same +binary and the same `--verify` in the dev profile; its timings are cited nowhere. On a host with +Postgres the number comes from: + +``` +PARITY_ADMIN_URL=postgres://postgres:postgres@host:5432/postgres \ + cargo run --release -p nostream-storage --example bench -- \ + --backend postgres --events 50000 --seed 7 --verify --out /tmp/bench-postgres.json +``` + +The Postgres arm drops and recreates the scratch database `nostream_bench_rust` on the server +that URL names, so it belongs only where that name is expendable. + +### D7 The TypeScript/Postgres column: not measured + +The baseline implementation is `src/` on `main`, and this branch's `src/` is not it: the tree has +already lost the modules the Rust crates replaced, so a run from this worktree would measure +neither implementation. This host also has no `node_modules` and no Docker, so neither the relay +nor the Postgres it needs can be started here. That column, and the side-by-side comparison the +gate reads, is filed as #1132 and must be run from a checkout of `origin/main` on a host with a +Docker daemon. + +### D8 No threshold is asserted + +This document carries evidence, not a pass/fail. The gate is #868: REQ p95 within 1.5× of the +Postgres implementation and ingest ≥ 1×, at the 1M and 10M corpora (#868). The board's +50 000 events/s figure is a target tracked in #864, not a measurement, and nothing here is +compared with it. No ratio, floor or comparison against another backend appears in this +document. + +## Context from job 007, not this rig's numbers + +ADR 0003 records the Postgres figures one review session measured +(`docs/rewrite/decisions/0003-storage-seam-and-postgres.md:219-233`): `count_by_filters` 267.6 ms, +a multi-value `#p` `EXISTS` 44.9 ms, and `claim_batch` 12.2 ms. They are context from job 007's +review and the provenance it names; they are not this rig's output, they were not re-measured +for this document, and no table above cites them. diff --git a/docs/rewrite/benchmarks/lmdb-50k-seed7.json b/docs/rewrite/benchmarks/lmdb-50k-seed7.json new file mode 100644 index 000000000..f54ec343c --- /dev/null +++ b/docs/rewrite/benchmarks/lmdb-50k-seed7.json @@ -0,0 +1,151 @@ +{ + "backend": "lmdb", + "event_count_read_back": 50000, + "events": 50000, + "seed": 7, + "shapes": [ + { + "count": 98, + "rows": 49000, + "shape": "create_many" + }, + { + "count": 1000, + "rows": 1000, + "shape": "create" + }, + { + "count": 200, + "rows": 200, + "shape": "by_id" + }, + { + "count": 200, + "rows": 16000, + "shape": "author_kind" + }, + { + "count": 200, + "rows": 100000, + "shape": "kind_since" + }, + { + "count": 200, + "rows": 20000, + "shape": "tag" + }, + { + "count": 50, + "rows": 40000, + "shape": "count" + } + ], + "volatile": { + "machine": { + "arch": "x86_64", + "cpu_count": 4, + "cpu_model": "Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz", + "load_1min": 43.34, + "os": "linux", + "profile": "release" + }, + "store": { + "bytes_per_event": 1883, + "data_bytes": 94191616 + }, + "timings": { + "author_kind": { + "ops": 200, + "p50_us": 320, + "p95_us": 435, + "p99_us": 552, + "per_second": 3610 + }, + "by_id": { + "ops": 200, + "p50_us": 20, + "p95_us": 23, + "p99_us": 71, + "per_second": 46674 + }, + "count": { + "ops": 50, + "p50_us": 7, + "p95_us": 12, + "p99_us": 18426, + "per_second": 2654 + }, + "create": { + "ops": 1000, + "p50_us": 3923, + "p95_us": 4686, + "p99_us": 5419, + "per_second": 254 + }, + "create_many": { + "ops": 98, + "p50_us": 27293, + "p95_us": 39467, + "p99_us": 48502, + "per_second": 35 + }, + "kind_since": { + "ops": 200, + "p50_us": 1481, + "p95_us": 1697, + "p99_us": 2312, + "per_second": 663 + }, + "read_back": { + "ops": 1, + "p50_us": 19174, + "p95_us": 19174, + "p99_us": 19174, + "per_second": 52 + }, + "tag": { + "ops": 200, + "p50_us": 272, + "p95_us": 335, + "p99_us": 426, + "per_second": 3594 + } + } + }, + "workload": { + "concurrency": 1, + "corpus": { + "authors": 200, + "content_len": 256, + "created_at_anchor_unix": 1700000000, + "created_at_window_secs": 2592000, + "kind_cycle": [ + 1, + 1, + 1, + 1, + 1, + 1, + 1, + 1, + 7, + 7 + ], + "tag_value_count": 20 + }, + "reads": { + "counts": 50, + "iterations": 200, + "limits": { + "author_kind": 100, + "by_id": 1, + "kind_since": 500, + "tag": 100 + } + }, + "writes": { + "create_many_batch": 500, + "ingest_events": 1000 + } + } +} diff --git a/docs/rewrite/decisions/0012-pg-to-lmdb-migration.md b/docs/rewrite/decisions/0012-pg-to-lmdb-migration.md index c14e19ad9..aece0b436 100644 --- a/docs/rewrite/decisions/0012-pg-to-lmdb-migration.md +++ b/docs/rewrite/decisions/0012-pg-to-lmdb-migration.md @@ -220,8 +220,9 @@ the `events` table only. Both numbers are plain digits so a reader can recompute exactly, and the rate comes from the same integers that were printed. **No floor is asserted.** The board's 50 000 events/s target belongs to the benchmark rig, -which does not exist; a CI runner's rate is not that number, so this tool reports what it -measured and claims nothing about it. +~~which does not exist~~ (landed as #1131; measured numbers in docs/rewrite/benchmarks.md); a CI +runner's rate is not that number, so this tool reports what it measured and claims nothing about +it. ## The relay must be stopped (D9) From 84f81d26a59f67b7e8aa32a5eb4ea97dc401d337 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 00:38:39 -0500 Subject: [PATCH 03/14] fix(bench): size the read windows from the corpus, assert exact totals and repeat the phases --- .github/workflows/checks.yml | 4 + CLAUDE.md | 23 +- crates/nostream-storage/examples/bench.rs | 1142 ++++++++++++++++----- 3 files changed, 919 insertions(+), 250 deletions(-) diff --git a/.github/workflows/checks.yml b/.github/workflows/checks.yml index 8244f0e7a..e85d3178a 100644 --- a/.github/workflows/checks.yml +++ b/.github/workflows/checks.yml @@ -286,6 +286,10 @@ jobs: env: PARITY_ADMIN_URL: postgres://postgres:postgres@localhost:5432/postgres run: cargo run -p nostream-storage --example bench -- --backend postgres --events 2000 --seed 7 --verify --out /tmp/bench-postgres.json + # `cargo test --workspace` builds an example target and never runs its tests, so the rig's + # own tests need a command that does. They carry the rules `--verify` asserts. + - name: Benchmark harness unit tests + run: cargo test -p nostream-storage --all-features --example bench - name: Storage builds without the Postgres driver run: cargo check -p nostream-storage --no-default-features --all-targets - name: Release build diff --git a/CLAUDE.md b/CLAUDE.md index de773bfa8..722f88561 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -36,9 +36,9 @@ cargo test --workspace --all-features cargo build --workspace --all-features --release ``` -CI additionally runs the three database-backed storage tests ("Storage parity against Postgres") -against a `postgres:16-alpine` service, and they are `#[ignore]`d so a checkout without a database still passes -`cargo test --workspace`: +CI additionally runs four database- and example-backed checks. Three are the storage tests +("Storage parity against Postgres"), against a `postgres:16-alpine` service; they are `#[ignore]`d +so a checkout without a database still passes `cargo test --workspace`: ``` cargo test -p nostream-storage --test migrations --test parity --test migration_pg \ @@ -48,8 +48,21 @@ cargo test -p nostream-storage --test migrations --test parity --test migration_ `PARITY_ADMIN_URL` names the administrative database (CI sets `postgres://postgres:postgres@localhost:5432/postgres`); the targets create, migrate and drop their own scratch databases — `migration_pg` seeds one and copies it into a temporary LMDB -store. `scripts/storage-parity.sh` runs all three plus the -TypeScript Cucumber suite against the sqlx-migrated schema — the complete local oracle. The +store. The fourth is the benchmark rig's Postgres arm ("Benchmark harness against Postgres"): +it runs `crates/nostream-storage/examples/bench.rs` against a scratch database and proves the path +and `--verify`, and its numbers are cited nowhere. + +The rig's own unit tests need their own command, because `cargo test --workspace` only *builds* an +example target. CI runs it as "Benchmark harness unit tests", and so must you when you touch the +rig: + +``` +cargo test -p nostream-storage --all-features --example bench +``` + +`scripts/storage-parity.sh` runs the three storage targets plus the +TypeScript Cucumber suite against the sqlx-migrated schema — the local parity oracle. It does not +run the benchmark rig, which is a measurement and not a parity check. The LMDB arm of that oracle needs no database: `cargo test -p nostream-storage --test parity_lmdb -- --nocapture` replays the same fixture on a temporary store and runs inside the fifth validation command above. diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs index 21061bff2..6ac2a4e2d 100644 --- a/crates/nostream-storage/examples/bench.rs +++ b/crates/nostream-storage/examples/bench.rs @@ -6,12 +6,13 @@ //! //! ```text //! cargo run --release -p nostream-storage --example bench -- \ -//! --backend lmdb --events 50000 --seed 7 --out /tmp/bench.json --verify +//! --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench.json //! ``` //! -//! Timings are never asserted and counts always are: `--verify` checks that the artifact records -//! the corpus it was asked for, so a run that measured a partial corpus, a filter that matched -//! nothing or a page that stopped early fails, while a slow host only makes the numbers large. +//! Timings are never asserted and counts always are: `--verify` compares every count the +//! artifact records against what the corpus says the workload must produce, so a run that +//! measured a partial corpus, a filter that matched nothing, a page that stopped early or a +//! window that slid off the corpus fails, while a slow host only makes the numbers large. //! Everything that can differ between two runs of one command sits under the single `volatile` //! key, which is what makes two runs comparable as `jq -S 'del(.volatile)'`. @@ -33,15 +34,18 @@ use serde_json::{Map, Value, json}; use sqlx::Executor; use sqlx::postgres::PgPool; -/// The corpus holds this many authors (`j = index % AUTHOR_COUNT`). +/// The corpus holds this many authors (`author = index % AUTHOR_COUNT`). const AUTHOR_COUNT: u64 = 200; -/// The kind each corpus event takes, in order: `KIND_CYCLE[index % KIND_CYCLE.len()]`. +/// The kind each corpus event takes, in order: `KIND_CYCLE[cycle_position(index)]`. /// /// Replaceable kinds are absent on purpose: the relay writes kind 3 with `upsert` /// (`strategies/contact_list.rs`), which is a different path from the `create` this measures. const KIND_CYCLE: [u64; 10] = [1, 1, 1, 1, 1, 1, 1, 1, 7, 7]; +/// The kind the read shapes filter on, and the majority of the corpus. +const TEXT_NOTE: u64 = 1; + /// The corpus content's length in bytes: 64 hex characters of the index, then `x`. const CONTENT_LEN: usize = 256; @@ -51,7 +55,8 @@ const TAG_VALUE_COUNT: u64 = 20; /// The newest `created_at` any corpus event carries. const CREATED_AT_ANCHOR_UNIX: i64 = 1_700_000_000; -/// The `created_at` spread below the anchor, and the window every read walks. +/// The `created_at` spread the corpus wraps around, and the bound every read window is derived +/// from. const CREATED_AT_WINDOW_SECS: i64 = 2_592_000; /// Events per `create_many` call: corpus loading, not ingest. @@ -72,9 +77,13 @@ const AUTHOR_KIND_LIMIT: u64 = 100; const KIND_SINCE_LIMIT: u64 = 500; const TAG_LIMIT: u64 = 100; +/// How many times the measured phases run in one invocation: the artifact carries the spread +/// across repeats, which is the only way a reader can tell a measurement from a lucky one. +const DEFAULT_REPEATS: u64 = 1; + /// The corpus ceiling a run may not cross without `--allow-large-corpus`. A 1M-event corpus is -/// about 1.4 GB of `data.mdb`, so the default refusal is what keeps a mistyped `--events` from -/// filling a measuring host's disk. +/// about 1.9 GB of `data.mdb` at the rate this rig measures, so the default refusal is what +/// keeps a mistyped `--events` from filling a measuring host's disk. const MAX_CORPUS_EVENTS: u64 = 200_000; /// The per-event disk projection the large-corpus refusal prints: twice the worst measured @@ -90,6 +99,17 @@ const DEFAULT_SEED: u64 = 7; const BY_ID_STRIDE: u64 = 7_919; const BY_ID_OFFSET: u64 = 13; +/// The shapes the artifact records, in the order it records them. +const SHAPES: [&str; 7] = [ + "create_many", + "create", + "by_id", + "author_kind", + "kind_since", + "tag", + "count", +]; + #[derive(Clone, Copy, PartialEq, Eq, ValueEnum)] enum Backend { /// The embedded LMDB store, opened under `--store`. @@ -111,16 +131,23 @@ impl Backend { #[derive(Parser)] #[command( about = "Measures one deterministic workload against the LMDB store or a scratch Postgres database", - after_help = "The Postgres arm drops and recreates the scratch database named above on the server \ - PARITY_ADMIN_URL points at, so run it only where that name is expendable. \ - --store is refused with --backend postgres: the data lives in Postgres." + after_help = "Exit codes: 0 the run completed, and with --verify every check passed; \ + 1 a verify failure, one `verify failed: : expected , got ` line per \ + failed check, with the artifact written either way; 2 a usage error, a refusal, \ + or a failure that stopped the run.\n\n\ + --repeats N runs the measured phases N times, each against a fresh store (a \ + --store directory gets one repeat- subdirectory per run), and the artifact \ + carries the spread across the repeats. The Postgres arm drops and recreates the \ + scratch database named above on the server PARITY_ADMIN_URL points at, so run it \ + only where that name is expendable." )] struct Arguments { /// The store to measure. #[arg(long, value_enum)] backend: Backend, - /// The corpus size; the ingest phase takes the last 1000 events of it. + /// The corpus size: at least 1000, and at most 200000 without --allow-large-corpus. The + /// ingest phase takes the last 1000 events of it. #[arg(long)] events: u64, @@ -128,15 +155,21 @@ struct Arguments { #[arg(long, default_value_t = DEFAULT_SEED)] seed: u64, - /// Where the JSON artifact is written. + /// How many times to run the measured phases; above 1 the artifact carries the spread. + #[arg(long, default_value_t = DEFAULT_REPEATS)] + repeats: u64, + + /// Where the JSON artifact is written; its directory must exist. #[arg(long)] out: PathBuf, - /// Check that the artifact records the corpus it was asked for. + /// Check that the artifact records the corpus it was asked for. The artifact is written + /// whether or not the check passes. #[arg(long)] verify: bool, - /// The store root for --backend lmdb; a fresh temporary directory when absent. + /// The store root for --backend lmdb; it must not already hold a store, and a fresh + /// temporary directory is used when absent. #[arg(long)] store: Option, @@ -160,6 +193,7 @@ struct Plan { backend: Backend, events: u64, seed: u64, + repeats: u64, out: PathBuf, verify: bool, store: Store, @@ -185,25 +219,32 @@ fn refusal(message: impl Into) -> Box { } /// One shape's row accounting: how many operations were issued and what they returned. -#[derive(Clone, Copy)] +#[derive(Clone, Copy, PartialEq, Eq)] struct ShapeCounts { name: &'static str, count: u64, rows: u64, } -/// One shape's per-operation samples, reduced to the artifact's five fields. +/// One shape's per-operation samples, with the rows the shape returned in total. +struct Samples { + values: Vec, + rows: u64, +} + +/// One shape's samples reduced to the artifact's fields. struct Timing { ops: u64, p50_us: u64, p95_us: u64, p99_us: u64, per_second: u64, + rows_per_second: u64, } impl Timing { - fn from_samples(samples: &[u64]) -> Self { - let mut sorted = samples.to_vec(); + fn from_samples(samples: &Samples) -> Self { + let mut sorted = samples.values.clone(); sorted.sort_unstable(); let total: u64 = sorted.iter().sum(); let ops = sorted.len() as u64; @@ -212,8 +253,31 @@ impl Timing { p50_us: nearest_rank(&sorted, 50), p95_us: nearest_rank(&sorted, 95), p99_us: nearest_rank(&sorted, 99), - // One operation's own rate: the whole shape's operations against the time they took. + // Both rates are the shape's own integers against the time its calls took: one counts + // operations, the other the rows those operations returned, and they differ by the + // batch size for `create_many` rather than by a second denominator. per_second: ops.saturating_mul(1_000_000) / total.max(1), + rows_per_second: samples.rows.saturating_mul(1_000_000) / total.max(1), + } + } +} + +/// One shape's spread across repeats: the middle value and the tenth and ninetieth percentiles +/// of the per-run rate. +struct Band { + median: u64, + p10: u64, + p90: u64, +} + +impl Band { + fn from_values(values: &[u64]) -> Self { + let mut sorted = values.to_vec(); + sorted.sort_unstable(); + Self { + median: nearest_rank(&sorted, 50), + p10: nearest_rank(&sorted, 10), + p90: nearest_rank(&sorted, 90), } } } @@ -233,7 +297,7 @@ fn nearest_rank(sorted: &[u64], p: u64) -> u64 { struct Run { event_count_read_back: u64, shapes: Vec, - timings: BTreeMap<&'static str, Vec>, + timings: BTreeMap<&'static str, Samples>, } /// The artifact, minus `volatile`: everything here is identical between two runs of one command. @@ -241,9 +305,13 @@ struct Report { backend: String, seed: u64, events: u64, + repeat_count: u64, event_count_read_back: u64, shapes: Vec, timings: BTreeMap, + bands: BTreeMap, + /// Every repeat's shapes, so verification can check they agree with the first. + repeat_shapes: Vec>, } /// One failed integrity check, reported as `verify failed: : expected , got `. @@ -253,6 +321,16 @@ struct VerifyFailure { got: String, } +impl VerifyFailure { + fn new(field: impl Into, expected: impl Into, got: impl Into) -> Self { + Self { + field: field.into(), + expected: expected.into(), + got: got.into(), + } + } +} + impl fmt::Display for VerifyFailure { fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { let Self { @@ -288,60 +366,111 @@ async fn run() -> Fallible { let arguments = Arguments::parse(); let plan = Plan::resolve(&arguments)?; - let (root, _temporary) = match &plan.store { - Store::Given(path) => (path.clone(), None), - Store::Temporary => { - let directory = tempfile::tempdir()?; - let path = directory.path().to_path_buf(); - (path, Some(directory)) - } - }; + eprintln!( + "measuring {}: {} events at seed {}, {} repeat{}, artifact {}", + plan.backend.name(), + plan.events, + plan.seed, + plan.repeats, + if plan.repeats == 1 { "" } else { "s" }, + plan.out.display() + ); - let store: Arc = match plan.backend { - Backend::Lmdb => Arc::new(LmdbBackend::open(&root).await?), - Backend::Postgres => { - let admin_url = plan - .admin_url - .as_deref() - .ok_or_else(|| refusal("--backend postgres needs PARITY_ADMIN_URL"))?; - Arc::new(postgres_backend(admin_url).await?) - } - }; + let mut first: Option = None; + let mut rest: Vec = Vec::new(); + let mut store_size = None; + + for repeat in 0..plan.repeats { + let (root, _temporary) = store_root(&plan, repeat)?; + let store: Arc = match plan.backend { + Backend::Lmdb => Arc::new(LmdbBackend::open(&root).await?), + Backend::Postgres => { + let admin_url = plan + .admin_url + .as_deref() + .ok_or_else(|| refusal("--backend postgres needs PARITY_ADMIN_URL"))?; + Arc::new(postgres_backend(admin_url).await?) + } + }; - let measured = measure(store.as_ref(), plan.events, plan.seed).await?; + let label = if plan.repeats == 1 { + String::new() + } else { + format!("repeat {}/{}: ", repeat + 1, plan.repeats) + }; + let measured = measure(store.as_ref(), plan.events, plan.seed, &label).await?; - let store_size = match plan.backend { - Backend::Lmdb => { + if plan.backend == Backend::Lmdb { let data_bytes = std::fs::metadata(store_file(&root))?.len(); - Some(StoreSize { + store_size = Some(StoreSize { data_bytes, bytes_per_event: data_bytes / plan.events, - }) + }); } - Backend::Postgres => None, - }; - let report = Report::new(plan.backend, plan.seed, plan.events, measured); - let artifact = report.artifact(volatile_json(&report.timings, store_size.as_ref())); - std::fs::write( - &plan.out, - format!("{}\n", serde_json::to_string_pretty(&artifact)?), - )?; + if first.is_none() { + first = Some(measured); + } else { + rest.push(measured); + } + } + + let first = first.ok_or_else(|| refusal("--repeats must be at least 1"))?; + let report = Report::new(plan.backend, plan.seed, plan.events, first, rest); + let artifact = report.artifact(volatile_json(&report, store_size.as_ref())); + + let text = format!("{}\n", serde_json::to_string_pretty(&artifact)?); + std::fs::write(&plan.out, text) + .map_err(|error| refusal(format!("--out {}: {error}", plan.out.display())))?; if plan.verify { let failures = verify(&report); for failure in &failures { eprintln!("{failure}"); } + eprintln!( + "wrote {}; verify: {}", + plan.out.display(), + if failures.is_empty() { + "passed".to_owned() + } else { + format!("{} check{} failed", failures.len(), plural(failures.len())) + } + ); return Ok(ExitCode::from(verify_exit_code(&failures))); } + eprintln!("wrote {}", plan.out.display()); Ok(ExitCode::SUCCESS) } +fn plural(count: usize) -> &'static str { + if count == 1 { "" } else { "s" } +} + +/// The root one repeat opens its store under: a fresh temporary directory each time, and one +/// subdirectory per repeat under a `--store` root when the phases run more than once. +fn store_root(plan: &Plan, repeat: u64) -> Fallible<(PathBuf, Option)> { + match &plan.store { + Store::Temporary => { + let directory = tempfile::tempdir()?; + let root = directory.path().to_path_buf(); + Ok((root, Some(directory))) + } + Store::Given(path) if plan.repeats == 1 => Ok((path.clone(), None)), + Store::Given(path) => Ok((path.join(format!("repeat-{repeat}")), None)), + } +} + impl Plan { /// Answers every refusal before a store is opened, so a refused run leaves nothing behind. fn resolve(arguments: &Arguments) -> Fallible { + if arguments.repeats < 1 { + return Err(refusal( + "--repeats 0 asks for no measurement: pass 1 or more", + )); + } + if arguments.events < INGEST_EVENTS { return Err(refusal(format!( "--events {} is below the minimum of {INGEST_EVENTS}: the ingest phase measures \ @@ -371,9 +500,29 @@ impl Plan { } if arguments.backend == Backend::Postgres && arguments.store.is_some() { - return Err(refusal( - "--store names an LMDB store and is only meaningful with --backend lmdb", - )); + let store = arguments + .store + .as_deref() + .map(|path| path.display().to_string()) + .unwrap_or_default(); + return Err(refusal(format!( + "--store {store} is only meaningful with --backend lmdb: the Postgres arm keeps \ + its data in the scratch database it creates" + ))); + } + + // The write happens after the whole measurement, so a mistyped directory has to be a + // refusal like any other rather than a failure at the end of a long run. + let parent = match arguments.out.parent() { + Some(parent) if !parent.as_os_str().is_empty() => parent.to_path_buf(), + _ => PathBuf::from("."), + }; + if !parent.is_dir() { + return Err(refusal(format!( + "--out {}: {} is not a directory. Create it and run again", + arguments.out.display(), + parent.display() + ))); } let admin_url = match arguments.backend { @@ -400,6 +549,7 @@ impl Plan { backend: arguments.backend, events: arguments.events, seed: arguments.seed, + repeats: arguments.repeats, out: arguments.out.clone(), verify: arguments.verify, store, @@ -477,13 +627,23 @@ fn with_database(url: &str, database: &str) -> String { } } +/// The cycle position event `index` takes. +/// +/// The author's ordinal is added to the block the event falls in, so every author writes every +/// kind as the corpus advances — keying the kind on the index alone would give each author a +/// single kind, because `AUTHOR_COUNT` is a multiple of the cycle length — while every +/// `AUTHOR_COUNT`-event block still holds the cycle's proportions. +fn cycle_position(index: u64) -> usize { + ((index % AUTHOR_COUNT + index / AUTHOR_COUNT) % KIND_CYCLE.len() as u64) as usize +} + /// Event `index` of the corpus, for seed `seed`: identical input, identical bytes. fn corpus_event(index: u64, seed: u64) -> Event { Event { id: event_id(index, seed), pubkey: author_pubkey(index % AUTHOR_COUNT, seed), created_at: CREATED_AT_ANCHOR_UNIX - (index % CREATED_AT_WINDOW_SECS as u64) as i64, - kind: Kind(KIND_CYCLE[(index % KIND_CYCLE.len() as u64) as usize]), + kind: Kind(KIND_CYCLE[cycle_position(index)]), tags: vec![vec![ "t".to_owned(), format!("bench-{}", index % TAG_VALUE_COUNT), @@ -511,17 +671,231 @@ fn author_pubkey(author: u64, seed: u64) -> Pubkey { Pubkey::from_byte_array(bytes) } +/// The `created_at` span the corpus covers: one second per event until the window is full. +/// +/// Every read window is derived from this rather than from [`CREATED_AT_WINDOW_SECS`], so a +/// window never slides off a corpus shorter than the window — which is what made the `count` +/// shape time an empty range for all but its first iteration. +fn corpus_span(events: u64) -> i64 { + events.min(CREATED_AT_WINDOW_SECS as u64) as i64 +} + +fn since_for(iteration: u64, events: u64) -> i64 { + let span = corpus_span(events); + CREATED_AT_ANCHOR_UNIX - span + (iteration as i64) * span / READ_ITERATIONS as i64 +} + +fn until_for(iteration: u64, events: u64) -> i64 { + let span = corpus_span(events); + CREATED_AT_ANCHOR_UNIX - (iteration as i64) * span / COUNT_ITERATIONS as i64 +} + +fn by_id_target(iteration: u64, events: u64, seed: u64) -> u64 { + (seed * BY_ID_STRIDE + iteration * BY_ID_STRIDE + BY_ID_OFFSET) % events +} + +/// One read shape's filter for one iteration. The workload and the oracle both call this, so a +/// window that slides off the corpus shows up as an empty expectation rather than as two +/// independent mistakes. +fn read_filters(name: &str, iteration: u64, events: u64, seed: u64) -> Vec { + match name { + "by_id" => { + let target = by_id_target(iteration, events, seed); + vec![Filter { + ids: Some(vec![event_id(target, seed).to_string()]), + limit: Some(BY_ID_LIMIT), + ..Filter::default() + }] + } + "author_kind" => vec![Filter { + authors: Some(vec![ + author_pubkey(iteration % AUTHOR_COUNT, seed).to_string(), + ]), + kinds: Some(vec![Kind::TEXT_NOTE]), + limit: Some(AUTHOR_KIND_LIMIT), + ..Filter::default() + }], + "kind_since" => vec![Filter { + kinds: Some(vec![Kind::TEXT_NOTE]), + since: Some(since_for(iteration, events)), + limit: Some(KIND_SINCE_LIMIT), + ..Filter::default() + }], + "tag" => { + let tag_index = iteration % TAG_VALUE_COUNT; + let mut tags = BTreeMap::new(); + tags.insert("#t".to_owned(), vec![format!("bench-{tag_index}")]); + vec![Filter { + tags, + limit: Some(TAG_LIMIT), + ..Filter::default() + }] + } + _ => vec![Filter { + kinds: Some(vec![Kind::TEXT_NOTE]), + until: Some(until_for(iteration, events)), + ..Filter::default() + }], + } +} + +/// The limit a read shape carries, or `None` for the unbounded `count`. +fn read_limit(name: &str) -> Option { + match name { + "by_id" => Some(BY_ID_LIMIT), + "author_kind" => Some(AUTHOR_KIND_LIMIT), + "kind_since" => Some(KIND_SINCE_LIMIT), + "tag" => Some(TAG_LIMIT), + _ => None, + } +} + +/// How many corpus events are `TEXT_NOTE` events among the first `count` indices — an index +/// range covers a `created_at` range because `created_at` falls as the index rises. +fn text_notes_in_range(lo: u64, hi: u64) -> u64 { + let (lo, hi) = (lo.min(hi), hi); + let mut total = 0; + let mut index = lo; + + if index < hi { + let block = index / AUTHOR_COUNT; + let end = ((block + 1) * AUTHOR_COUNT).min(hi); + total += text_notes_in_block(block, index % AUTHOR_COUNT, end - index); + index = end; + } + + let blocks = (hi - index) / AUTHOR_COUNT; + total += blocks * text_notes_per_block(); + index += blocks * AUTHOR_COUNT; + + if index < hi { + total += text_notes_in_block(index / AUTHOR_COUNT, 0, hi - index); + } + + total +} + +/// `TEXT_NOTE` events among `count` consecutive authors of one block, starting at `first_author`. +fn text_notes_in_block(block: u64, first_author: u64, count: u64) -> u64 { + (0..count) + .filter(|offset| { + let author = first_author + offset; + KIND_CYCLE[((author + block) % KIND_CYCLE.len() as u64) as usize] == TEXT_NOTE + }) + .count() as u64 +} + +/// `TEXT_NOTE` events in one whole block: the cycle's share of `AUTHOR_COUNT`, whatever block +/// it is, because every author ordinal appears once per block. +fn text_notes_per_block() -> u64 { + text_notes_in_block(0, 0, AUTHOR_COUNT) +} + +/// Corpus events a shape's filter matches in one iteration, before the limit — the oracle's +/// expectation, derived from the corpus definition and not from what the store returned. +fn expected_matches(name: &str, iteration: u64, events: u64) -> u64 { + match name { + "by_id" => 1, + "author_kind" => { + let author = iteration % AUTHOR_COUNT; + if author >= events { + return 0; + } + let sorties = (events - author).div_ceil(AUTHOR_COUNT); + let decades = sorties / KIND_CYCLE.len() as u64; + let mut matches = decades * kind_cycle_notes(); + for offset in 0..sorties % KIND_CYCLE.len() as u64 { + if KIND_CYCLE[((author % KIND_CYCLE.len() as u64 + offset) + % KIND_CYCLE.len() as u64) as usize] + == TEXT_NOTE + { + matches += 1; + } + } + matches + } + "tag" => { + let value = iteration % TAG_VALUE_COUNT; + if value >= events { + 0 + } else { + (events - 1 - value) / TAG_VALUE_COUNT + 1 + } + } + "kind_since" => text_notes_since(events, since_for(iteration, events)), + _ => text_notes_until(events, until_for(iteration, events)), + } +} + +/// `TEXT_NOTE` events the cycle holds, which is also the count over any run of +/// `KIND_CYCLE.len()` consecutive events. +fn kind_cycle_notes() -> u64 { + KIND_CYCLE.iter().filter(|kind| **kind == TEXT_NOTE).count() as u64 +} + +/// `TEXT_NOTE` events with `created_at >= since`. +fn text_notes_since(events: u64, since: i64) -> u64 { + let window = CREATED_AT_WINDOW_SECS as u64; + let newest = CREATED_AT_ANCHOR_UNIX - since; + if newest < 0 { + return 0; + } + if newest as u64 >= window { + return text_notes_in_range(0, events); + } + let newest = newest as u64; + let mut total = 0; + let mut cycle = 0; + while cycle * window < events { + let start = cycle * window; + let end = (start + newest + 1).min(events); + total += text_notes_in_range(start, end); + cycle += 1; + } + total +} + +/// `TEXT_NOTE` events with `created_at <= until`. +fn text_notes_until(events: u64, until: i64) -> u64 { + let window = CREATED_AT_WINDOW_SECS as u64; + let oldest = CREATED_AT_ANCHOR_UNIX - until; + if oldest <= 0 { + return text_notes_in_range(0, events); + } + if oldest as u64 >= window { + return 0; + } + let oldest = oldest as u64; + let mut total = 0; + let mut cycle = 0; + while cycle * window < events { + let start = cycle * window + oldest; + let end = ((cycle + 1) * window).min(events); + if start < end { + total += text_notes_in_range(start, end); + } + cycle += 1; + } + total +} + /// Runs R4's phases in order and records one sample per operation. -async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallible { +async fn measure( + store: &dyn EventRepository, + events: u64, + seed: u64, + label: &str, +) -> Fallible { let bulk_events = events - INGEST_EVENTS; - let mut timings: BTreeMap<&'static str, Vec> = BTreeMap::new(); + let mut timings: BTreeMap<&'static str, Samples> = BTreeMap::new(); let mut shapes = Vec::new(); // 1. Bulk load: the first `events - INGEST_EVENTS` events, one `create_many` per batch. - let mut samples = Vec::new(); + let mut values = Vec::new(); let mut rows = 0; let mut count = 0; let mut index = 0; + let load_started = Instant::now(); while index < bulk_events { let end = (index + WRITE_BATCH as u64).min(bulk_events); let batch: Vec = (index..end) @@ -529,11 +903,15 @@ async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallibl .collect(); let started = Instant::now(); rows += store.create_many(&batch).await?; - samples.push(elapsed_us(started)); + values.push(elapsed_us(started)); count += 1; index = end; } - timings.insert("create_many", samples); + eprintln!( + "{label}loaded {bulk_events} events in {} ms", + load_started.elapsed().as_millis() + ); + timings.insert("create_many", Samples { values, rows }); shapes.push(ShapeCounts { name: "create_many", count, @@ -541,15 +919,20 @@ async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallibl }); // 2. Ingest: the corpus tail, one `create` per call, which is the relay's own write. - let mut samples = Vec::new(); + let mut values = Vec::new(); let mut rows = 0; + let ingest_started = Instant::now(); for index in bulk_events..events { let record = EventRecord::from_event(&corpus_event(index, seed)); let started = Instant::now(); rows += store.create(&record).await?; - samples.push(elapsed_us(started)); + values.push(elapsed_us(started)); } - timings.insert("create", samples); + eprintln!( + "{label}ingested {INGEST_EVENTS} events in {} ms", + ingest_started.elapsed().as_millis() + ); + timings.insert("create", Samples { values, rows }); shapes.push(ShapeCounts { name: "create", count: INGEST_EVENTS, @@ -559,94 +942,30 @@ async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallibl // 3. Read the whole corpus back once, which is what the unbounded count costs. let started = Instant::now(); let event_count_read_back = store.count_by_filters(&[Filter::default()]).await?; - timings.insert("read_back", vec![elapsed_us(started)]); + timings.insert( + "read_back", + Samples { + values: vec![elapsed_us(started)], + rows: event_count_read_back, + }, + ); // 4. The five read shapes, every target and window derived from the iteration and the seed. - let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { - let target = (seed * BY_ID_STRIDE + iteration * BY_ID_STRIDE + BY_ID_OFFSET) % events; - vec![Filter { - ids: Some(vec![event_id(target, seed).to_string()]), - limit: Some(BY_ID_LIMIT), - ..Filter::default() - }] - }) - .await?; - timings.insert("by_id", samples); - shapes.push(ShapeCounts { - name: "by_id", - count, - rows, - }); - - let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { - vec![Filter { - authors: Some(vec![ - author_pubkey(iteration % AUTHOR_COUNT, seed).to_string(), - ]), - kinds: Some(vec![Kind::TEXT_NOTE]), - limit: Some(AUTHOR_KIND_LIMIT), - ..Filter::default() - }] - }) - .await?; - timings.insert("author_kind", samples); - shapes.push(ShapeCounts { - name: "author_kind", - count, - rows, - }); - - let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { - let since = CREATED_AT_ANCHOR_UNIX - CREATED_AT_WINDOW_SECS - + (iteration as i64) * CREATED_AT_WINDOW_SECS / READ_ITERATIONS as i64; - vec![Filter { - kinds: Some(vec![Kind::TEXT_NOTE]), - since: Some(since), - limit: Some(KIND_SINCE_LIMIT), - ..Filter::default() - }] - }) - .await?; - timings.insert("kind_since", samples); - shapes.push(ShapeCounts { - name: "kind_since", - count, - rows, - }); - - let (count, rows, samples) = read_shape(store, READ_ITERATIONS, |iteration| { - let tag_index = iteration % TAG_VALUE_COUNT; - let mut tags = BTreeMap::new(); - tags.insert("#t".to_owned(), vec![format!("bench-{tag_index}")]); - vec![Filter { - tags, - limit: Some(TAG_LIMIT), - ..Filter::default() - }] - }) - .await?; - timings.insert("tag", samples); - shapes.push(ShapeCounts { - name: "tag", - count, - rows, - }); + for name in ["by_id", "author_kind", "kind_since", "tag"] { + let (count, rows, values) = read_shape(store, name, READ_ITERATIONS, seed, events).await?; + timings.insert(name, Samples { values, rows }); + shapes.push(ShapeCounts { name, count, rows }); + } - let mut samples = Vec::new(); + let mut values = Vec::new(); let mut rows = 0; for iteration in 0..COUNT_ITERATIONS { - let until = CREATED_AT_ANCHOR_UNIX - - (iteration as i64) * CREATED_AT_WINDOW_SECS / COUNT_ITERATIONS as i64; - let filters = [Filter { - kinds: Some(vec![Kind::TEXT_NOTE]), - until: Some(until), - ..Filter::default() - }]; + let filters = read_filters("count", iteration, events, seed); let started = Instant::now(); rows += store.count_by_filters(&filters).await?; - samples.push(elapsed_us(started)); + values.push(elapsed_us(started)); } - timings.insert("count", samples); + timings.insert("count", Samples { values, rows }); shapes.push(ShapeCounts { name: "count", count: COUNT_ITERATIONS, @@ -664,19 +983,21 @@ async fn measure(store: &dyn EventRepository, events: u64, seed: u64) -> Fallibl /// whole read. Returns the operations issued, the rows drained and one sample per call. async fn read_shape( store: &dyn EventRepository, + name: &str, iterations: u64, - filters: impl Fn(u64) -> Vec, + seed: u64, + events: u64, ) -> Fallible<(u64, u64, Vec)> { - let mut samples = Vec::with_capacity(iterations as usize); + let mut values = Vec::with_capacity(iterations as usize); let mut rows = 0; for iteration in 0..iterations { - let filters = filters(iteration); + let filters = read_filters(name, iteration, events, seed); let started = Instant::now(); let records = collect_records(store.find_by_filters(&filters).await?).await?; - samples.push(elapsed_us(started)); + values.push(elapsed_us(started)); rows += records.len() as u64; } - Ok((iterations, rows, samples)) + Ok((iterations, rows, values)) } fn elapsed_us(started: Instant) -> u64 { @@ -684,19 +1005,49 @@ fn elapsed_us(started: Instant) -> u64 { } impl Report { - fn new(backend: Backend, seed: u64, events: u64, run: Run) -> Self { - let timings = run - .timings + fn new(backend: Backend, seed: u64, events: u64, first: Run, rest: Vec) -> Self { + let repeat_count = 1 + rest.len() as u64; + + let mut timings = BTreeMap::new(); + let mut rates: BTreeMap<&'static str, (Vec, Vec)> = BTreeMap::new(); + let mut repeat_shapes = Vec::new(); + + for run in std::iter::once(&first).chain(rest.iter()) { + for (name, samples) in &run.timings { + let timing = Timing::from_samples(samples); + let entry = rates.entry(name).or_default(); + entry.0.push(timing.per_second); + entry.1.push(timing.rows_per_second); + } + repeat_shapes.push(run.shapes.clone()); + } + for (name, samples) in &first.timings { + timings.insert((*name).to_owned(), Timing::from_samples(samples)); + } + + let bands = rates .into_iter() - .map(|(name, samples)| (name.to_owned(), Timing::from_samples(&samples))) + .map(|(name, (per_second, rows_per_second))| { + ( + name.to_owned(), + ( + Band::from_values(&per_second), + Band::from_values(&rows_per_second), + ), + ) + }) .collect(); + Self { backend: backend.name().to_owned(), seed, events, - event_count_read_back: run.event_count_read_back, - shapes: run.shapes, + repeat_count, + event_count_read_back: first.event_count_read_back, + shapes: first.shapes, timings, + bands, + repeat_shapes, } } @@ -717,7 +1068,7 @@ impl Report { "seed": self.seed, "events": self.events, "event_count_read_back": self.event_count_read_back, - "workload": workload_json(), + "workload": workload_json(self.repeat_count), "shapes": shapes, "volatile": volatile, }) @@ -725,7 +1076,7 @@ impl Report { } /// The workload the run measured, echoed so the artifact carries its own definition. -fn workload_json() -> Value { +fn workload_json(repeat_count: u64) -> Value { json!({ "corpus": { "authors": AUTHOR_COUNT, @@ -750,14 +1101,16 @@ fn workload_json() -> Value { }, }, "concurrency": 1, + "repeats": repeat_count, }) } -/// Everything that can differ between two runs: the host, the store's size and the timings. -fn volatile_json(timings: &BTreeMap, store: Option<&StoreSize>) -> Value { - let mut entries = Map::new(); - for (name, timing) in timings { - entries.insert( +/// Everything that can differ between two runs: the host, the store's size, the timings and the +/// spread across repeats. +fn volatile_json(report: &Report, store: Option<&StoreSize>) -> Value { + let mut timings = Map::new(); + for (name, timing) in &report.timings { + timings.insert( name.clone(), json!({ "ops": timing.ops, @@ -765,9 +1118,30 @@ fn volatile_json(timings: &BTreeMap, store: Option<&StoreSize>) "p95_us": timing.p95_us, "p99_us": timing.p99_us, "per_second": timing.per_second, + "rows_per_second": timing.rows_per_second, }), ); } + + let mut repeats = Map::new(); + for (name, (per_second, rows_per_second)) in &report.bands { + repeats.insert( + name.clone(), + json!({ + "per_second": { + "median": per_second.median, + "p10": per_second.p10, + "p90": per_second.p90, + }, + "rows_per_second": { + "median": rows_per_second.median, + "p10": rows_per_second.p10, + "p90": rows_per_second.p90, + }, + }), + ); + } + json!({ "machine": { "cpu_count": cpu_count(), @@ -787,7 +1161,8 @@ fn volatile_json(timings: &BTreeMap, store: Option<&StoreSize>) "bytes_per_event": Value::Null, }), }, - "timings": entries, + "timings": timings, + "repeats": repeats, }) } @@ -813,20 +1188,32 @@ fn load_1min() -> Option { load.split_whitespace().next()?.parse().ok() } -/// Every integrity check `--verify` makes; an empty list means the run recorded what it asked for. +/// Every integrity check `--verify` makes; an empty list means the run recorded what the corpus +/// says it must. fn verify(report: &Report) -> Vec { - let mut failures = Vec::new(); - let mut check = |field: String, expected: u64, got: u64| { + fn check(failures: &mut Vec, field: String, expected: u64, got: u64) { if expected != got { - failures.push(VerifyFailure { + failures.push(VerifyFailure::new( field, - expected: expected.to_string(), - got: got.to_string(), - }); + expected.to_string(), + got.to_string(), + )); } - }; + } + + let mut failures = Vec::new(); + + let names: Vec<&str> = report.shapes.iter().map(|shape| shape.name).collect(); + if names != SHAPES.to_vec() { + failures.push(VerifyFailure::new( + "shapes", + SHAPES.join(", "), + names.join(", "), + )); + } check( + &mut failures, "event_count_read_back".to_owned(), report.events, report.event_count_read_back, @@ -837,57 +1224,157 @@ fn verify(report: &Report) -> Vec { let create = shape(report, "create"); check( + &mut failures, "shapes[create_many].rows + shapes[create].rows".to_owned(), report.events, create_many.rows + create.rows, ); - check("shapes[create].rows".to_owned(), create.count, create.rows); + check( + &mut failures, + "shapes[create].rows".to_owned(), + create.count, + create.rows, + ); // R6's `create_many.rows == count * create_many_batch` is this: every call wrote the batch it // was given. A bulk load that is not a whole number of batches ends in a short one, so the // expected total is the bulk event count, which is `count * batch` whenever it divides. check( + &mut failures, "shapes[create_many].rows".to_owned(), bulk_events, create_many.rows, ); check( + &mut failures, "shapes[create_many].count".to_owned(), bulk_events.div_ceil(WRITE_BATCH as u64), create_many.count, ); - for (name, iterations) in [ - ("by_id", READ_ITERATIONS), - ("author_kind", READ_ITERATIONS), - ("kind_since", READ_ITERATIONS), - ("tag", READ_ITERATIONS), - ("count", COUNT_ITERATIONS), - ] { - let measured = shape(report, name); - check(format!("shapes[{name}].count"), iterations, measured.count); + // The read shapes are checked against what the corpus says they must return, not against + // "more than nothing": an empty window, a page stopped at its first batch and a selector + // that stopped matching all record a smaller total, and all three passed the `rows > 0` + // check this replaces. + for name in ["by_id", "author_kind", "kind_since", "tag"] { + let limit = read_limit(name).unwrap_or(0); + let mut expected = 0; + for iteration in 0..READ_ITERATIONS { + let matches = expected_matches(name, iteration, report.events); + if matches == 0 { + failures.push(VerifyFailure::new( + format!("shapes[{name}].rows"), + "> 0 in every iteration", + format!("0 at iteration {iteration}"), + )); + } + expected += matches.min(limit); + } + check( + &mut failures, + format!("shapes[{name}].rows"), + expected, + shape(report, name).rows, + ); + check( + &mut failures, + format!("shapes[{name}].count"), + READ_ITERATIONS, + shape(report, name).count, + ); } + let mut expected = 0; + for iteration in 0..COUNT_ITERATIONS { + let matches = expected_matches("count", iteration, report.events); + if matches == 0 { + failures.push(VerifyFailure::new( + "shapes[count].rows", + "> 0 in every iteration", + format!("0 at iteration {iteration}"), + )); + } + expected += matches; + } + check( + &mut failures, + "shapes[count].rows".to_owned(), + expected, + shape(report, "count").rows, + ); + check( + &mut failures, + "shapes[count].count".to_owned(), + COUNT_ITERATIONS, + shape(report, "count").count, + ); + for measured in &report.shapes { if measured.rows == 0 { - failures.push(VerifyFailure { - field: format!("shapes[{}].rows", measured.name), - expected: "> 0".to_owned(), - got: measured.rows.to_string(), - }); + failures.push(VerifyFailure::new( + format!("shapes[{}].rows", measured.name), + "> 0", + measured.rows.to_string(), + )); } } for (name, timing) in &report.timings { let ordered = timing.p99_us >= timing.p95_us && timing.p95_us >= timing.p50_us; if !ordered { - failures.push(VerifyFailure { - field: format!("volatile.timings[{name}]"), - expected: "p99_us >= p95_us >= p50_us".to_owned(), - got: format!( + failures.push(VerifyFailure::new( + format!("volatile.timings[{name}]"), + "p99_us >= p95_us >= p50_us", + format!( "{} >= {} >= {}", timing.p99_us, timing.p95_us, timing.p50_us ), - }); + )); + } + check( + &mut failures, + format!("volatile.timings[{name}].ops"), + timing.ops.max(1), + timing.ops, + ); + check( + &mut failures, + format!("volatile.timings[{name}].per_second"), + timing.per_second.max(1), + timing.per_second, + ); + check( + &mut failures, + format!("volatile.timings[{name}].rows_per_second"), + timing.rows_per_second.max(1), + timing.rows_per_second, + ); + } + + for (name, (per_second, rows_per_second)) in &report.bands { + for (metric, band) in [ + ("per_second", per_second), + ("rows_per_second", rows_per_second), + ] { + let ordered = band.p10 <= band.median && band.median <= band.p90; + if !ordered { + failures.push(VerifyFailure::new( + format!("volatile.repeats[{name}].{metric}"), + "p10 <= median <= p90", + format!("{} <= {} <= {}", band.p10, band.median, band.p90), + )); + } + } + } + + for (index, shapes) in report.repeat_shapes.iter().enumerate().skip(1) { + for (first, repeat) in report.shapes.iter().zip(shapes.iter()) { + if first != repeat { + failures.push(VerifyFailure::new( + format!("repeats[{index}].shapes[{}]", first.name), + format!("count {} rows {}", first.count, first.rows), + format!("count {} rows {}", repeat.count, repeat.rows), + )); + } } } @@ -917,18 +1404,11 @@ fn verify_exit_code(failures: &[VerifyFailure]) -> u8 { mod tests { use super::*; + const EVENTS: u64 = 50_000; + fn valid_report() -> Report { let mut timings = BTreeMap::new(); - for name in [ - "create_many", - "create", - "by_id", - "author_kind", - "kind_since", - "tag", - "count", - "read_back", - ] { + for name in SHAPES.iter().chain(std::iter::once(&"read_back")).copied() { timings.insert( name.to_owned(), Timing { @@ -937,52 +1417,72 @@ mod tests { p95_us: 20, p99_us: 30, per_second: 1_000, + rows_per_second: 2_000, }, ); } + let bands = timings + .keys() + .map(|name| { + ( + name.clone(), + ( + Band { + median: 1_000, + p10: 900, + p90: 1_100, + }, + Band { + median: 2_000, + p10: 1_800, + p90: 2_200, + }, + ), + ) + }) + .collect(); + let mut shapes = vec![ + ShapeCounts { + name: "create_many", + count: 98, + rows: 49_000, + }, + ShapeCounts { + name: "create", + count: 1_000, + rows: 1_000, + }, + ]; + for name in ["by_id", "author_kind", "kind_since", "tag"] { + let limit = read_limit(name).unwrap_or(0); + let rows = (0..READ_ITERATIONS) + .map(|iteration| expected_matches(name, iteration, EVENTS).min(limit)) + .sum(); + shapes.push(ShapeCounts { + name, + count: READ_ITERATIONS, + rows, + }); + } + let rows = (0..COUNT_ITERATIONS) + .map(|iteration| expected_matches("count", iteration, EVENTS)) + .sum(); + shapes.push(ShapeCounts { + name: "count", + count: COUNT_ITERATIONS, + rows, + }); + Report { backend: "lmdb".to_owned(), seed: DEFAULT_SEED, - events: 50_000, - event_count_read_back: 50_000, - shapes: vec![ - ShapeCounts { - name: "create_many", - count: 98, - rows: 49_000, - }, - ShapeCounts { - name: "create", - count: 1_000, - rows: 1_000, - }, - ShapeCounts { - name: "by_id", - count: READ_ITERATIONS, - rows: 200, - }, - ShapeCounts { - name: "author_kind", - count: READ_ITERATIONS, - rows: 20_000, - }, - ShapeCounts { - name: "kind_since", - count: READ_ITERATIONS, - rows: 50_000, - }, - ShapeCounts { - name: "tag", - count: READ_ITERATIONS, - rows: 20_000, - }, - ShapeCounts { - name: "count", - count: COUNT_ITERATIONS, - rows: 1_000_000, - }, - ], + events: EVENTS, + repeat_count: 1, + event_count_read_back: EVENTS, + repeat_shapes: vec![shapes.clone()], + shapes, timings, + bands, } } @@ -995,12 +1495,24 @@ mod tests { #[test] fn percentiles_use_nearest_rank() { let samples: Vec = (1..=200).collect(); - let timing = Timing::from_samples(&samples); + let timing = Timing::from_samples(&Samples { + values: samples, + rows: 20_100, + }); assert_eq!(timing.p50_us, 100); assert_eq!(timing.p95_us, 190); assert_eq!(timing.p99_us, 198); assert_eq!(timing.ops, 200); assert_eq!(timing.per_second, 200 * 1_000_000 / 20_100); + assert_eq!(timing.rows_per_second, 20_100 * 1_000_000 / 20_100); + } + + #[test] + fn bands_report_median_p10_p90() { + let band = Band::from_values(&[30, 10, 20]); + assert_eq!((band.p10, band.median, band.p90), (10, 20, 30)); + let band = Band::from_values(&[42]); + assert_eq!((band.p10, band.median, band.p90), (42, 42, 42)); } #[test] @@ -1059,10 +1571,53 @@ mod tests { .expect("a tag shape"); shape.rows = 0; let failures = verify(&report); + assert!( + failures + .iter() + .any(|failure| failure.field == "shapes[tag].rows"), + "no shapes[tag].rows failure in {failures:?}", + failures = failures.len() + ); + } + + #[test] + fn verify_rejects_a_short_read_page() { + let mut report = valid_report(); + let shape = report + .shapes + .iter_mut() + .find(|shape| shape.name == "author_kind") + .expect("an author_kind shape"); + // What a page truncated to its first batch, or an empty author range, would record. + shape.rows = READ_ITERATIONS; + let failures = verify(&report); assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); - assert_eq!(failures[0].field, "shapes[tag].rows"); - assert_eq!(failures[0].expected, "> 0"); - assert_eq!(failures[0].got, "0"); + assert_eq!(failures[0].field, "shapes[author_kind].rows"); + assert_eq!(failures[0].expected, "20000"); + assert_eq!(failures[0].got, "200"); + } + + #[test] + fn verify_rejects_a_band_out_of_order() { + let mut report = valid_report(); + let (per_second, _) = report.bands.get_mut("count").expect("a count band"); + // The median above the ninetieth percentile, while the tenth stays below it: only the + // middle clause of the ordering catches this, so the test pins that clause too. + per_second.median = per_second.p90 + 1; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "volatile.repeats[count].per_second"); + } + + #[test] + fn verify_rejects_a_repeat_that_disagrees() { + let mut report = valid_report(); + let mut second = report.shapes.clone(); + second[0].rows -= 1; + report.repeat_shapes.push(second); + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "repeats[1].shapes[create_many]"); } #[test] @@ -1086,6 +1641,21 @@ mod tests { } } + #[test] + fn every_author_writes_both_kinds() { + for author in 0..AUTHOR_COUNT { + let kinds: std::collections::BTreeSet = (0..5_000) + .filter(|index| index % AUTHOR_COUNT == author) + .map(|index| corpus_event(index, 7).kind.0) + .collect(); + assert_eq!( + kinds, + std::collections::BTreeSet::from([1, 7]), + "author {author} writes {kinds:?}" + ); + } + } + #[test] fn the_corpus_content_is_the_configured_length() { for index in 0..10_000 { @@ -1100,4 +1670,86 @@ mod tests { assert_eq!(event.tags[0][0], "t"); } } + + #[test] + fn every_read_window_matches_events_in_every_iteration() { + for events in [1_000, 2_000, 5_000, 50_000] { + for name in ["by_id", "author_kind", "kind_since", "tag", "count"] { + let iterations = if name == "count" { + COUNT_ITERATIONS + } else { + READ_ITERATIONS + }; + for iteration in 0..iterations { + let matches = expected_matches(name, iteration, events); + assert!( + matches > 0, + "{name} at {events} events: iteration {iteration} matches nothing" + ); + } + } + } + } + + #[test] + fn expectations_match_the_corpus() { + for events in [1_000u64, 2_000, 4_321] { + let corpus: Vec = (0..events).map(|index| corpus_event(index, 7)).collect(); + for name in ["by_id", "author_kind", "kind_since", "tag", "count"] { + let iterations = if name == "count" { + COUNT_ITERATIONS + } else { + READ_ITERATIONS + }; + let sampled = (0..iterations).step_by(17).chain([ + 0, + 1, + iterations / 2, + iterations - 2, + iterations - 1, + ]); + for iteration in sampled { + let filters = read_filters(name, iteration, events, 7); + let matched = corpus + .iter() + .filter(|event| filters.iter().any(|filter| filter.matches(event))) + .count() as u64; + assert_eq!( + matched, + expected_matches(name, iteration, events), + "{name} at {events} events, iteration {iteration}" + ); + } + } + } + } + + #[test] + fn the_expected_totals_are_the_ones_the_document_quotes() { + let totals: Vec<(String, u64)> = ["by_id", "author_kind", "kind_since", "tag", "count"] + .into_iter() + .map(|name| { + let limit = read_limit(name).unwrap_or(u64::MAX); + let iterations = if name == "count" { + COUNT_ITERATIONS + } else { + READ_ITERATIONS + }; + let rows = (0..iterations) + .map(|iteration| expected_matches(name, iteration, EVENTS).min(limit)) + .sum(); + (name.to_owned(), rows) + }) + .collect(); + assert_eq!( + totals, + vec![ + ("by_id".to_owned(), 200), + ("author_kind".to_owned(), 20_000), + ("kind_since".to_owned(), 99_602), + ("tag".to_owned(), 20_000), + ("count".to_owned(), 1_020_000), + ] + ); + } } From b835532c9209c1997a5914e822b0633573cfab12 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 00:38:39 -0500 Subject: [PATCH 04/14] docs: quote the rig's band and define its tables' arithmetic --- docs/rewrite/benchmarks.md | 177 ++++++++++++------- docs/rewrite/benchmarks/lmdb-50k-seed7.json | 181 ++++++++++++++++---- 2 files changed, 262 insertions(+), 96 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index 1af9ccd32..25fd0241c 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -1,7 +1,7 @@ # Benchmarks: the LMDB store on the rig's workload The numbers in this document come from one command on one host, and from the artifact that -command wrote, which is committed beside this document: +command wrote, committed beside this document: `docs/rewrite/benchmarks/lmdb-50k-seed7.json` @@ -17,49 +17,81 @@ which needs a database this host does not have, and the TypeScript/Postgres colu | | | |---|---| -| Date | 2026-11-13 | +| Date | 2026-11-14 | | Machine | 4 CPUs, `Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz` | -| Load average, one minute | 43.34 | -| Free disk at run time | 19 GB (`df -h /`) | +| Load average, one minute | 43.92 | +| Free disk at run time | 12 GB (`df -h /`) | | Profile | `release` | -| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --verify --out /tmp/bench-lmdb-1.json` | +| Repeats | 3 (`workload.repeats`) | +| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-lmdb-1.json` | | Artifact | `docs/rewrite/benchmarks/lmdb-50k-seed7.json` | The machine, the load average and the store's size are `volatile.machine` and `volatile.store` -in that artifact. The load figure matters: this host is shared, and two runs of the same command -have differed by several times on the write shapes, whose cost is LMDB's synchronous commit. +in that artifact. This host is shared: the load figure is other tenants' work on four cores, and +the three repeats below measure what that does to the numbers rather than leaving it to a +sentence. ## The LMDB numbers -One row per shape, from the artifact's `shapes` and `volatile.timings`. - -| shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | per_second | +**Within one run.** One row per shape, from the artifact's `shapes` and the first repeat's +`volatile.timings`. + +| shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | +|---|---|---|---|---|---| +| `create_many` | 98 | 49000 | 41.7 | 100.6 | 1097.4 | +| `create` | 1000 | 1000 | 3.7 | 6.5 | 8.2 | +| `by_id` | 200 | 200 | 0.0 | 0.1 | 0.1 | +| `author_kind` | 200 | 20000 | 0.3 | 0.4 | 0.4 | +| `kind_since` | 200 | 99602 | 1.4 | 2.1 | 2.3 | +| `tag` | 200 | 20000 | 0.3 | 0.4 | 0.5 | +| `count` | 50 | 1020000 | 9.6 | 19.5 | 21.8 | +| `read_back` | 1 | 50000 | 20.5 | 20.5 | 20.5 | + +Every column here is the artifact's own integer printed as-is (the `count`, `rows` and `ops` +numbers), except the three percentile columns, which are the artifact's microsecond integers +printed in milliseconds with exactly one decimal, rounding half-up: `19 514` µs prints as `19.5`, +and `0` µs would print as `0.0`. `read_back` carries no `shapes` entry: it is the single +unbounded count the corpus is read back with, and its `rows` is `event_count_read_back`. + +`count` is one repository call. `rows` is the sum over the shape's calls, which is why +`kind_since` shows 99602 rows at a limit of 500 — two hundred pages, most of them full — and why +`count`, which carries no limit, sums every match of every iteration. + +**Across the three repeats.** One row per shape, from `volatile.repeats`. The band is what this +rig exists to publish: a point estimate from one run of a shared host is not a measurement of the +store. + +| shape | per_second median | p10 | p90 | rows_per_second median | p10 | p90 | |---|---|---|---|---|---|---| -| `create_many` | 98 | 49000 | 27.3 | 39.5 | 48.5 | 35 | -| `create` | 1000 | 1000 | 3.9 | 4.7 | 5.4 | 254 | -| `by_id` | 200 | 200 | 0.0 | 0.0 | 0.1 | 46674 | -| `author_kind` | 200 | 16000 | 0.3 | 0.4 | 0.6 | 3610 | -| `kind_since` | 200 | 100000 | 1.5 | 1.7 | 2.3 | 663 | -| `tag` | 200 | 20000 | 0.3 | 0.3 | 0.4 | 3594 | -| `count` | 50 | 40000 | 0.0 | 0.0 | 18.4 | 2654 | -| `read_back` | 1 | 50000 | 19.2 | 19.2 | 19.2 | 52 | - -The `count` and `rows` columns are the artifact's integers printed as-is (rule a), and so is -`per_second`; the three percentile columns are the artifact's microsecond integers printed in -milliseconds with exactly one decimal, half-up (rule b). `read_back` carries no `shapes` entry: -it is the single unbounded count the corpus is read back with, and its `rows` is -`event_count_read_back`. +| `create_many` | 20 | 16 | 44 | 10009 | 8345 | 22483 | +| `create` | 243 | 85 | 270 | 243 | 85 | 270 | +| `by_id` | 39131 | 37757 | 47653 | 39131 | 37757 | 47653 | +| `author_kind` | 2943 | 2729 | 3131 | 294334 | 272966 | 313116 | +| `kind_since` | 678 | 651 | 700 | 338042 | 324696 | 348817 | +| `tag` | 3315 | 3308 | 3447 | 331543 | 330846 | 344750 | +| `count` | 98 | 94 | 105 | 2012445 | 1922779 | 2142195 | +| `read_back` | 48 | 36 | 52 | 2433800 | 1802711 | 2649287 | + +Every figure is the artifact's integer printed as-is: `median`, `p10` and `p90` are the +nearest-rank percentiles over the three repeats' rates, and the rule is the one the within-run +percentiles use, applied to three numbers instead of hundreds. + +`per_second` counts operations: one event for `create`, one five-hundred-event batch for +`create_many`, one filter query for a read shape, one count for `count`. `rows_per_second` counts +the rows those operations returned. The two differ for `create_many` by its batch size, which is +why the same column reads 20 operations and 10009 rows, and they coincide for `create` and for +the read shapes that always return one row per operation. + +**The store.** | events | data_bytes | bytes_per_event | |---|---|---| -| 50000 | 94191616 | 1883.8 | - -`events` and `data_bytes` are the artifact's integers as-is (rule a); `bytes_per_event` is -`data_bytes / events` rounded to one decimal (rule c), which is why it is not the artifact's own -truncated integer. +| 50000 | 94490624 | 1889.8 | -The percentiles are nearest-rank over the per-call samples, so `p50` of a shape with one -operation is that operation. `per_second` is the shape's operations against the time they took. +`events` and `data_bytes` are the artifact's integers as-is; `bytes_per_event` is +`data_bytes / events` rounded to one decimal, so it is not the artifact's own truncated integer. +`data_bytes` is `data.mdb`'s length, which includes pages LMDB allocated and has not reused yet, +so it overstates live bytes — the safe direction for the disk arithmetic in D5. ## The workload @@ -67,11 +99,13 @@ operation is that operation. `per_second` is the shape's operations against the Generated, not loaded: event `i` of `N` at seed `s` has an id of `i` and `s` little-endian in its first bytes, an author of `i % 200` over 200 authors, a kind from the cycle -`[1,1,1,1,1,1,1,1,7,7]`, `created_at = 1700000000 - (i % 2592000)`, a 256-byte content of the -index in hex then `x`, and one tag `["t", "bench-{i % 20}"]` over 20 values. The run recorded -here used seed 7. Identical input produces identical bytes, which is what makes two runs -comparable: the second run's artifact, with `volatile` removed, is identical to this one. The -signature is zero bytes, because nothing on the store path verifies one. +`[1,1,1,1,1,1,1,1,7,7]` taken at `(i % 200 + i / 200) % 10` — the author's ordinal plus the block +the event falls in, so every author writes both kinds while every 200-event block keeps the +cycle's proportions — `created_at = 1700000000 - (i % 2592000)`, a 256-byte content of the index +in hex then `x`, and one tag `["t", "bench-{i % 20}"]` over 20 values. The run recorded here used +seed 7. Identical input produces identical bytes, which is what makes two runs comparable: the +second run's artifact, with `volatile` removed, is identical to this one. The signature is zero +bytes, because nothing on the store path verifies one. ### D2 The two write shapes @@ -99,34 +133,42 @@ path in `crates/nostream-storage/src/lmdb/events.rs`: header of each candidate (`docs/rewrite/decisions/0011-lmdb-backend.md:61-73`) and therefore scales with the number of matches rather than with the page. -`count` is the shape that shows the difference: its median is a fraction of a millisecond while -its tail is the width of the corpus, because the first iterations count every kind-1 event. +Every window is derived from the corpus's own `created_at` span, so every iteration matches +events: `count` reads 1020000 rows over its 50 iterations and its median is a real scan of +milliseconds, not the empty range a window sized from the calendar month produced. ### D4 Concurrency, warm-up, and what a timing is -Concurrency is 1: one writer and one reader, no concurrent load, no background traffic. There -is no warm-up pass and the first iteration counts, so the figures include the cost a cold page -cache adds. A timing is the repository call alone — one `create`, one `create_many` batch, one -filter query, one count — measured around the await at the call site, with the corpus generation -outside it. Nothing here is a socket round trip: the wire is out of scope. +Concurrency is 1: one writer and one reader, no concurrent load, no background traffic. There is +no warm-up pass and the first iteration counts. A timing is the repository call alone — one +`create`, one `create_many` batch, one filter query, one count — measured around the await at the +call site, with the corpus generation outside it. Nothing here is a socket round trip: the wire is +out of scope. -The write shapes measure LMDB's synchronous commit, since the environment is opened with default -flags (`crates/nostream-storage/src/backend.rs`). On this shared host they vary between runs of -one command by several times; the figures above are one recorded run, not a bound, and a reader -comparing two hosts should compare the read shapes first. +The reads are warm, not cold: the store is written immediately before it is read, and 94490624 +bytes of `data.mdb` fits this host's memory, so a read shape pays the page cache's hit rather +than its miss. A cold-cache run is a different measurement and this rig does not make one. + +The write shapes are not stable between repeats, and the band above is the evidence rather than a +claim about it: `create`'s per-second rate spans 85 to 270 across the three repeats. The read +shapes move much less — their bands are a fraction of that width — except `read_back`, which is +one operation per repeat and so is a single sample each time. The cost being timed for the writes +is LMDB's synchronous commit, which waits on a shared host's disk, so the write rows are one +host's measurement under load 43.92 and not a bound. A reader comparing two hosts should compare +the read shapes first. ### D5 The corpora measured, and the ones that were not -Measured here: 50000 events, seed 7, on the store the harness creates under a temporary -directory. The harness's default ceiling is what keeps a mistyped corpus from filling a disk: a -run above it is refused before the store is touched, with the projected store size printed in -bytes and `--allow-large-corpus` named as the override. +Measured here: 50000 events, seed 7, three repeats, on the store the harness creates under a +temporary directory. The harness's default ceiling is what keeps a mistyped corpus from filling a +disk: a run above it is refused before the store is touched, with the projected store size printed +in bytes and `--allow-large-corpus` named as the override. -The gate's 1M and 10M corpora (#868) were not measured here: this host had 19 GB free at run +The gate's 1M and 10M corpora (#868) were not measured here: this host had 12 GB free at run time, and the store's own measurement projects: -projection: 1M events (#868) x 1883.8 bytes/event = 1883800000 bytes -projection: 10M events (#868) x 1883.8 bytes/event = 18838000000 bytes +projection: 1M events (#868) x 1889.8 bytes/event = 1889800000 bytes +projection: 10M events (#868) x 1889.8 bytes/event = 18898000000 bytes Both are projections from this run's bytes per event, not measurements, and the 1M run alone (#868) would need the `--allow-large-corpus` override on a host with room for it. @@ -138,15 +180,16 @@ The second Rust backend is the same `EventRepository` over the same workload, ru daemon, no `psql` and no Postgres server, so the harness refuses the run rather than skipping it (`PARITY_ADMIN_URL must name an administrative database, …`). -CI reaches it, because CI's `Rust Checks` job already runs a Postgres service. The step is named -`Benchmark harness against Postgres` in `.github/workflows/checks.yml`, and it runs the same -binary and the same `--verify` in the dev profile; its timings are cited nowhere. On a host with -Postgres the number comes from: +CI reaches it, because CI's `Rust Checks` job already runs a Postgres service. Two steps in +`.github/workflows/checks.yml` carry the rig there: `Benchmark harness against Postgres` runs the +same binary and the same `--verify` in the dev profile, and its timings are cited nowhere; and +`Benchmark harness unit tests` runs the harness's own tests, which `cargo test --workspace` would +only have compiled. On a host with Postgres the number comes from: ``` PARITY_ADMIN_URL=postgres://postgres:postgres@host:5432/postgres \ cargo run --release -p nostream-storage --example bench -- \ - --backend postgres --events 50000 --seed 7 --verify --out /tmp/bench-postgres.json + --backend postgres --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-postgres.json ``` The Postgres arm drops and recreates the scratch database `nostream_bench_rust` on the server @@ -169,6 +212,22 @@ Postgres implementation and ingest ≥ 1×, at the 1M and 10M corpora (#868). Th compared with it. No ratio, floor or comparison against another backend appears in this document. +## How a run reports itself + +The harness's contract is three exit code values, the same ones `--help` states: + +- exit code 0 — the run completed, and with `--verify` every check passed. +- exit code 1 — a verify failure: one `verify failed: : expected , got ` line on + stderr per failed check, with the artifact written anyway so the failure can be read. +- exit code 2 — a usage error, a refusal, or a failure that stopped the run. + +A refusal is answered before the store is opened and prints one line: a corpus below the minimum +or above the ceiling, a `--out` directory that does not exist, a `--repeats` below one, a store +directory that already holds one, a Postgres run without `PARITY_ADMIN_URL`, or a running `rustc` +— a build on the same box distorts the numbers about threefold, so pass `--allow-busy-host` only +when the measurement is a smoke test. Progress goes to stderr, so stdout never carries anything a +script would parse. + ## Context from job 007, not this rig's numbers ADR 0003 records the Postgres figures one review session measured diff --git a/docs/rewrite/benchmarks/lmdb-50k-seed7.json b/docs/rewrite/benchmarks/lmdb-50k-seed7.json index f54ec343c..7f9a1cb5d 100644 --- a/docs/rewrite/benchmarks/lmdb-50k-seed7.json +++ b/docs/rewrite/benchmarks/lmdb-50k-seed7.json @@ -21,12 +21,12 @@ }, { "count": 200, - "rows": 16000, + "rows": 20000, "shape": "author_kind" }, { "count": 200, - "rows": 100000, + "rows": 99602, "shape": "kind_since" }, { @@ -36,7 +36,7 @@ }, { "count": 50, - "rows": 40000, + "rows": 1020000, "shape": "count" } ], @@ -45,70 +45,176 @@ "arch": "x86_64", "cpu_count": 4, "cpu_model": "Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz", - "load_1min": 43.34, + "load_1min": 43.92, "os": "linux", "profile": "release" }, + "repeats": { + "author_kind": { + "per_second": { + "median": 2943, + "p10": 2729, + "p90": 3131 + }, + "rows_per_second": { + "median": 294334, + "p10": 272966, + "p90": 313116 + } + }, + "by_id": { + "per_second": { + "median": 39131, + "p10": 37757, + "p90": 47653 + }, + "rows_per_second": { + "median": 39131, + "p10": 37757, + "p90": 47653 + } + }, + "count": { + "per_second": { + "median": 98, + "p10": 94, + "p90": 105 + }, + "rows_per_second": { + "median": 2012445, + "p10": 1922779, + "p90": 2142195 + } + }, + "create": { + "per_second": { + "median": 243, + "p10": 85, + "p90": 270 + }, + "rows_per_second": { + "median": 243, + "p10": 85, + "p90": 270 + } + }, + "create_many": { + "per_second": { + "median": 20, + "p10": 16, + "p90": 44 + }, + "rows_per_second": { + "median": 10009, + "p10": 8345, + "p90": 22483 + } + }, + "kind_since": { + "per_second": { + "median": 678, + "p10": 651, + "p90": 700 + }, + "rows_per_second": { + "median": 338042, + "p10": 324696, + "p90": 348817 + } + }, + "read_back": { + "per_second": { + "median": 48, + "p10": 36, + "p90": 52 + }, + "rows_per_second": { + "median": 2433800, + "p10": 1802711, + "p90": 2649287 + } + }, + "tag": { + "per_second": { + "median": 3315, + "p10": 3308, + "p90": 3447 + }, + "rows_per_second": { + "median": 331543, + "p10": 330846, + "p90": 344750 + } + } + }, "store": { - "bytes_per_event": 1883, - "data_bytes": 94191616 + "bytes_per_event": 1889, + "data_bytes": 94490624 }, "timings": { "author_kind": { "ops": 200, - "p50_us": 320, - "p95_us": 435, - "p99_us": 552, - "per_second": 3610 + "p50_us": 332, + "p95_us": 395, + "p99_us": 416, + "per_second": 2943, + "rows_per_second": 294334 }, "by_id": { "ops": 200, - "p50_us": 20, - "p95_us": 23, - "p99_us": 71, - "per_second": 46674 + "p50_us": 22, + "p95_us": 53, + "p99_us": 64, + "per_second": 37757, + "rows_per_second": 37757 }, "count": { "ops": 50, - "p50_us": 7, - "p95_us": 12, - "p99_us": 18426, - "per_second": 2654 + "p50_us": 9564, + "p95_us": 19514, + "p99_us": 21805, + "per_second": 94, + "rows_per_second": 1922779 }, "create": { "ops": 1000, - "p50_us": 3923, - "p95_us": 4686, - "p99_us": 5419, - "per_second": 254 + "p50_us": 3726, + "p95_us": 6475, + "p99_us": 8192, + "per_second": 243, + "rows_per_second": 243 }, "create_many": { "ops": 98, - "p50_us": 27293, - "p95_us": 39467, - "p99_us": 48502, - "per_second": 35 + "p50_us": 41717, + "p95_us": 100578, + "p99_us": 1097356, + "per_second": 16, + "rows_per_second": 8345 }, "kind_since": { "ops": 200, - "p50_us": 1481, - "p95_us": 1697, - "p99_us": 2312, - "per_second": 663 + "p50_us": 1439, + "p95_us": 2092, + "p99_us": 2319, + "per_second": 651, + "rows_per_second": 324696 }, "read_back": { "ops": 1, - "p50_us": 19174, - "p95_us": 19174, - "p99_us": 19174, - "per_second": 52 + "p50_us": 20544, + "p95_us": 20544, + "p99_us": 20544, + "per_second": 48, + "rows_per_second": 2433800 }, "tag": { "ops": 200, "p50_us": 272, - "p95_us": 335, - "p99_us": 426, - "per_second": 3594 + "p95_us": 425, + "p99_us": 478, + "per_second": 3447, + "rows_per_second": 344750 } } }, @@ -143,6 +249,7 @@ "tag": 100 } }, + "repeats": 3, "writes": { "create_many_batch": 500, "ingest_events": 1000 From 37cb5f4feb59fd608d829a605152a10a8a06496f Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 01:14:39 -0500 Subject: [PATCH 05/14] fix(bench): refuse every repeat's store root and carry the percentile bands --- crates/nostream-storage/examples/bench.rs | 330 ++++++++++++++++------ 1 file changed, 247 insertions(+), 83 deletions(-) diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs index 6ac2a4e2d..8613e169e 100644 --- a/crates/nostream-storage/examples/bench.rs +++ b/crates/nostream-storage/examples/bench.rs @@ -19,7 +19,7 @@ use std::collections::BTreeMap; use std::error::Error; use std::fmt; -use std::path::PathBuf; +use std::path::{Path, PathBuf}; use std::process::ExitCode; use std::sync::Arc; use std::time::Instant; @@ -81,6 +81,10 @@ const TAG_LIMIT: u64 = 100; /// across repeats, which is the only way a reader can tell a measurement from a lucky one. const DEFAULT_REPEATS: u64 = 1; +/// The artifact's layout version: bumped when a field's meaning or position changes, so a reader +/// can tell which shape of document it holds. +const ARTIFACT_SCHEMA: u64 = 1; + /// The corpus ceiling a run may not cross without `--allow-large-corpus`. A 1M-event corpus is /// about 1.9 GB of `data.mdb` at the rate this rig measures, so the default refusal is what /// keeps a mistyped `--events` from filling a measuring host's disk. @@ -136,8 +140,10 @@ impl Backend { failed check, with the artifact written either way; 2 a usage error, a refusal, \ or a failure that stopped the run.\n\n\ --repeats N runs the measured phases N times, each against a fresh store (a \ - --store directory gets one repeat- subdirectory per run), and the artifact \ - carries the spread across the repeats. The Postgres arm drops and recreates the \ + --store directory gets one repeat- subdirectory per run, and every one of \ + those directories is refused if it already holds a store); the artifact carries \ + the band across the repeats, and a single repeat is one point reported three \ + times. The Postgres arm drops and recreates the \ scratch database named above on the server PARITY_ADMIN_URL points at, so run it \ only where that name is expendable." )] @@ -146,8 +152,8 @@ struct Arguments { #[arg(long, value_enum)] backend: Backend, - /// The corpus size: at least 1000, and at most 200000 without --allow-large-corpus. The - /// ingest phase takes the last 1000 events of it. + /// The corpus size: at least 1001 — the ingest phase takes the last 1000 events and the bulk + /// phase needs one more — and at most 200000 without --allow-large-corpus. #[arg(long)] events: u64, @@ -155,7 +161,9 @@ struct Arguments { #[arg(long, default_value_t = DEFAULT_SEED)] seed: u64, - /// How many times to run the measured phases; above 1 the artifact carries the spread. + /// How many times to run the measured phases, each against a fresh store. Above 1 the + /// artifact carries the band across the repeats; a single repeat is one point, reported + /// three times. #[arg(long, default_value_t = DEFAULT_REPEATS)] repeats: u64, @@ -168,8 +176,8 @@ struct Arguments { #[arg(long)] verify: bool, - /// The store root for --backend lmdb; it must not already hold a store, and a fresh - /// temporary directory is used when absent. + /// The store root for --backend lmdb; it must not already hold a store at any directory the + /// repeats would open, and a fresh temporary directory is used when absent. #[arg(long)] store: Option, @@ -282,6 +290,40 @@ impl Band { } } +/// One shape's spread across repeats: the same nearest-rank rule applied to the per-run rates and +/// to the per-run percentiles, so the number the cutover gate reads carries a band too. +struct ShapeBands { + per_second: Band, + rows_per_second: Band, + p50_us: Band, + p95_us: Band, + p99_us: Band, +} + +impl ShapeBands { + fn from_timings(timings: &[Timing]) -> Self { + let values = |pick: fn(&Timing) -> u64| -> Vec { timings.iter().map(pick).collect() }; + Self { + per_second: Band::from_values(&values(|timing| timing.per_second)), + rows_per_second: Band::from_values(&values(|timing| timing.rows_per_second)), + p50_us: Band::from_values(&values(|timing| timing.p50_us)), + p95_us: Band::from_values(&values(|timing| timing.p95_us)), + p99_us: Band::from_values(&values(|timing| timing.p99_us)), + } + } + + /// The five bands with the names the artifact gives them, in the order the document prints. + fn named(&self) -> [(&'static str, &Band); 5] { + [ + ("per_second", &self.per_second), + ("rows_per_second", &self.rows_per_second), + ("p50_us", &self.p50_us), + ("p95_us", &self.p95_us), + ("p99_us", &self.p99_us), + ] + } +} + /// The percentile the sample list carries: nearest rank over the sorted samples, index /// `ceil(p/100 * n) - 1` clamped into the list, in whole microseconds. fn nearest_rank(sorted: &[u64], p: u64) -> u64 { @@ -309,7 +351,7 @@ struct Report { event_count_read_back: u64, shapes: Vec, timings: BTreeMap, - bands: BTreeMap, + bands: BTreeMap, /// Every repeat's shapes, so verification can check they agree with the first. repeat_shapes: Vec>, } @@ -366,8 +408,15 @@ async fn run() -> Fallible { let arguments = Arguments::parse(); let plan = Plan::resolve(&arguments)?; + let store_note = match &plan.store { + Store::Temporary => "a temporary directory".to_owned(), + Store::Given(path) if plan.repeats == 1 => path.display().to_string(), + Store::Given(path) => { + format!("{} (one repeat- per repeat)", path.display()) + } + }; eprintln!( - "measuring {}: {} events at seed {}, {} repeat{}, artifact {}", + "measuring {}: {} events at seed {}, {} repeat{}, store {store_note}, artifact {}", plan.backend.name(), plan.events, plan.seed, @@ -379,8 +428,14 @@ async fn run() -> Fallible { let mut first: Option = None; let mut rest: Vec = Vec::new(); let mut store_size = None; + let mut loads: Vec = Vec::new(); for repeat in 0..plan.repeats { + // Sampled before each repeat, so the artifact can say what the host looked like for + // every run rather than only for the last one. + if let Some(load) = load_1min() { + loads.push(load); + } let (root, _temporary) = store_root(&plan, repeat)?; let store: Arc = match plan.backend { Backend::Lmdb => Arc::new(LmdbBackend::open(&root).await?), @@ -400,7 +455,9 @@ async fn run() -> Fallible { }; let measured = measure(store.as_ref(), plan.events, plan.seed, &label).await?; - if plan.backend == Backend::Lmdb { + // The repeats write the same corpus, so the first repeat's store stands for all of them; + // taking it here keeps this block and `timings` describing the same run. + if plan.backend == Backend::Lmdb && store_size.is_none() { let data_bytes = std::fs::metadata(store_file(&root))?.len(); store_size = Some(StoreSize { data_bytes, @@ -417,7 +474,7 @@ async fn run() -> Fallible { let first = first.ok_or_else(|| refusal("--repeats must be at least 1"))?; let report = Report::new(plan.backend, plan.seed, plan.events, first, rest); - let artifact = report.artifact(volatile_json(&report, store_size.as_ref())); + let artifact = report.artifact(volatile_json(&report, store_size.as_ref(), &loads)); let text = format!("{}\n", serde_json::to_string_pretty(&artifact)?); std::fs::write(&plan.out, text) @@ -448,8 +505,35 @@ fn plural(count: usize) -> &'static str { if count == 1 { "" } else { "s" } } -/// The root one repeat opens its store under: a fresh temporary directory each time, and one -/// subdirectory per repeat under a `--store` root when the phases run more than once. +/// The root one repeat opens its store under. The refusal in `given_store` and the open in +/// `store_root` both call this, so they cannot disagree about which directory a run writes to. +fn repeat_root(path: &Path, repeat: u64, repeats: u64) -> PathBuf { + if repeats == 1 { + path.to_path_buf() + } else { + path.join(format!("repeat-{repeat}")) + } +} + +/// Takes a `--store` root after refusing every directory the repeats would open into. A store left +/// by an earlier run is the one thing this flag cannot detect for the operator, and a repeat run +/// writes under `repeat-`, so each of those roots is checked and the message names the one +/// that was found. +fn given_store(path: &Path, repeats: u64) -> Fallible { + for repeat in 0..repeats { + let root = repeat_root(path, repeat, repeats); + if store_exists(&root) { + return Err(refusal(format!( + "--store {} already holds a store: {} exists. Choose another --store or remove it", + path.display(), + store_file(&root).display() + ))); + } + } + Ok(Store::Given(path.to_path_buf())) +} + +/// The root one repeat opens, with the temporary directory that keeps it alive when there is one. fn store_root(plan: &Plan, repeat: u64) -> Fallible<(PathBuf, Option)> { match &plan.store { Store::Temporary => { @@ -457,8 +541,7 @@ fn store_root(plan: &Plan, repeat: u64) -> Fallible<(PathBuf, Option Ok((path.clone(), None)), - Store::Given(path) => Ok((path.join(format!("repeat-{repeat}")), None)), + Store::Given(path) => Ok((repeat_root(path, repeat, plan.repeats), None)), } } @@ -471,11 +554,15 @@ impl Plan { )); } - if arguments.events < INGEST_EVENTS { + // The bulk phase is what is left after the ingest reserve, so a corpus of exactly the + // reserve would leave `create_many` no call to time and the shape's zero-row checks could + // never pass. One event above the reserve is the smallest run that measures everything. + if arguments.events <= INGEST_EVENTS { return Err(refusal(format!( - "--events {} is below the minimum of {INGEST_EVENTS}: the ingest phase measures \ - the last {INGEST_EVENTS} events", - arguments.events + "--events {} is below the minimum of {}: the ingest phase measures the last \ + {INGEST_EVENTS} events and the bulk phase needs at least one more to load", + arguments.events, + INGEST_EVENTS + 1 ))); } @@ -531,17 +618,7 @@ impl Plan { }; let store = match &arguments.store { - Some(path) => { - if store_exists(path) { - return Err(refusal(format!( - "--store {} already holds a store: {} exists. Choose another --store or \ - remove it", - path.display(), - store_file(path).display() - ))); - } - Store::Given(path.clone()) - } + Some(path) => given_store(path, arguments.repeats)?, None => Store::Temporary, }; @@ -940,6 +1017,7 @@ async fn measure( }); // 3. Read the whole corpus back once, which is what the unbounded count costs. + let reads_started = Instant::now(); let started = Instant::now(); let event_count_read_back = store.count_by_filters(&[Filter::default()]).await?; timings.insert( @@ -971,6 +1049,10 @@ async fn measure( count: COUNT_ITERATIONS, rows, }); + eprintln!( + "{label}read back and ran the five read shapes in {} ms", + reads_started.elapsed().as_millis() + ); Ok(Run { event_count_read_back, @@ -1009,15 +1091,15 @@ impl Report { let repeat_count = 1 + rest.len() as u64; let mut timings = BTreeMap::new(); - let mut rates: BTreeMap<&'static str, (Vec, Vec)> = BTreeMap::new(); + let mut per_repeat: BTreeMap<&'static str, Vec> = BTreeMap::new(); let mut repeat_shapes = Vec::new(); for run in std::iter::once(&first).chain(rest.iter()) { for (name, samples) in &run.timings { - let timing = Timing::from_samples(samples); - let entry = rates.entry(name).or_default(); - entry.0.push(timing.per_second); - entry.1.push(timing.rows_per_second); + per_repeat + .entry(name) + .or_default() + .push(Timing::from_samples(samples)); } repeat_shapes.push(run.shapes.clone()); } @@ -1025,17 +1107,9 @@ impl Report { timings.insert((*name).to_owned(), Timing::from_samples(samples)); } - let bands = rates + let bands = per_repeat .into_iter() - .map(|(name, (per_second, rows_per_second))| { - ( - name.to_owned(), - ( - Band::from_values(&per_second), - Band::from_values(&rows_per_second), - ), - ) - }) + .map(|(name, timings)| (name.to_owned(), ShapeBands::from_timings(&timings))) .collect(); Self { @@ -1064,6 +1138,7 @@ impl Report { }) .collect(); json!({ + "schema": ARTIFACT_SCHEMA, "backend": self.backend, "seed": self.seed, "events": self.events, @@ -1107,7 +1182,7 @@ fn workload_json(repeat_count: u64) -> Value { /// Everything that can differ between two runs: the host, the store's size, the timings and the /// spread across repeats. -fn volatile_json(report: &Report, store: Option<&StoreSize>) -> Value { +fn volatile_json(report: &Report, store: Option<&StoreSize>, loads: &[f64]) -> Value { let mut timings = Map::new(); for (name, timing) in &report.timings { timings.insert( @@ -1124,22 +1199,19 @@ fn volatile_json(report: &Report, store: Option<&StoreSize>) -> Value { } let mut repeats = Map::new(); - for (name, (per_second, rows_per_second)) in &report.bands { - repeats.insert( - name.clone(), - json!({ - "per_second": { - "median": per_second.median, - "p10": per_second.p10, - "p90": per_second.p90, - }, - "rows_per_second": { - "median": rows_per_second.median, - "p10": rows_per_second.p10, - "p90": rows_per_second.p90, - }, - }), - ); + for (name, bands) in &report.bands { + let mut entry = Map::new(); + for (metric, band) in bands.named() { + entry.insert( + metric.to_owned(), + json!({ + "median": band.median, + "p10": band.p10, + "p90": band.p90, + }), + ); + } + repeats.insert(name.clone(), Value::Object(entry)); } json!({ @@ -1149,7 +1221,8 @@ fn volatile_json(report: &Report, store: Option<&StoreSize>) -> Value { "os": std::env::consts::OS, "arch": std::env::consts::ARCH, "profile": if cfg!(debug_assertions) { "debug" } else { "release" }, - "load_1min": load_1min(), + "load_1min": loads.first().copied(), + "load_1min_by_repeat": loads, }, "store": match store { Some(size) => json!({ @@ -1350,11 +1423,8 @@ fn verify(report: &Report) -> Vec { ); } - for (name, (per_second, rows_per_second)) in &report.bands { - for (metric, band) in [ - ("per_second", per_second), - ("rows_per_second", rows_per_second), - ] { + for (name, bands) in &report.bands { + for (metric, band) in bands.named() { let ordered = band.p10 <= band.median && band.median <= band.p90; if !ordered { failures.push(VerifyFailure::new( @@ -1424,20 +1494,20 @@ mod tests { let bands = timings .keys() .map(|name| { + let band = |median: u64| Band { + median, + p10: median / 2, + p90: median + 1, + }; ( name.clone(), - ( - Band { - median: 1_000, - p10: 900, - p90: 1_100, - }, - Band { - median: 2_000, - p10: 1_800, - p90: 2_200, - }, - ), + ShapeBands { + per_second: band(1_000), + rows_per_second: band(2_000), + p50_us: band(10), + p95_us: band(20), + p99_us: band(30), + }, ) }) .collect(); @@ -1515,6 +1585,91 @@ mod tests { assert_eq!((band.p10, band.median, band.p90), (42, 42, 42)); } + #[test] + fn shape_bands_carry_the_percentiles_and_both_rates() { + let timings: Vec = [10, 20, 30] + .into_iter() + .map(|p95| Timing { + ops: 1, + p50_us: p95 - 5, + p95_us: p95, + p99_us: p95 + 5, + per_second: p95 * 100, + rows_per_second: p95 * 200, + }) + .collect(); + let bands = ShapeBands::from_timings(&timings); + assert_eq!( + (bands.p95_us.p10, bands.p95_us.median, bands.p95_us.p90), + (10, 20, 30) + ); + assert_eq!(bands.p50_us.median, 15); + assert_eq!(bands.p99_us.p90, 35); + assert_eq!(bands.per_second.median, 2_000); + assert_eq!(bands.rows_per_second.p90, 6_000); + } + + #[test] + fn a_repeat_run_refuses_a_store_left_by_an_earlier_run() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + let root = repeat_root(directory.path(), 1, 2); + std::fs::create_dir_all(root.join("lmdb")) + .ok() + .expect("a store dir"); + std::fs::write(store_file(&root), b"") + .ok() + .expect("a store file"); + + // One run writes to the root itself, which holds no store, so it is not refused. + assert!(given_store(directory.path(), 1).is_ok()); + // Two repeats open `repeat-1`, which does: the refusal names the directory it found. + let error = given_store(directory.path(), 2) + .err() + .expect("a refusal") + .to_string(); + assert!(error.contains("--store"), "{error}"); + assert!(error.contains("repeat-1"), "{error}"); + assert!( + error.contains(&store_file(&root).display().to_string()), + "{error}" + ); + } + + #[test] + fn a_single_run_refuses_a_populated_store() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + std::fs::create_dir_all(directory.path().join("lmdb")) + .ok() + .expect("a store dir"); + std::fs::write(store_file(directory.path()), b"") + .ok() + .expect("a store file"); + assert!(given_store(directory.path(), 1).is_err()); + } + + #[test] + fn the_smallest_accepted_corpus_leaves_a_bulk_load() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + let arguments = |events| Arguments { + backend: Backend::Lmdb, + events, + seed: DEFAULT_SEED, + repeats: 1, + out: directory.path().join("artifact.json"), + verify: false, + store: None, + allow_large_corpus: false, + allow_busy_host: true, + }; + + let error = Plan::resolve(&arguments(1_000)) + .err() + .expect("a refusal") + .to_string(); + assert!(error.contains("below the minimum of 1001"), "{error}"); + assert!(Plan::resolve(&arguments(1_001)).is_ok()); + } + #[test] fn corpus_is_identical_for_a_seed() { let first: Vec = (0..1_000).map(|index| corpus_event(index, 7)).collect(); @@ -1600,13 +1755,22 @@ mod tests { #[test] fn verify_rejects_a_band_out_of_order() { let mut report = valid_report(); - let (per_second, _) = report.bands.get_mut("count").expect("a count band"); + let count = report.bands.get_mut("count").expect("a count band"); // The median above the ninetieth percentile, while the tenth stays below it: only the // middle clause of the ordering catches this, so the test pins that clause too. - per_second.median = per_second.p90 + 1; + count.per_second.median = count.per_second.p90 + 1; let failures = verify(&report); assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); assert_eq!(failures[0].field, "volatile.repeats[count].per_second"); + + // The percentile bands are checked by the same rule: the p95 band is the one the gate + // reads, so it is the one this pins. + let mut report = valid_report(); + let count = report.bands.get_mut("count").expect("a count band"); + count.p95_us.median = count.p95_us.p90 + 1; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "volatile.repeats[count].p95_us"); } #[test] From 64d3f5eda5df1631053c73549bcb80ad5a9dc917 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 01:14:39 -0500 Subject: [PATCH 06/14] docs: quote the p95 band, define the exclusions and the percentile rule --- CLAUDE.md | 4 +- docs/rewrite/benchmarks.md | 185 ++++++++---- docs/rewrite/benchmarks/lmdb-50k-seed7.json | 304 ++++++++++++++------ 3 files changed, 345 insertions(+), 148 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 722f88561..b3ccf25e1 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -36,7 +36,7 @@ cargo test --workspace --all-features cargo build --workspace --all-features --release ``` -CI additionally runs four database- and example-backed checks. Three are the storage tests +CI additionally runs five database- and example-backed checks. Three are the storage tests ("Storage parity against Postgres"), against a `postgres:16-alpine` service; they are `#[ignore]`d so a checkout without a database still passes `cargo test --workspace`: @@ -50,7 +50,7 @@ cargo test -p nostream-storage --test migrations --test parity --test migration_ drop their own scratch databases — `migration_pg` seeds one and copies it into a temporary LMDB store. The fourth is the benchmark rig's Postgres arm ("Benchmark harness against Postgres"): it runs `crates/nostream-storage/examples/bench.rs` against a scratch database and proves the path -and `--verify`, and its numbers are cited nowhere. +and `--verify`, and its numbers are cited nowhere. The fifth, below, is the rig's own unit tests. The rig's own unit tests need their own command, because `cargo test --workspace` only *builds* an example target. CI runs it as "Benchmark harness unit tests", and so must you when you touch the diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index 25fd0241c..9f4f115ee 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -19,39 +19,43 @@ which needs a database this host does not have, and the TypeScript/Postgres colu |---|---| | Date | 2026-11-14 | | Machine | 4 CPUs, `Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz` | -| Load average, one minute | 43.92 | -| Free disk at run time | 12 GB (`df -h /`) | +| Load average, one minute | 43.32 (`volatile.machine.load_1min`, the first repeat's) | +| Free disk at run time | 8.6 GB (`df -h /`) | | Profile | `release` | | Repeats | 3 (`workload.repeats`) | -| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-lmdb-1.json` | +| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-lmdb-3.json` | | Artifact | `docs/rewrite/benchmarks/lmdb-50k-seed7.json` | The machine, the load average and the store's size are `volatile.machine` and `volatile.store` in that artifact. This host is shared: the load figure is other tenants' work on four cores, and the three repeats below measure what that does to the numbers rather than leaving it to a -sentence. +sentence. The load is sampled before every repeat, not once: `load_1min_by_repeat` holds `43.32`, +`43.27` and `43.25`, so the one-minute figure above is the first of three readings that agree. ## The LMDB numbers **Within one run.** One row per shape, from the artifact's `shapes` and the first repeat's `volatile.timings`. -| shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | -|---|---|---|---|---|---| -| `create_many` | 98 | 49000 | 41.7 | 100.6 | 1097.4 | -| `create` | 1000 | 1000 | 3.7 | 6.5 | 8.2 | -| `by_id` | 200 | 200 | 0.0 | 0.1 | 0.1 | -| `author_kind` | 200 | 20000 | 0.3 | 0.4 | 0.4 | -| `kind_since` | 200 | 99602 | 1.4 | 2.1 | 2.3 | -| `tag` | 200 | 20000 | 0.3 | 0.4 | 0.5 | -| `count` | 50 | 1020000 | 9.6 | 19.5 | 21.8 | -| `read_back` | 1 | 50000 | 20.5 | 20.5 | 20.5 | - -Every column here is the artifact's own integer printed as-is (the `count`, `rows` and `ops` -numbers), except the three percentile columns, which are the artifact's microsecond integers -printed in milliseconds with exactly one decimal, rounding half-up: `19 514` µs prints as `19.5`, -and `0` µs would print as `0.0`. `read_back` carries no `shapes` entry: it is the single -unbounded count the corpus is read back with, and its `rows` is `event_count_read_back`. +| shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | per_second | rows_per_second | +|---|---|---|---|---|---|---|---| +| `create_many` | 98 | 49000 | 29.6 | 37.3 | 41.4 | 34 | 17277 | +| `create` | 1000 | 1000 | 4.0 | 4.7 | 5.5 | 251 | 251 | +| `by_id` | 200 | 200 | 0.0 | 0.0 | 0.0 | 46500 | 46500 | +| `author_kind` | 200 | 20000 | 0.3 | 0.3 | 0.3 | 3408 | 340802 | +| `kind_since` | 200 | 99602 | 1.4 | 1.5 | 1.6 | 736 | 366841 | +| `tag` | 200 | 20000 | 0.3 | 0.3 | 0.3 | 3707 | 370727 | +| `count` | 50 | 1020000 | 9.2 | 17.3 | 18.5 | 107 | 2198669 | +| `read_back` | 1 | 50000 | 21.9 | 21.9 | 21.9 | 45 | 2283105 | + +Every column here is the artifact's own integer printed as-is (the `count`, `rows`, `ops`, +`per_second` and `rows_per_second` numbers), except the three percentile columns, which are the +artifact's microsecond integers printed in milliseconds with exactly one decimal, rounding +half-up: `30 449` µs prints as `30.4`. The cost of that rule is the `by_id` row, whose calls take +tens of microseconds and print as `0.0`; the artifact's integers are the measurement, and this +table is a reading of them. `read_back` carries no `shapes` entry: it is the single unbounded +count the corpus is read back with, and its `rows` is `event_count_read_back`. The rates are the +first repeat's, like the percentiles. `count` is one repository call. `rows` is the sum over the shape's calls, which is why `kind_since` shows 99602 rows at a limit of 500 — two hundred pages, most of them full — and why @@ -61,26 +65,36 @@ unbounded count the corpus is read back with, and its `rows` is `event_count_rea rig exists to publish: a point estimate from one run of a shared host is not a measurement of the store. -| shape | per_second median | p10 | p90 | rows_per_second median | p10 | p90 | -|---|---|---|---|---|---|---| -| `create_many` | 20 | 16 | 44 | 10009 | 8345 | 22483 | -| `create` | 243 | 85 | 270 | 243 | 85 | 270 | -| `by_id` | 39131 | 37757 | 47653 | 39131 | 37757 | 47653 | -| `author_kind` | 2943 | 2729 | 3131 | 294334 | 272966 | 313116 | -| `kind_since` | 678 | 651 | 700 | 338042 | 324696 | 348817 | -| `tag` | 3315 | 3308 | 3447 | 331543 | 330846 | 344750 | -| `count` | 98 | 94 | 105 | 2012445 | 1922779 | 2142195 | -| `read_back` | 48 | 36 | 52 | 2433800 | 1802711 | 2649287 | - -Every figure is the artifact's integer printed as-is: `median`, `p10` and `p90` are the -nearest-rank percentiles over the three repeats' rates, and the rule is the one the within-run -percentiles use, applied to three numbers instead of hundreds. +| shape | per_second median | p10 | p90 | rows_per_second median | p10 | p90 | p95 (ms) median | p10 | p90 | +|---|---|---|---|---|---|---|---|---|---| +| `create_many` | 48 | 34 | 48 | 24416 | 17277 | 24435 | 30.4 | 29.6 | 37.3 | +| `create` | 251 | 248 | 253 | 251 | 248 | 253 | 4.7 | 4.6 | 4.9 | +| `by_id` | 43047 | 41614 | 46500 | 43047 | 41614 | 46500 | 0.0 | 0.0 | 0.0 | +| `author_kind` | 3408 | 2940 | 3424 | 340802 | 294061 | 342483 | 0.3 | 0.3 | 0.4 | +| `kind_since` | 716 | 690 | 736 | 356779 | 343923 | 366841 | 1.6 | 1.5 | 1.6 | +| `tag` | 3438 | 3116 | 3707 | 343855 | 311623 | 370727 | 0.3 | 0.3 | 0.4 | +| `count` | 102 | 101 | 107 | 2100528 | 2061001 | 2198669 | 18.4 | 17.3 | 19.6 | +| `read_back` | 45 | 20 | 53 | 2283105 | 1040084 | 2661131 | 21.9 | 18.8 | 48.1 | + +Every figure is the artifact's integer printed as-is, except the three `p95` columns, which are +`volatile.repeats..p95_us` in milliseconds under the same one-decimal rounding as the +table above. All five bands are in the artifact — `p50_us`, `p95_us` and `p99_us` beside the two rates — +because the cutover gate reads a p95, and a band on the rates alone would leave the number it +compares without one. + +**What a band is.** Each band is the nearest-rank percentile of the shape's per-repeat values: +sort the `n` values ascending and take the one at position `ceil(p ÷ 100 × n)` — the first value +whose position reaches `p` per cent of the samples. With three repeats the tenth percentile is +the smallest value, the median the middle one and the ninetieth the largest; with two, the median +is the lower of the two rather than their mean. One repeat is a point, not a band: the artifact +still carries the three fields, and all three hold that single value, so a one-repeat artifact's +band is the measurement printed three times and is not evidence of stability. `per_second` counts operations: one event for `create`, one five-hundred-event batch for `create_many`, one filter query for a read shape, one count for `count`. `rows_per_second` counts the rows those operations returned. The two differ for `create_many` by its batch size, which is -why the same column reads 20 operations and 10009 rows, and they coincide for `create` and for -the read shapes that always return one row per operation. +why the same column reads 48 operations and 24416 rows, and they coincide for `create` and for the +read shapes that always return one row per operation. **The store.** @@ -88,7 +102,10 @@ the read shapes that always return one row per operation. |---|---|---| | 50000 | 94490624 | 1889.8 | -`events` and `data_bytes` are the artifact's integers as-is; `bytes_per_event` is +These are `volatile.store`, read from the first repeat's store: the repeats write the same corpus +in the same order, so the first one's size stands for all three, and taking it there keeps this +block describing the same repeat as `volatile.timings` and `shapes`. `events` and `data_bytes` are +the artifact's integers as-is; `bytes_per_event` is `data_bytes / events` rounded to one decimal, so it is not the artifact's own truncated integer. `data_bytes` is `data.mdb`'s length, which includes pages LMDB allocated and has not reused yet, so it overstates live bytes — the safe direction for the disk arithmetic in D5. @@ -149,13 +166,28 @@ The reads are warm, not cold: the store is written immediately before it is read bytes of `data.mdb` fits this host's memory, so a read shape pays the page cache's hit rather than its miss. A cold-cache run is a different measurement and this rig does not make one. -The write shapes are not stable between repeats, and the band above is the evidence rather than a -claim about it: `create`'s per-second rate spans 85 to 270 across the three repeats. The read -shapes move much less — their bands are a fraction of that width — except `read_back`, which is -one operation per repeat and so is a single sample each time. The cost being timed for the writes -is LMDB's synchronous commit, which waits on a shared host's disk, so the write rows are one -host's measurement under load 43.92 and not a bound. A reader comparing two hosts should compare -the read shapes first. +Each repeat writes the whole corpus into a fresh store and reads it with the same corpus-derived +windows, so a repeat's rate is the same workload under a different moment on the host, and the +band across repeats is the spread of that moment — not a spread of the workload. + +The two rates divide by the time the shape's calls took, added up, not by its median: a shape +whose few slow calls carry the total has a rate below `1 / p50`, so a reader who recomputes a rate +from the percentile columns above gets a number the artifact does not record. + +On this run the read shapes and `create` agreed closely between repeats — `create`'s per-second +band spans 248 to 253 — which is what makes the write rows worth reading as a measurement of this +host on this day. `create_many`'s band is the widest of them: one repeat loaded at 34 batches per +second where the other two reached 48, and its `p95` band runs from 29.6 to 37.3 ms around a +median of 30.4. That is one repeat's writes waiting on the host's disk rather than the same wait +landing in all three. A repeat can stall altogether — one earlier run of this same +command on this host had a single repeat's ingest take an order of magnitude longer than the other +two, and its `create` band was several times as wide as this one's — so the band, and not one +run's number, is what the tables above are for. + +The cost being timed for the writes is LMDB's synchronous commit, which waits on a shared host's +disk; `create_many` also copies the batch and writes its indexes, and this rig does not separate +the two. The write rows are one host's measurement at load 43.32 and not a bound. A reader +comparing two hosts should compare the read shapes first. ### D5 The corpora measured, and the ones that were not @@ -164,14 +196,17 @@ temporary directory. The harness's default ceiling is what keeps a mistyped corp disk: a run above it is refused before the store is touched, with the projected store size printed in bytes and `--allow-large-corpus` named as the override. -The gate's 1M and 10M corpora (#868) were not measured here: this host had 12 GB free at run -time, and the store's own measurement projects: +The gate's 1M and 10M corpora (#868) were not measured here, and disk space is not the reason: +the projections below put the 1M corpus inside the 8.6 GB this host had free, and only the 10M +corpus outside it. They are #868's runs because they are the gate's corpora, and this job's scope +is the recorded one; the cost of the `count` shape, which scans its whole match set per iteration, +grows with the corpus and belongs in that run's budget too. projection: 1M events (#868) x 1889.8 bytes/event = 1889800000 bytes projection: 10M events (#868) x 1889.8 bytes/event = 18898000000 bytes -Both are projections from this run's bytes per event, not measurements, and the 1M run alone -(#868) would need the `--allow-large-corpus` override on a host with room for it. +Both are projections from this run's bytes per event, not measurements, and each would need the +`--allow-large-corpus` override on a host with room for it. ### D6 The Rust/Postgres column: not measured in this environment @@ -207,10 +242,45 @@ Docker daemon. ### D8 No threshold is asserted This document carries evidence, not a pass/fail. The gate is #868: REQ p95 within 1.5× of the -Postgres implementation and ingest ≥ 1×, at the 1M and 10M corpora (#868). The board's -50 000 events/s figure is a target tracked in #864, not a measurement, and nothing here is -compared with it. No ratio, floor or comparison against another backend appears in this -document. +Postgres implementation and ingest ≥ 1×, at the 1M and 10M corpora (#868). That p95 comparison +reads the band, not one run: the artifact carries `p95_us` per shape across repeats so the median +and the width are both available, and a single run's p95 inside a band as wide as `read_back`'s +above cannot decide a margin of one and a half on its own. The board's 50 000 events/s figure is a +target tracked in #864, not a measurement, and nothing here is compared with it. No ratio, floor +or comparison against another backend appears in this document. + +The artifact's `schema` integer is its layout version: the block above is schema 1, and a field +whose meaning or position changes takes the next number so a consumer can tell which shape of +document it holds. + +### D9 The deliberate exclusions, and where the workload is defined + +The workload is one shape of the relay's traffic, and what it leaves out was decided rather than +overlooked. Its definition is the constants at the top of +`crates/nostream-storage/examples/bench.rs` — one file, and the workload's single definition — +echoed into the artifact's `workload` object so a published result can be traced back to the +definition that produced it. A change to any of those constants makes a new workload, not a new row +in the tables above, and a result from a changed workload is not comparable with this one. + +Not measured, and why: + +- **Replaceable kinds and `upsert`.** Kinds 0, 3, 41 and 10000–19999 reach `upsert` + (`crates/nostream-storage/src/repositories.rs:494`), because the relay replaces the current + version of such an event rather than appending another. The corpus holds kinds 1 and 7 only, so + the rig times the append path; adding `upsert` would change what a corpus row means, not just + add a shape. +- **Retention and purge.** `delete_expired_and_retained` and the reconciliation scans are separate + calls over the same tables, and a corpus written in one sweep measures none of them. +- **NIP-50 `search`.** Not on the base this rig builds against, and a full-text scan is a + different access path from the five filter shapes in D3. +- **Transactions.** The Postgres arm pays for serializable transaction groups the LMDB arm does + not have; the rig times repository calls, not the grouping above them. +- **Concurrency above one.** One writer, one reader, `concurrency: 1`: no concurrent readers, no + subscriber fan-out and no live dispatch. A store's cost under contention is a different figure. +- **The wire.** Nothing here is a socket round trip (D4). + +A later job that adds any of these is measuring a different workload, and should say so where its +numbers are published instead of comparing them with the tables above. ## How a run reports itself @@ -222,11 +292,12 @@ The harness's contract is three exit code values, the same ones `--help` states: - exit code 2 — a usage error, a refusal, or a failure that stopped the run. A refusal is answered before the store is opened and prints one line: a corpus below the minimum -or above the ceiling, a `--out` directory that does not exist, a `--repeats` below one, a store -directory that already holds one, a Postgres run without `PARITY_ADMIN_URL`, or a running `rustc` -— a build on the same box distorts the numbers about threefold, so pass `--allow-busy-host` only -when the measurement is a smoke test. Progress goes to stderr, so stdout never carries anything a -script would parse. +— the ingest phase takes the corpus's last thousand events, and the bulk phase needs one more to +have anything to load — or above the ceiling, a `--out` directory that does not exist, a +`--repeats` below one, a `--store` directory that already holds a store at any path the repeats +would open, a Postgres run without `PARITY_ADMIN_URL`, or a running `rustc` — a build on the same +box distorts the numbers about threefold, so pass `--allow-busy-host` only when the measurement is +a smoke test. Progress goes to stderr, so stdout never carries anything a script would parse. ## Context from job 007, not this rig's numbers diff --git a/docs/rewrite/benchmarks/lmdb-50k-seed7.json b/docs/rewrite/benchmarks/lmdb-50k-seed7.json index 7f9a1cb5d..fdbd3d96c 100644 --- a/docs/rewrite/benchmarks/lmdb-50k-seed7.json +++ b/docs/rewrite/benchmarks/lmdb-50k-seed7.json @@ -2,6 +2,7 @@ "backend": "lmdb", "event_count_read_back": 50000, "events": 50000, + "schema": 1, "seed": 7, "shapes": [ { @@ -45,105 +46,230 @@ "arch": "x86_64", "cpu_count": 4, "cpu_model": "Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz", - "load_1min": 43.92, + "load_1min": 43.32, + "load_1min_by_repeat": [ + 43.32, + 43.27, + 43.25 + ], "os": "linux", "profile": "release" }, "repeats": { "author_kind": { + "p50_us": { + "median": 291, + "p10": 289, + "p90": 320 + }, + "p95_us": { + "median": 313, + "p10": 308, + "p90": 435 + }, + "p99_us": { + "median": 353, + "p10": 339, + "p90": 499 + }, "per_second": { - "median": 2943, - "p10": 2729, - "p90": 3131 + "median": 3408, + "p10": 2940, + "p90": 3424 }, "rows_per_second": { - "median": 294334, - "p10": 272966, - "p90": 313116 + "median": 340802, + "p10": 294061, + "p90": 342483 } }, "by_id": { + "p50_us": { + "median": 19, + "p10": 19, + "p90": 23 + }, + "p95_us": { + "median": 25, + "p10": 25, + "p90": 28 + }, + "p99_us": { + "median": 34, + "p10": 31, + "p90": 152 + }, "per_second": { - "median": 39131, - "p10": 37757, - "p90": 47653 + "median": 43047, + "p10": 41614, + "p90": 46500 }, "rows_per_second": { - "median": 39131, - "p10": 37757, - "p90": 47653 + "median": 43047, + "p10": 41614, + "p90": 46500 } }, "count": { + "p50_us": { + "median": 9381, + "p10": 9206, + "p90": 9732 + }, + "p95_us": { + "median": 18358, + "p10": 17250, + "p90": 19570 + }, + "p99_us": { + "median": 19103, + "p10": 18524, + "p90": 21493 + }, "per_second": { - "median": 98, - "p10": 94, - "p90": 105 + "median": 102, + "p10": 101, + "p90": 107 }, "rows_per_second": { - "median": 2012445, - "p10": 1922779, - "p90": 2142195 + "median": 2100528, + "p10": 2061001, + "p90": 2198669 } }, "create": { + "p50_us": { + "median": 3980, + "p10": 3954, + "p90": 3985 + }, + "p95_us": { + "median": 4717, + "p10": 4632, + "p90": 4941 + }, + "p99_us": { + "median": 5534, + "p10": 5013, + "p90": 6389 + }, "per_second": { - "median": 243, - "p10": 85, - "p90": 270 + "median": 251, + "p10": 248, + "p90": 253 }, "rows_per_second": { - "median": 243, - "p10": 85, - "p90": 270 + "median": 251, + "p10": 248, + "p90": 253 } }, "create_many": { + "p50_us": { + "median": 19640, + "p10": 18796, + "p90": 29611 + }, + "p95_us": { + "median": 30449, + "p10": 29637, + "p90": 37269 + }, + "p99_us": { + "median": 35338, + "p10": 32829, + "p90": 41430 + }, "per_second": { - "median": 20, - "p10": 16, - "p90": 44 + "median": 48, + "p10": 34, + "p90": 48 }, "rows_per_second": { - "median": 10009, - "p10": 8345, - "p90": 22483 + "median": 24416, + "p10": 17277, + "p90": 24435 } }, "kind_since": { + "p50_us": { + "median": 1377, + "p10": 1350, + "p90": 1439 + }, + "p95_us": { + "median": 1585, + "p10": 1460, + "p90": 1595 + }, + "p99_us": { + "median": 1703, + "p10": 1601, + "p90": 1724 + }, "per_second": { - "median": 678, - "p10": 651, - "p90": 700 + "median": 716, + "p10": 690, + "p90": 736 }, "rows_per_second": { - "median": 338042, - "p10": 324696, - "p90": 348817 + "median": 356779, + "p10": 343923, + "p90": 366841 } }, "read_back": { + "p50_us": { + "median": 21900, + "p10": 18789, + "p90": 48073 + }, + "p95_us": { + "median": 21900, + "p10": 18789, + "p90": 48073 + }, + "p99_us": { + "median": 21900, + "p10": 18789, + "p90": 48073 + }, "per_second": { - "median": 48, - "p10": 36, - "p90": 52 + "median": 45, + "p10": 20, + "p90": 53 }, "rows_per_second": { - "median": 2433800, - "p10": 1802711, - "p90": 2649287 + "median": 2283105, + "p10": 1040084, + "p90": 2661131 } }, "tag": { + "p50_us": { + "median": 286, + "p10": 265, + "p90": 308 + }, + "p95_us": { + "median": 328, + "p10": 301, + "p90": 406 + }, + "p99_us": { + "median": 362, + "p10": 349, + "p90": 557 + }, "per_second": { - "median": 3315, - "p10": 3308, - "p90": 3447 + "median": 3438, + "p10": 3116, + "p90": 3707 }, "rows_per_second": { - "median": 331543, - "p10": 330846, - "p90": 344750 + "median": 343855, + "p10": 311623, + "p90": 370727 } } }, @@ -154,67 +280,67 @@ "timings": { "author_kind": { "ops": 200, - "p50_us": 332, - "p95_us": 395, - "p99_us": 416, - "per_second": 2943, - "rows_per_second": 294334 + "p50_us": 291, + "p95_us": 308, + "p99_us": 339, + "per_second": 3408, + "rows_per_second": 340802 }, "by_id": { "ops": 200, - "p50_us": 22, - "p95_us": 53, - "p99_us": 64, - "per_second": 37757, - "rows_per_second": 37757 + "p50_us": 19, + "p95_us": 25, + "p99_us": 34, + "per_second": 46500, + "rows_per_second": 46500 }, "count": { "ops": 50, - "p50_us": 9564, - "p95_us": 19514, - "p99_us": 21805, - "per_second": 94, - "rows_per_second": 1922779 + "p50_us": 9206, + "p95_us": 17250, + "p99_us": 18524, + "per_second": 107, + "rows_per_second": 2198669 }, "create": { "ops": 1000, - "p50_us": 3726, - "p95_us": 6475, - "p99_us": 8192, - "per_second": 243, - "rows_per_second": 243 + "p50_us": 3954, + "p95_us": 4717, + "p99_us": 5534, + "per_second": 251, + "rows_per_second": 251 }, "create_many": { "ops": 98, - "p50_us": 41717, - "p95_us": 100578, - "p99_us": 1097356, - "per_second": 16, - "rows_per_second": 8345 + "p50_us": 29611, + "p95_us": 37269, + "p99_us": 41430, + "per_second": 34, + "rows_per_second": 17277 }, "kind_since": { "ops": 200, - "p50_us": 1439, - "p95_us": 2092, - "p99_us": 2319, - "per_second": 651, - "rows_per_second": 324696 + "p50_us": 1350, + "p95_us": 1460, + "p99_us": 1601, + "per_second": 736, + "rows_per_second": 366841 }, "read_back": { "ops": 1, - "p50_us": 20544, - "p95_us": 20544, - "p99_us": 20544, - "per_second": 48, - "rows_per_second": 2433800 + "p50_us": 21900, + "p95_us": 21900, + "p99_us": 21900, + "per_second": 45, + "rows_per_second": 2283105 }, "tag": { "ops": 200, - "p50_us": 272, - "p95_us": 425, - "p99_us": 478, - "per_second": 3447, - "rows_per_second": 344750 + "p50_us": 265, + "p95_us": 301, + "p99_us": 349, + "per_second": 3707, + "rows_per_second": 370727 } } }, From 817a0cdd7e56750751de3baeae6e3f70a853d7e9 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 01:41:55 -0500 Subject: [PATCH 07/14] docs: correct the rig's exclusions, its disk arithmetic and its uncited multipliers --- docs/rewrite/benchmarks.md | 69 ++++++++++++++++++++++++-------------- 1 file changed, 44 insertions(+), 25 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index 9f4f115ee..78b67bbce 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -78,9 +78,9 @@ store. Every figure is the artifact's integer printed as-is, except the three `p95` columns, which are `volatile.repeats..p95_us` in milliseconds under the same one-decimal rounding as the -table above. All five bands are in the artifact — `p50_us`, `p95_us` and `p99_us` beside the two rates — -because the cutover gate reads a p95, and a band on the rates alone would leave the number it -compares without one. +table above. All five bands are in the artifact — `p50_us`, `p95_us` and `p99_us` beside the two +rates — because the cutover gate reads a p95, and a band on the rates alone would leave the number +it compares without one. **What a band is.** Each band is the nearest-rank percentile of the shape's per-repeat values: sort the `n` values ascending and take the one at position `ceil(p ÷ 100 × n)` — the first value @@ -179,10 +179,9 @@ band spans 248 to 253 — which is what makes the write rows worth reading as a host on this day. `create_many`'s band is the widest of them: one repeat loaded at 34 batches per second where the other two reached 48, and its `p95` band runs from 29.6 to 37.3 ms around a median of 30.4. That is one repeat's writes waiting on the host's disk rather than the same wait -landing in all three. A repeat can stall altogether — one earlier run of this same -command on this host had a single repeat's ingest take an order of magnitude longer than the other -two, and its `create` band was several times as wide as this one's — so the band, and not one -run's number, is what the tables above are for. +landing in all three. A repeat on a shared host can stall outright, and nothing in the rig +prevents it, so the band — and not one run's number — is what the tables above are for. A run +whose band is wider than this one's is a reading of a busier host, not of a slower store. The cost being timed for the writes is LMDB's synchronous commit, which waits on a shared host's disk; `create_many` also copies the batch and writes its indexes, and this rig does not separate @@ -196,10 +195,11 @@ temporary directory. The harness's default ceiling is what keeps a mistyped corp disk: a run above it is refused before the store is touched, with the projected store size printed in bytes and `--allow-large-corpus` named as the override. -The gate's 1M and 10M corpora (#868) were not measured here, and disk space is not the reason: -the projections below put the 1M corpus inside the 8.6 GB this host had free, and only the 10M -corpus outside it. They are #868's runs because they are the gate's corpora, and this job's scope -is the recorded one; the cost of the `count` shape, which scans its whole match set per iteration, +The gate's 1M and 10M corpora (#868) were not measured here. Disk space rules the 10M corpus out +on this host — the projection below is more than twice the 8.6 GB the run recorded free — and does +not rule the 1M corpus out, whose projection fits inside it: 1M is #868's run because it is the +gate's corpus and this job's scope is the recorded one, and it needs `--allow-large-corpus` +wherever it runs. The cost of the `count` shape, which scans its whole match set per iteration, grows with the corpus and belongs in that run's budget too. projection: 1M events (#868) x 1889.8 bytes/event = 1889800000 bytes @@ -245,13 +245,19 @@ This document carries evidence, not a pass/fail. The gate is #868: REQ p95 withi Postgres implementation and ingest ≥ 1×, at the 1M and 10M corpora (#868). That p95 comparison reads the band, not one run: the artifact carries `p95_us` per shape across repeats so the median and the width are both available, and a single run's p95 inside a band as wide as `read_back`'s -above cannot decide a margin of one and a half on its own. The board's 50 000 events/s figure is a -target tracked in #864, not a measurement, and nothing here is compared with it. No ratio, floor -or comparison against another backend appears in this document. - -The artifact's `schema` integer is its layout version: the block above is schema 1, and a field -whose meaning or position changes takes the next number so a consumer can tell which shape of -document it holds. +above cannot decide a margin of one and a half on its own. #868's rule does not say which statistic +of the band the ratio applies to, and a band that straddles the threshold — one repeat inside the +margin, another outside it — is exactly the case that rule has to settle; this document measures +and does not decide it. The board's 50 000 events/s figure is a target tracked in #864, not a +measurement, and nothing here is compared with it. No ratio, floor or comparison against another +backend appears in this document. + +The artifact's `schema` integer is its layout version: the artifact this document reads — the +committed `docs/rewrite/benchmarks/lmdb-50k-seed7.json` — is schema 1, and a field whose meaning +or position changes takes the next number, so a consumer can tell which shape of document it holds. +A consumer that meets an unknown value should refuse the artifact and name the version it found, +the way `crates/nostream-storage/src/lmdb/encoding.rs:184-193` refuses a value written by a +different row format rather than reading it as if it were this one. ### D9 The deliberate exclusions, and where the workload is defined @@ -264,15 +270,28 @@ in the tables above, and a result from a changed workload is not comparable with Not measured, and why: -- **Replaceable kinds and `upsert`.** Kinds 0, 3, 41 and 10000–19999 reach `upsert` - (`crates/nostream-storage/src/repositories.rs:494`), because the relay replaces the current - version of such an event rather than appending another. The corpus holds kinds 1 and 7 only, so - the rig times the append path; adding `upsert` would change what a corpus row means, not just - add a shape. +- **Replaceable kinds and `upsert`.** Kinds 0, 3, 41, 10000–19999 and 30000–39999 reach `upsert` + (`crates/nostream-storage/src/repositories.rs:494`) — the parameterized replaceable range + through `crates/nostream-relay/src/strategies/parameterized_replaceable.rs:35`, reached from + `strategies/mod.rs:102-103` — because the relay replaces the current version of such an event + rather than appending another. Ephemeral kinds 20000–29999 are the other half, never stored at + all: the relay acknowledges and broadcasts them with no repository call + (`strategies/ephemeral.rs`, `crates/nostream-core/src/event.rs:247-250`). The corpus holds kinds + 1 and 7 only, so the rig times the append path, and every stored kind it lacks travels a + different repository call; adding one would change what a corpus row means, not just add a + shape. - **Retention and purge.** `delete_expired_and_retained` and the reconciliation scans are separate calls over the same tables, and a corpus written in one sweep measures none of them. -- **NIP-50 `search`.** Not on the base this rig builds against, and a full-text scan is a - different access path from the five filter shapes in D3. +- **NIP-50 `search`.** It is on the base — `Filter.search` is + `crates/nostream-core/src/filter.rs:67`, Postgres builds `ts_rank`/`plainto_tsquery` over it + (`postgres/sql.rs:225-231`), and the LMDB arm answers `StorageError::NotImplemented` for it + (`lmdb/events.rs:1061-1072`, ADR 0011's `:331`). What keeps it out of the tables is the gate: + both arms honour `search` only with `nip50.enabled`, and the harness opens either backend without + settings (`LmdbBackend::open`, `PostgresBackend::connect`), so with the gate off a filter carrying + `search` is measured as the plain filter underneath it, the query silently dropped. A `search` row + added to this rig as it stands would therefore time a filtered read and call it a search; a + Postgres-only row would be one-sided, since the LMDB arm cannot answer one at all. A real search + benchmark starts by opening the store with the gate on, and that is its own job. - **Transactions.** The Postgres arm pays for serializable transaction groups the LMDB arm does not have; the rig times repository calls, not the grouping above them. - **Concurrency above one.** One writer, one reader, `concurrency: 1`: no concurrent readers, no From 3ad5686a3ae9d363a04f3bf1f0d1302b5229c3fc Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sat, 14 Nov 2026 01:49:03 -0500 Subject: [PATCH 08/14] docs: correct the rig's claims about the append and ephemeral arms --- docs/rewrite/benchmarks.md | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index 78b67bbce..becb5642f 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -274,12 +274,19 @@ Not measured, and why: (`crates/nostream-storage/src/repositories.rs:494`) — the parameterized replaceable range through `crates/nostream-relay/src/strategies/parameterized_replaceable.rs:35`, reached from `strategies/mod.rs:102-103` — because the relay replaces the current version of such an event - rather than appending another. Ephemeral kinds 20000–29999 are the other half, never stored at - all: the relay acknowledges and broadcasts them with no repository call - (`strategies/ephemeral.rs`, `crates/nostream-core/src/event.rs:247-250`). The corpus holds kinds - 1 and 7 only, so the rig times the append path, and every stored kind it lacks travels a - different repository call; adding one would change what a corpus row means, not just add a - shape. + rather than appending another. Ephemeral kinds 20000–29999 are never stored at all + (`crates/nostream-core/src/event.rs:247-250`) and reach no repository call — except 28934, 28935 + and 28936, which the invites and users arms claim before the ephemeral arm is reached + (`strategies/mod.rs:90-96`), and which the rig does not exercise: 28934 spends an invite and + admits the user (`join_request.rs:100`, `:118`), 28936 revokes the admission + (`leave_request.rs:91`), and a client-published 28935 is refused without touching a store + (`invite_request.rs:33-38`). The rig times the default arm's append, and the arms that re-enter + `create` — delete, gift wrap, DVM job request, group, report, timestamp and vanish, beside the + default arm itself (`strategies/default.rs:36`, `delete.rs:105`, `gift_wrap.rs:38`, + `dvm_job_request.rs:30`, `group.rs:37`, `report.rs:35`, `timestamp.rs:40`, `vanish.rs:37`) — are + the same call with a different row, so a corpus using them measures what the `create` shape + measures. Only the replaceable families need `upsert`, which the rig does not call; adding one + would change what a corpus row means, not just add a shape. - **Retention and purge.** `delete_expired_and_retained` and the reconciliation scans are separate calls over the same tables, and a corpus written in one sweep measures none of them. - **NIP-50 `search`.** It is on the base — `Filter.search` is From d0489b8376f973604e39683e0455092693771805 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:04:56 -0500 Subject: [PATCH 09/14] fix(bench): check operations not rates, refuse a directory artifact, wrap the seed --- crates/nostream-storage/examples/bench.rs | 244 ++++++++++++++++++++-- 1 file changed, 221 insertions(+), 23 deletions(-) diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs index 8613e169e..c1a4947a8 100644 --- a/crates/nostream-storage/examples/bench.rs +++ b/crates/nostream-storage/examples/bench.rs @@ -82,8 +82,9 @@ const TAG_LIMIT: u64 = 100; const DEFAULT_REPEATS: u64 = 1; /// The artifact's layout version: bumped when a field's meaning or position changes, so a reader -/// can tell which shape of document it holds. -const ARTIFACT_SCHEMA: u64 = 1; +/// can tell which shape of document it holds. Version 2 added `workload.reads.by_id_stride` and +/// `by_id_offset`, which two otherwise identical read workloads can differ by. +const ARTIFACT_SCHEMA: u64 = 2; /// The corpus ceiling a run may not cross without `--allow-large-corpus`. A 1M-event corpus is /// about 1.9 GB of `data.mdb` at the rate this rig measures, so the default refusal is what @@ -354,6 +355,8 @@ struct Report { bands: BTreeMap, /// Every repeat's shapes, so verification can check they agree with the first. repeat_shapes: Vec>, + /// Every repeat's read-back count, so a short read in a later repeat is caught too. + repeat_read_backs: Vec, } /// One failed integrity check, reported as `verify failed: : expected , got `. @@ -505,6 +508,27 @@ fn plural(count: usize) -> &'static str { if count == 1 { "" } else { "s" } } +/// Checks that the artifact's directory will take a new file, by creating and removing a sibling +/// name: the destination itself is never opened, so an artifact already there is left alone. +fn probe_writable(parent: &Path, out: &Path) -> Fallible<()> { + let probe = parent.join(format!(".bench-out-probe-{}", std::process::id())); + match std::fs::OpenOptions::new() + .write(true) + .create_new(true) + .open(&probe) + { + Ok(_) => { + let _ = std::fs::remove_file(&probe); + Ok(()) + } + Err(error) => Err(refusal(format!( + "--out {}: {} cannot be written ({error})", + out.display(), + parent.display() + ))), + } +} + /// The root one repeat opens its store under. The refusal in `given_store` and the open in /// `store_root` both call this, so they cannot disagree about which directory a run writes to. fn repeat_root(path: &Path, repeat: u64, repeats: u64) -> PathBuf { @@ -598,8 +622,11 @@ impl Plan { ))); } - // The write happens after the whole measurement, so a mistyped directory has to be a - // refusal like any other rather than a failure at the end of a long run. + // The write happens after the whole measurement, so a mistyped path has to be a refusal + // like any other rather than a failure at the end of a long run. Three things are checked, + // because each fails late and expensively otherwise: the parent exists, the destination is + // not a directory, and a file can be created in that parent — probed with a sibling name, + // since probing the destination itself would truncate an artifact that is already there. let parent = match arguments.out.parent() { Some(parent) if !parent.as_os_str().is_empty() => parent.to_path_buf(), _ => PathBuf::from("."), @@ -611,6 +638,13 @@ impl Plan { parent.display() ))); } + if arguments.out.is_dir() { + return Err(refusal(format!( + "--out {} is a directory, and the artifact is one file. Name a file inside it", + arguments.out.display() + ))); + } + probe_writable(&parent, &arguments.out)?; let admin_url = match arguments.backend { Backend::Postgres => Some(admin_url()?), @@ -767,8 +801,15 @@ fn until_for(iteration: u64, events: u64) -> i64 { CREATED_AT_ANCHOR_UNIX - (iteration as i64) * span / COUNT_ITERATIONS as i64 } +/// The `by_id` iteration's target id. The seed's only job is to pick a reproducible offset into +/// the corpus, so this arithmetic is deliberately modular and wraps rather than overflowing: every +/// `u64` is a legal seed, and one seed must select the same rows in a debug build as in a release +/// build. fn by_id_target(iteration: u64, events: u64, seed: u64) -> u64 { - (seed * BY_ID_STRIDE + iteration * BY_ID_STRIDE + BY_ID_OFFSET) % events + seed.wrapping_mul(BY_ID_STRIDE) + .wrapping_add(iteration.wrapping_mul(BY_ID_STRIDE)) + .wrapping_add(BY_ID_OFFSET) + % events } /// One read shape's filter for one iteration. The workload and the oracle both call this, so a @@ -1093,6 +1134,7 @@ impl Report { let mut timings = BTreeMap::new(); let mut per_repeat: BTreeMap<&'static str, Vec> = BTreeMap::new(); let mut repeat_shapes = Vec::new(); + let mut repeat_read_backs = Vec::new(); for run in std::iter::once(&first).chain(rest.iter()) { for (name, samples) in &run.timings { @@ -1102,6 +1144,7 @@ impl Report { .push(Timing::from_samples(samples)); } repeat_shapes.push(run.shapes.clone()); + repeat_read_backs.push(run.event_count_read_back); } for (name, samples) in &first.timings { timings.insert((*name).to_owned(), Timing::from_samples(samples)); @@ -1122,6 +1165,7 @@ impl Report { timings, bands, repeat_shapes, + repeat_read_backs, } } @@ -1168,6 +1212,8 @@ fn workload_json(repeat_count: u64) -> Value { "reads": { "iterations": READ_ITERATIONS, "counts": COUNT_ITERATIONS, + "by_id_stride": BY_ID_STRIDE, + "by_id_offset": BY_ID_OFFSET, "limits": { "by_id": BY_ID_LIMIT, "author_kind": AUTHOR_KIND_LIMIT, @@ -1403,24 +1449,17 @@ fn verify(report: &Report) -> Vec { ), )); } - check( - &mut failures, - format!("volatile.timings[{name}].ops"), - timing.ops.max(1), - timing.ops, - ); - check( - &mut failures, - format!("volatile.timings[{name}].per_second"), - timing.per_second.max(1), - timing.per_second, - ); - check( - &mut failures, - format!("volatile.timings[{name}].rows_per_second"), - timing.rows_per_second.max(1), - timing.rows_per_second, - ); + // The shape has to have been called at least once. The rates are derived integers, so a + // phase that takes more than a second with few operations in it rounds to zero — that is a + // measurement of a slow host, not a failure, and comparing `0.max(1)` against `0` would + // reject a correct run. + if timing.ops == 0 { + failures.push(VerifyFailure::new( + format!("volatile.timings[{name}].ops"), + "> 0", + "0", + )); + } } for (name, bands) in &report.bands { @@ -1436,6 +1475,17 @@ fn verify(report: &Report) -> Vec { } } + // Index 0 is the first repeat, which `event_count_read_back` above already covers; the rest + // are checked here so a short read in any repeat fails the run. + for (index, count) in report.repeat_read_backs.iter().enumerate() { + check( + &mut failures, + format!("repeats[{index}].event_count_read_back"), + report.events, + *count, + ); + } + for (index, shapes) in report.repeat_shapes.iter().enumerate().skip(1) { for (first, repeat) in report.shapes.iter().zip(shapes.iter()) { if first != repeat { @@ -1550,6 +1600,7 @@ mod tests { repeat_count: 1, event_count_read_back: EVENTS, repeat_shapes: vec![shapes.clone()], + repeat_read_backs: vec![EVENTS], shapes, timings, bands, @@ -1647,6 +1698,22 @@ mod tests { assert!(given_store(directory.path(), 1).is_err()); } + /// The command line the `--out` refusal tests resolve, with everything else at its default: + /// the busy-host check is off and the store is temporary, so only the destination decides. + fn arguments_for(out: PathBuf) -> Arguments { + Arguments { + backend: Backend::Lmdb, + events: 1_001, + seed: DEFAULT_SEED, + repeats: 1, + out, + verify: false, + store: None, + allow_large_corpus: false, + allow_busy_host: true, + } + } + #[test] fn the_smallest_accepted_corpus_leaves_a_bulk_load() { let directory = tempfile::tempdir().ok().expect("a temporary directory"); @@ -1735,6 +1802,137 @@ mod tests { ); } + #[test] + fn a_zero_rounded_rate_verifies() { + let mut report = valid_report(); + // A phase that takes over a second with few operations in it rounds its integer rate to + // zero: a slow host's measurement, not a failed run. + let timing = report.timings.get_mut("create").expect("a create timing"); + assert!(timing.ops > 0); + timing.per_second = 0; + timing.rows_per_second = 0; + let failures = verify(&report); + assert!(failures.is_empty(), "{} failures", failures.len()); + } + + #[test] + fn verify_rejects_a_shape_with_no_operations() { + let mut report = valid_report(); + report + .timings + .get_mut("create") + .expect("a create timing") + .ops = 0; + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "volatile.timings[create].ops"); + assert_eq!(failures[0].got, "0"); + } + + #[test] + fn verify_rejects_a_read_back_that_disagrees_in_a_repeat() { + let mut report = valid_report(); + // Index 1 is the second repeat; the first is `event_count_read_back`. + report.repeat_read_backs.push(EVENTS - 1); + let failures = verify(&report); + assert_eq!(failures.len(), 1, "one failure, not {}", failures.len()); + assert_eq!(failures[0].field, "repeats[1].event_count_read_back"); + assert_eq!(failures[0].expected, EVENTS.to_string()); + } + + #[test] + fn the_by_id_target_is_modular_and_in_range() { + // `u64::MAX` is a legal seed, and the arithmetic wraps in both profiles rather than + // overflowing in one and panicking in the other. + for seed in [7, u64::MAX, u64::MAX / BY_ID_STRIDE + 1] { + for iteration in [0, 1, READ_ITERATIONS - 1] { + let target = by_id_target(iteration, EVENTS, seed); + assert!(target < EVENTS, "seed {seed} iteration {iteration}"); + assert_eq!( + target, + seed.wrapping_mul(BY_ID_STRIDE) + .wrapping_add(iteration.wrapping_mul(BY_ID_STRIDE)) + .wrapping_add(BY_ID_OFFSET) + % EVENTS + ); + } + } + } + + #[test] + fn the_out_refusal_names_a_directory_destination() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + // The destination is a directory: its parent exists, so only this check answers it, and + // without it the run fails after the whole measurement. + let error = Plan::resolve(&arguments_for(directory.path().to_path_buf())) + .err() + .expect("a refusal") + .to_string(); + assert!(error.contains("--out"), "{error}"); + assert!(error.contains("is a directory"), "{error}"); + assert!(error.contains(&directory.path().display().to_string()), "{error}"); + } + + #[test] + fn the_out_refusal_names_a_missing_parent() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + let missing = directory.path().join("absent").join("artifact.json"); + let error = Plan::resolve(&arguments_for(missing.clone())) + .err() + .expect("a refusal") + .to_string(); + assert!(error.contains("--out"), "{error}"); + assert!(error.contains("is not a directory"), "{error}"); + } + + #[test] + fn a_writable_destination_is_not_refused() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + let out = directory.path().join("artifact.json"); + assert!(Plan::resolve(&arguments_for(out)).is_ok()); + // The probe leaves nothing behind, and it never creates the destination itself. + let entries: Vec<_> = std::fs::read_dir(directory.path()) + .ok() + .expect("a directory") + .filter_map(|entry| entry.ok()) + .map(|entry| entry.file_name()) + .collect(); + assert!(entries.is_empty(), "left behind: {entries:?}"); + } + + #[test] + fn the_out_refusal_names_a_directory_it_cannot_write() { + let directory = tempfile::tempdir().ok().expect("a temporary directory"); + let out = directory.path().join("artifact.json"); + let mut permissions = std::fs::metadata(directory.path()) + .ok() + .expect("a directory") + .permissions(); + let writable = permissions.clone(); + #[cfg(unix)] + std::os::unix::fs::PermissionsExt::set_mode(&mut permissions, 0o500); + std::fs::set_permissions(directory.path(), permissions) + .ok() + .expect("permissions"); + + let outcome = Plan::resolve(&arguments_for(out)); + std::fs::set_permissions(directory.path(), writable).ok().expect("permissions"); + + // A privileged user can write anywhere, so the refusal is only observable unprivileged. + if let Err(error) = outcome { + let error = error.to_string(); + assert!(error.contains("--out"), "{error}"); + assert!(error.contains("cannot be written"), "{error}"); + } + } + + #[test] + fn the_artifact_records_the_by_id_stepping() { + let workload = workload_json(1); + assert_eq!(workload["reads"]["by_id_stride"], BY_ID_STRIDE); + assert_eq!(workload["reads"]["by_id_offset"], BY_ID_OFFSET); + } + #[test] fn verify_rejects_a_short_read_page() { let mut report = valid_report(); From 50a66cb7d5ba68934bcaf6b17573b071412f8b00 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:05:55 -0500 Subject: [PATCH 10/14] test(bench): ask the filesystem whether the probe should refuse --- crates/nostream-storage/examples/bench.rs | 30 ++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs index c1a4947a8..119c9c51d 100644 --- a/crates/nostream-storage/examples/bench.rs +++ b/crates/nostream-storage/examples/bench.rs @@ -1915,12 +1915,36 @@ mod tests { .ok() .expect("permissions"); + // Whether this user can write there at all, asked of the operating system rather than + // assumed: a privileged user can write anywhere, so the refusal is only observable when + // an ordinary one cannot. + let probe = directory.path().join("probe"); + let writable_by_this_user = std::fs::OpenOptions::new() + .write(true) + .create_new(true) + .open(&probe) + .is_ok(); + let _ = std::fs::remove_file(&probe); + let outcome = Plan::resolve(&arguments_for(out)); std::fs::set_permissions(directory.path(), writable).ok().expect("permissions"); - // A privileged user can write anywhere, so the refusal is only observable unprivileged. - if let Err(error) = outcome { - let error = error.to_string(); + if !writable_by_this_user { + let error = outcome + .err() + .expect("a refusal for a directory this user cannot write") + .to_string(); + assert!(error.contains("--out"), "{error}"); + assert!(error.contains("cannot be written"), "{error}"); + } + + // A read-only filesystem refuses the probe even to a privileged user, and `/proc` is one + // whose files cannot be created: this half is observable in any environment. + if Path::new("/proc").is_dir() { + let error = Plan::resolve(&arguments_for(PathBuf::from("/proc/bench-artifact.json"))) + .err() + .expect("a refusal on a filesystem that cannot take a new file") + .to_string(); assert!(error.contains("--out"), "{error}"); assert!(error.contains("cannot be written"), "{error}"); } From c964cb0a334a7ad93ea9dfc7451a15d04eccfab5 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:16:48 -0500 Subject: [PATCH 11/14] style: rustfmt the harness after the rework --- crates/nostream-storage/examples/bench.rs | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/crates/nostream-storage/examples/bench.rs b/crates/nostream-storage/examples/bench.rs index 119c9c51d..91001cbc1 100644 --- a/crates/nostream-storage/examples/bench.rs +++ b/crates/nostream-storage/examples/bench.rs @@ -1870,7 +1870,10 @@ mod tests { .to_string(); assert!(error.contains("--out"), "{error}"); assert!(error.contains("is a directory"), "{error}"); - assert!(error.contains(&directory.path().display().to_string()), "{error}"); + assert!( + error.contains(&directory.path().display().to_string()), + "{error}" + ); } #[test] @@ -1927,7 +1930,9 @@ mod tests { let _ = std::fs::remove_file(&probe); let outcome = Plan::resolve(&arguments_for(out)); - std::fs::set_permissions(directory.path(), writable).ok().expect("permissions"); + std::fs::set_permissions(directory.path(), writable) + .ok() + .expect("permissions"); if !writable_by_this_user { let error = outcome From 6245c216be42bc4c0be51b4683ed29980f3d4fd7 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:16:48 -0500 Subject: [PATCH 12/14] docs: quote the regenerated schema-2 artifact --- docs/rewrite/benchmarks.md | 65 ++-- docs/rewrite/benchmarks/lmdb-50k-seed7.json | 330 ++++++++++---------- 2 files changed, 199 insertions(+), 196 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index becb5642f..d34c3a958 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -19,18 +19,18 @@ which needs a database this host does not have, and the TypeScript/Postgres colu |---|---| | Date | 2026-11-14 | | Machine | 4 CPUs, `Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz` | -| Load average, one minute | 43.32 (`volatile.machine.load_1min`, the first repeat's) | -| Free disk at run time | 8.6 GB (`df -h /`) | +| Load average, one minute | 48.79 (`volatile.machine.load_1min`, the first repeat's) | +| Free disk at run time | 33 GB (`df -h /`) | | Profile | `release` | | Repeats | 3 (`workload.repeats`) | -| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-lmdb-3.json` | +| Command | `cargo run --release -p nostream-storage --example bench -- --backend lmdb --events 50000 --seed 7 --repeats 3 --verify --out /tmp/bench-lmdb-1.json` | | Artifact | `docs/rewrite/benchmarks/lmdb-50k-seed7.json` | The machine, the load average and the store's size are `volatile.machine` and `volatile.store` in that artifact. This host is shared: the load figure is other tenants' work on four cores, and the three repeats below measure what that does to the numbers rather than leaving it to a -sentence. The load is sampled before every repeat, not once: `load_1min_by_repeat` holds `43.32`, -`43.27` and `43.25`, so the one-minute figure above is the first of three readings that agree. +sentence. The load is sampled before every repeat, not once: `load_1min_by_repeat` holds `48.79`, +`48.73` and `48.69`, so the one-minute figure above is the first of three readings that agree. ## The LMDB numbers @@ -39,19 +39,19 @@ sentence. The load is sampled before every repeat, not once: `load_1min_by_repea | shape | count | rows | p50 (ms) | p95 (ms) | p99 (ms) | per_second | rows_per_second | |---|---|---|---|---|---|---|---| -| `create_many` | 98 | 49000 | 29.6 | 37.3 | 41.4 | 34 | 17277 | -| `create` | 1000 | 1000 | 4.0 | 4.7 | 5.5 | 251 | 251 | -| `by_id` | 200 | 200 | 0.0 | 0.0 | 0.0 | 46500 | 46500 | -| `author_kind` | 200 | 20000 | 0.3 | 0.3 | 0.3 | 3408 | 340802 | -| `kind_since` | 200 | 99602 | 1.4 | 1.5 | 1.6 | 736 | 366841 | -| `tag` | 200 | 20000 | 0.3 | 0.3 | 0.3 | 3707 | 370727 | -| `count` | 50 | 1020000 | 9.2 | 17.3 | 18.5 | 107 | 2198669 | -| `read_back` | 1 | 50000 | 21.9 | 21.9 | 21.9 | 45 | 2283105 | +| `create_many` | 98 | 49000 | 22.2 | 31.2 | 32.7 | 43 | 21985 | +| `create` | 1000 | 1000 | 3.8 | 4.6 | 4.9 | 256 | 256 | +| `by_id` | 200 | 200 | 0.0 | 0.1 | 0.1 | 36784 | 36784 | +| `author_kind` | 200 | 20000 | 0.3 | 0.4 | 0.5 | 2813 | 281333 | +| `kind_since` | 200 | 99602 | 1.5 | 1.7 | 2.0 | 660 | 328819 | +| `tag` | 200 | 20000 | 0.3 | 0.3 | 0.3 | 3531 | 353150 | +| `count` | 50 | 1020000 | 10.7 | 18.2 | 18.9 | 95 | 1953259 | +| `read_back` | 1 | 50000 | 20.4 | 20.4 | 20.4 | 48 | 2446902 | Every column here is the artifact's own integer printed as-is (the `count`, `rows`, `ops`, `per_second` and `rows_per_second` numbers), except the three percentile columns, which are the artifact's microsecond integers printed in milliseconds with exactly one decimal, rounding -half-up: `30 449` µs prints as `30.4`. The cost of that rule is the `by_id` row, whose calls take +half-up: `31 162` µs prints as `31.2`. The cost of that rule is the `by_id` row, whose calls take tens of microseconds and print as `0.0`; the artifact's integers are the measurement, and this table is a reading of them. `read_back` carries no `shapes` entry: it is the single unbounded count the corpus is read back with, and its `rows` is `event_count_read_back`. The rates are the @@ -67,14 +67,14 @@ store. | shape | per_second median | p10 | p90 | rows_per_second median | p10 | p90 | p95 (ms) median | p10 | p90 | |---|---|---|---|---|---|---|---|---|---| -| `create_many` | 48 | 34 | 48 | 24416 | 17277 | 24435 | 30.4 | 29.6 | 37.3 | -| `create` | 251 | 248 | 253 | 251 | 248 | 253 | 4.7 | 4.6 | 4.9 | -| `by_id` | 43047 | 41614 | 46500 | 43047 | 41614 | 46500 | 0.0 | 0.0 | 0.0 | -| `author_kind` | 3408 | 2940 | 3424 | 340802 | 294061 | 342483 | 0.3 | 0.3 | 0.4 | -| `kind_since` | 716 | 690 | 736 | 356779 | 343923 | 366841 | 1.6 | 1.5 | 1.6 | -| `tag` | 3438 | 3116 | 3707 | 343855 | 311623 | 370727 | 0.3 | 0.3 | 0.4 | -| `count` | 102 | 101 | 107 | 2100528 | 2061001 | 2198669 | 18.4 | 17.3 | 19.6 | -| `read_back` | 45 | 20 | 53 | 2283105 | 1040084 | 2661131 | 21.9 | 18.8 | 48.1 | +| `create_many` | 45 | 43 | 45 | 22673 | 21985 | 22890 | 30.6 | 30.1 | 31.2 | +| `create` | 254 | 251 | 256 | 254 | 251 | 256 | 4.7 | 4.6 | 4.7 | +| `by_id` | 37615 | 36784 | 48732 | 37615 | 36784 | 48732 | 0.0 | 0.0 | 0.1 | +| `author_kind` | 3202 | 2813 | 3344 | 320210 | 281333 | 334476 | 0.3 | 0.3 | 0.4 | +| `kind_since` | 660 | 659 | 734 | 328819 | 328382 | 365695 | 1.7 | 1.5 | 1.7 | +| `tag` | 3552 | 3531 | 3679 | 355220 | 353150 | 367944 | 0.3 | 0.3 | 0.3 | +| `count` | 109 | 95 | 111 | 2229576 | 1953259 | 2275323 | 18.2 | 17.2 | 18.2 | +| `read_back` | 48 | 21 | 54 | 2446902 | 1084857 | 2703141 | 20.4 | 18.5 | 46.1 | Every figure is the artifact's integer printed as-is, except the three `p95` columns, which are `volatile.repeats..p95_us` in milliseconds under the same one-decimal rounding as the @@ -175,17 +175,17 @@ whose few slow calls carry the total has a rate below `1 / p50`, so a reader who from the percentile columns above gets a number the artifact does not record. On this run the read shapes and `create` agreed closely between repeats — `create`'s per-second -band spans 248 to 253 — which is what makes the write rows worth reading as a measurement of this +band spans 251 to 256 — which is what makes the write rows worth reading as a measurement of this host on this day. `create_many`'s band is the widest of them: one repeat loaded at 34 batches per -second where the other two reached 48, and its `p95` band runs from 29.6 to 37.3 ms around a -median of 30.4. That is one repeat's writes waiting on the host's disk rather than the same wait +second where the other two reached 45, and its `p95` band runs from 30.1 to 31.2 ms around a +median of 30.6. That is one repeat's writes waiting on the host's disk rather than the same wait landing in all three. A repeat on a shared host can stall outright, and nothing in the rig prevents it, so the band — and not one run's number — is what the tables above are for. A run whose band is wider than this one's is a reading of a busier host, not of a slower store. The cost being timed for the writes is LMDB's synchronous commit, which waits on a shared host's disk; `create_many` also copies the batch and writes its indexes, and this rig does not separate -the two. The write rows are one host's measurement at load 43.32 and not a bound. A reader +the two. The write rows are one host's measurement at load 48.79 and not a bound. A reader comparing two hosts should compare the read shapes first. ### D5 The corpora measured, and the ones that were not @@ -195,11 +195,10 @@ temporary directory. The harness's default ceiling is what keeps a mistyped corp disk: a run above it is refused before the store is touched, with the projected store size printed in bytes and `--allow-large-corpus` named as the override. -The gate's 1M and 10M corpora (#868) were not measured here. Disk space rules the 10M corpus out -on this host — the projection below is more than twice the 8.6 GB the run recorded free — and does -not rule the 1M corpus out, whose projection fits inside it: 1M is #868's run because it is the -gate's corpus and this job's scope is the recorded one, and it needs `--allow-large-corpus` -wherever it runs. The cost of the `count` shape, which scans its whole match set per iteration, +The gate's 1M and 10M corpora (#868) were not measured here. Disk space rules neither out on this +host: the 1M projection fits easily inside the 33 GB the run recorded free, and so does the 10M +one. Both are #868's runs because they are the gate's corpora and this job's scope is the +recorded one, and each needs `--allow-large-corpus` wherever it runs. The cost of the `count` shape, which scans its whole match set per iteration, grows with the corpus and belongs in that run's budget too. projection: 1M events (#868) x 1889.8 bytes/event = 1889800000 bytes @@ -253,8 +252,10 @@ measurement, and nothing here is compared with it. No ratio, floor or comparison backend appears in this document. The artifact's `schema` integer is its layout version: the artifact this document reads — the -committed `docs/rewrite/benchmarks/lmdb-50k-seed7.json` — is schema 1, and a field whose meaning +committed `docs/rewrite/benchmarks/lmdb-50k-seed7.json` — is schema 2, and a field whose meaning or position changes takes the next number, so a consumer can tell which shape of document it holds. +Version 2 added `workload.reads.by_id_stride` and `workload.reads.by_id_offset`: without them two +artifacts that step through the corpus differently were the same document. A consumer that meets an unknown value should refuse the artifact and name the version it found, the way `crates/nostream-storage/src/lmdb/encoding.rs:184-193` refuses a value written by a different row format rather than reading it as if it were this one. diff --git a/docs/rewrite/benchmarks/lmdb-50k-seed7.json b/docs/rewrite/benchmarks/lmdb-50k-seed7.json index fdbd3d96c..c1d91fb2f 100644 --- a/docs/rewrite/benchmarks/lmdb-50k-seed7.json +++ b/docs/rewrite/benchmarks/lmdb-50k-seed7.json @@ -2,7 +2,7 @@ "backend": "lmdb", "event_count_read_back": 50000, "events": 50000, - "schema": 1, + "schema": 2, "seed": 7, "shapes": [ { @@ -46,11 +46,11 @@ "arch": "x86_64", "cpu_count": 4, "cpu_model": "Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz", - "load_1min": 43.32, + "load_1min": 48.79, "load_1min_by_repeat": [ - 43.32, - 43.27, - 43.25 + 48.79, + 48.73, + 48.69 ], "os": "linux", "profile": "release" @@ -58,218 +58,218 @@ "repeats": { "author_kind": { "p50_us": { - "median": 291, - "p10": 289, - "p90": 320 + "median": 311, + "p10": 295, + "p90": 339 }, "p95_us": { - "median": 313, - "p10": 308, - "p90": 435 + "median": 325, + "p10": 320, + "p90": 422 }, "p99_us": { - "median": 353, - "p10": 339, - "p90": 499 + "median": 386, + "p10": 332, + "p90": 531 }, "per_second": { - "median": 3408, - "p10": 2940, - "p90": 3424 + "median": 3202, + "p10": 2813, + "p90": 3344 }, "rows_per_second": { - "median": 340802, - "p10": 294061, - "p90": 342483 + "median": 320210, + "p10": 281333, + "p90": 334476 } }, "by_id": { "p50_us": { - "median": 19, + "median": 22, "p10": 19, - "p90": 23 + "p90": 27 }, "p95_us": { - "median": 25, - "p10": 25, - "p90": 28 + "median": 30, + "p10": 20, + "p90": 53 }, "p99_us": { - "median": 34, - "p10": 31, - "p90": 152 + "median": 59, + "p10": 38, + "p90": 75 }, "per_second": { - "median": 43047, - "p10": 41614, - "p90": 46500 + "median": 37615, + "p10": 36784, + "p90": 48732 }, "rows_per_second": { - "median": 43047, - "p10": 41614, - "p90": 46500 + "median": 37615, + "p10": 36784, + "p90": 48732 } }, "count": { "p50_us": { - "median": 9381, - "p10": 9206, - "p90": 9732 + "median": 9621, + "p10": 8690, + "p90": 10656 }, "p95_us": { - "median": 18358, - "p10": 17250, - "p90": 19570 + "median": 18156, + "p10": 17224, + "p90": 18194 }, "p99_us": { - "median": 19103, - "p10": 18524, - "p90": 21493 + "median": 18394, + "p10": 18245, + "p90": 18894 }, "per_second": { - "median": 102, - "p10": 101, - "p90": 107 + "median": 109, + "p10": 95, + "p90": 111 }, "rows_per_second": { - "median": 2100528, - "p10": 2061001, - "p90": 2198669 + "median": 2229576, + "p10": 1953259, + "p90": 2275323 } }, "create": { "p50_us": { - "median": 3980, - "p10": 3954, - "p90": 3985 + "median": 3891, + "p10": 3788, + "p90": 3988 }, "p95_us": { - "median": 4717, - "p10": 4632, - "p90": 4941 + "median": 4655, + "p10": 4644, + "p90": 4694 }, "p99_us": { - "median": 5534, - "p10": 5013, - "p90": 6389 + "median": 4971, + "p10": 4885, + "p90": 5323 }, "per_second": { - "median": 251, - "p10": 248, - "p90": 253 + "median": 254, + "p10": 251, + "p90": 256 }, "rows_per_second": { - "median": 251, - "p10": 248, - "p90": 253 + "median": 254, + "p10": 251, + "p90": 256 } }, "create_many": { "p50_us": { - "median": 19640, - "p10": 18796, - "p90": 29611 + "median": 22042, + "p10": 21661, + "p90": 22195 }, "p95_us": { - "median": 30449, - "p10": 29637, - "p90": 37269 + "median": 30618, + "p10": 30112, + "p90": 31162 }, "p99_us": { - "median": 35338, - "p10": 32829, - "p90": 41430 + "median": 32675, + "p10": 32333, + "p90": 33129 }, "per_second": { - "median": 48, - "p10": 34, - "p90": 48 + "median": 45, + "p10": 43, + "p90": 45 }, "rows_per_second": { - "median": 24416, - "p10": 17277, - "p90": 24435 + "median": 22673, + "p10": 21985, + "p90": 22890 } }, "kind_since": { "p50_us": { - "median": 1377, - "p10": 1350, - "p90": 1439 + "median": 1507, + "p10": 1351, + "p90": 1523 }, "p95_us": { - "median": 1585, - "p10": 1460, - "p90": 1595 + "median": 1690, + "p10": 1497, + "p90": 1707 }, "p99_us": { - "median": 1703, - "p10": 1601, - "p90": 1724 + "median": 1964, + "p10": 1643, + "p90": 1987 }, "per_second": { - "median": 716, - "p10": 690, - "p90": 736 + "median": 660, + "p10": 659, + "p90": 734 }, "rows_per_second": { - "median": 356779, - "p10": 343923, - "p90": 366841 + "median": 328819, + "p10": 328382, + "p90": 365695 } }, "read_back": { "p50_us": { - "median": 21900, - "p10": 18789, - "p90": 48073 + "median": 20434, + "p10": 18497, + "p90": 46089 }, "p95_us": { - "median": 21900, - "p10": 18789, - "p90": 48073 + "median": 20434, + "p10": 18497, + "p90": 46089 }, "p99_us": { - "median": 21900, - "p10": 18789, - "p90": 48073 + "median": 20434, + "p10": 18497, + "p90": 46089 }, "per_second": { - "median": 45, - "p10": 20, - "p90": 53 + "median": 48, + "p10": 21, + "p90": 54 }, "rows_per_second": { - "median": 2283105, - "p10": 1040084, - "p90": 2661131 + "median": 2446902, + "p10": 1084857, + "p90": 2703141 } }, "tag": { "p50_us": { - "median": 286, - "p10": 265, - "p90": 308 + "median": 278, + "p10": 270, + "p90": 281 }, "p95_us": { - "median": 328, - "p10": 301, - "p90": 406 + "median": 290, + "p10": 282, + "p90": 292 }, "p99_us": { - "median": 362, - "p10": 349, - "p90": 557 + "median": 325, + "p10": 311, + "p90": 347 }, "per_second": { - "median": 3438, - "p10": 3116, - "p90": 3707 + "median": 3552, + "p10": 3531, + "p90": 3679 }, "rows_per_second": { - "median": 343855, - "p10": 311623, - "p90": 370727 + "median": 355220, + "p10": 353150, + "p90": 367944 } } }, @@ -280,67 +280,67 @@ "timings": { "author_kind": { "ops": 200, - "p50_us": 291, - "p95_us": 308, - "p99_us": 339, - "per_second": 3408, - "rows_per_second": 340802 + "p50_us": 339, + "p95_us": 422, + "p99_us": 531, + "per_second": 2813, + "rows_per_second": 281333 }, "by_id": { "ops": 200, - "p50_us": 19, - "p95_us": 25, - "p99_us": 34, - "per_second": 46500, - "rows_per_second": 46500 + "p50_us": 22, + "p95_us": 53, + "p99_us": 59, + "per_second": 36784, + "rows_per_second": 36784 }, "count": { "ops": 50, - "p50_us": 9206, - "p95_us": 17250, - "p99_us": 18524, - "per_second": 107, - "rows_per_second": 2198669 + "p50_us": 10656, + "p95_us": 18194, + "p99_us": 18894, + "per_second": 95, + "rows_per_second": 1953259 }, "create": { "ops": 1000, - "p50_us": 3954, - "p95_us": 4717, - "p99_us": 5534, - "per_second": 251, - "rows_per_second": 251 + "p50_us": 3788, + "p95_us": 4644, + "p99_us": 4885, + "per_second": 256, + "rows_per_second": 256 }, "create_many": { "ops": 98, - "p50_us": 29611, - "p95_us": 37269, - "p99_us": 41430, - "per_second": 34, - "rows_per_second": 17277 + "p50_us": 22195, + "p95_us": 31162, + "p99_us": 32675, + "per_second": 43, + "rows_per_second": 21985 }, "kind_since": { "ops": 200, - "p50_us": 1350, - "p95_us": 1460, - "p99_us": 1601, - "per_second": 736, - "rows_per_second": 366841 + "p50_us": 1507, + "p95_us": 1690, + "p99_us": 1964, + "per_second": 660, + "rows_per_second": 328819 }, "read_back": { "ops": 1, - "p50_us": 21900, - "p95_us": 21900, - "p99_us": 21900, - "per_second": 45, - "rows_per_second": 2283105 + "p50_us": 20434, + "p95_us": 20434, + "p99_us": 20434, + "per_second": 48, + "rows_per_second": 2446902 }, "tag": { "ops": 200, - "p50_us": 265, - "p95_us": 301, - "p99_us": 349, - "per_second": 3707, - "rows_per_second": 370727 + "p50_us": 281, + "p95_us": 292, + "p99_us": 325, + "per_second": 3531, + "rows_per_second": 353150 } } }, @@ -366,6 +366,8 @@ "tag_value_count": 20 }, "reads": { + "by_id_offset": 13, + "by_id_stride": 7919, "counts": 50, "iterations": 200, "limits": { From c3115cd57161cc391224131790e663fef1db16f9 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:17:25 -0500 Subject: [PATCH 13/14] docs: read the regenerated run's bands instead of the old one's --- docs/rewrite/benchmarks.md | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index d34c3a958..c93405039 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -174,14 +174,15 @@ The two rates divide by the time the shape's calls took, added up, not by its me whose few slow calls carry the total has a rate below `1 / p50`, so a reader who recomputes a rate from the percentile columns above gets a number the artifact does not record. -On this run the read shapes and `create` agreed closely between repeats — `create`'s per-second -band spans 251 to 256 — which is what makes the write rows worth reading as a measurement of this -host on this day. `create_many`'s band is the widest of them: one repeat loaded at 34 batches per -second where the other two reached 45, and its `p95` band runs from 30.1 to 31.2 ms around a -median of 30.6. That is one repeat's writes waiting on the host's disk rather than the same wait -landing in all three. A repeat on a shared host can stall outright, and nothing in the rig -prevents it, so the band — and not one run's number — is what the tables above are for. A run -whose band is wider than this one's is a reading of a busier host, not of a slower store. +On this run both write shapes agreed closely between repeats — `create`'s per-second band spans 251 +to 256, `create_many`'s 43 to 45, and its `p95` band runs from 30.1 to 31.2 ms around a median of +30.6 — which is what makes the write rows worth reading as a measurement of this host on this day. +The widest bands belong to the shapes measured least often: `read_back` is one operation per repeat, +and `by_id`'s band runs from 36784 to 48732 per second across calls that take a few tens of +microseconds, so one stalled call moves it. A repeat on a shared host can stall outright, and +nothing in the rig prevents it, so the band — and not one run's number — is what the tables above +are for. A run whose band is wider than this one's is a reading of a busier host, not of a slower +store. The cost being timed for the writes is LMDB's synchronous commit, which waits on a shared host's disk; `create_many` also copies the batch and writes its indexes, and this rig does not separate From d8086949bf7a06a23e9811d2ce5382d59c176a28 Mon Sep 17 00:00:00 2001 From: chappie-daemon Date: Sun, 15 Nov 2026 08:31:29 -0500 Subject: [PATCH 14/14] docs: quote the regenerated run's row rates and its date --- docs/rewrite/benchmarks.md | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/docs/rewrite/benchmarks.md b/docs/rewrite/benchmarks.md index c93405039..561162e9f 100644 --- a/docs/rewrite/benchmarks.md +++ b/docs/rewrite/benchmarks.md @@ -17,7 +17,7 @@ which needs a database this host does not have, and the TypeScript/Postgres colu | | | |---|---| -| Date | 2026-11-14 | +| Date | 2026-11-15 | | Machine | 4 CPUs, `Intel(R) Core(TM) i7-10700T CPU @ 2.00GHz` | | Load average, one minute | 48.79 (`volatile.machine.load_1min`, the first repeat's) | | Free disk at run time | 33 GB (`df -h /`) | @@ -92,9 +92,10 @@ band is the measurement printed three times and is not evidence of stability. `per_second` counts operations: one event for `create`, one five-hundred-event batch for `create_many`, one filter query for a read shape, one count for `count`. `rows_per_second` counts -the rows those operations returned. The two differ for `create_many` by its batch size, which is -why the same column reads 48 operations and 24416 rows, and they coincide for `create` and for the -read shapes that always return one row per operation. +the rows those operations returned. The two differ for `create_many` by its batch size: the +within-run row above reads 43 operations against 21985 rows in the same second, and the band's +medians differ by the same factor. They coincide for `create` and for the read shapes that always +return one row per operation. **The store.** @@ -199,8 +200,9 @@ in bytes and `--allow-large-corpus` named as the override. The gate's 1M and 10M corpora (#868) were not measured here. Disk space rules neither out on this host: the 1M projection fits easily inside the 33 GB the run recorded free, and so does the 10M one. Both are #868's runs because they are the gate's corpora and this job's scope is the -recorded one, and each needs `--allow-large-corpus` wherever it runs. The cost of the `count` shape, which scans its whole match set per iteration, -grows with the corpus and belongs in that run's budget too. +recorded one, and each needs `--allow-large-corpus` wherever it runs. The cost of the `count` +shape, which scans its whole match set per iteration, grows with the corpus and belongs in that +run's budget too. projection: 1M events (#868) x 1889.8 bytes/event = 1889800000 bytes projection: 10M events (#868) x 1889.8 bytes/event = 18898000000 bytes