diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index de86f89..4be4c5c 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -262,7 +262,7 @@ Indexes are not free here. On that same 103 MiB database `dbstat` attributes 20 ### Measuring these queries -Index work here is measured in **page misses** — `SQLITE_DBSTATUS_CACHE_MISS`, the 4 KiB database pages SQLite has to fetch from the file — and not in milliseconds. Development happens on an SSD and the appliance runs off an SD card, where the same page count costs orders of magnitude more; a query that reads the whole table can look free on one machine and take seconds on the other. `tests/stats_page_miss_bench.rs` reports the figure against a real database and `tests/stats_page_miss_test.rs` asserts the properties behind it; `tests/stats_parallel_bench.rs` is the wall-clock companion, and is the one to distrust when the two disagree. +Index work here is measured in **page misses** — `SQLITE_DBSTATUS_CACHE_MISS`, the 4 KiB database pages SQLite has to fetch from the file — and not in milliseconds. Development happens on an SSD and the appliance runs off an SD card, where the same page count costs orders of magnitude more; a query that reads the whole table can look free on one machine and take seconds on the other. `tests/stats_page_miss_bench.rs` reports the figure against a real database and `tests/stats_page_miss_test.rs` asserts the properties behind it; `tests/dashboard_page_miss_bench.rs` does the same for the dashboard's first response and its recurring event-stream tick, and `tests/logs_page_miss_bench.rs` for every filter the query log offers, with values drawn from the database under test. All three take `BENCH_DB` and a `BENCH_NOW` that pins the clock, so a copy older than its windows still measures the traffic it holds; `tests/stats_parallel_bench.rs` is the wall-clock companion, and is the one to distrust when the two disagree. That distinction is not hypothetical. `outcome_breakdown_since` was left uncovered through version 11 because carrying `result` in an index measured *slower* on wall clock — but the plain table lookup it was compared against read 12 173 pages to the covered form's 2 157, or the entire 10 784-page table of a 370 k-row database. On an SSD with a warm OS page cache that difference does not show up in a duration. diff --git a/CLAUDE.md b/CLAUDE.md index 7d887e2..eb8149a 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -132,7 +132,7 @@ Statistics adds the conventions for a page whose readings sit in a **chosen wind - **`app.js` does not redraw what it did not need to draw.** `StatsPage` is three charts and one date; the bar-list, health-grid and highlights renderers are gone rather than kept as a second copy of the markup. There is no polling here — this page is history, not a live reading. - **The range is in the URL and the switcher is three ``s** (`/stats?range=30d`), because the range picks the *server's* window. `StatsRange::label()` is the one spelling shared by the link, the parse and every card title. An unrecognised range renders the default rather than 400ing — it is a link an operator can edit, and every window on offer is spelled out right above it. - **A date the server can only write in UTC ships as an ISO day plus its timestamp** (`data-date-ts`), and `app.js` restates it in the browser's locale — the same division as the query log's relative times, and for the same reason. -- **This page is measured in page misses, not milliseconds.** Development is on an SSD and the appliance runs off an SD card, so a duration measured here says nothing about a Raspberry Pi; the pages a query fetches from the file are the same on both. `cargo nextest run --release --no-capture --run-ignored only stats_page_miss` with `BENCH_DB` pointed at a copy of a real database reports them. A wall-clock reading is the thing to distrust when the two disagree — it is what left the outcome breakdown scanning the whole table through version 11. +- **This page is measured in page misses, not milliseconds.** Development is on an SSD and the appliance runs off an SD card, so a duration measured here says nothing about a Raspberry Pi; the pages a query fetches from the file are the same on both. `cargo nextest run --release --no-capture --run-ignored only stats_page_miss` with `BENCH_DB` pointed at a copy of a real database reports them; `dashboard_page_miss` and `logs_page_miss` do the same for the dashboard (first response and tick) and the query log (every filter), and `BENCH_NOW` pins the clock on a copy older than its windows. A wall-clock reading is the thing to distrust when the two disagree — it is what left the outcome breakdown scanning the whole table through version 11. - **One scan per index, not one per reading.** `stats_scan_since` and `traffic_lists_since` (`src/db.rs`) are the page's two scans — the second answering top domains, the distinct-domain count and top clients from one grouping of `(domain, client_ip, doh_token)` — and every reading on it — the charts included — is folded out of one of them; `compute_range_stats` (`src/admin/stats.rs`) is what the page calls. `stats_scan_since` streams its rows and folds them in Rust rather than grouping in SQL: a grain carrying both the quarter hour and `response_ms` approaches a group per row, which would be a temp b-tree the size of the window. The single-purpose functions `/api/stats/*` uses are statements of their own — adding a seventh reading to the page means folding it out of one of those two scans, not adding a statement. - **A total nobody can count cheaply is maintained, not counted.** `query_logs`' row count lives in `settings` (`query_log_count`), moved by the insert batch, the prune and Clear All inside their own transactions — `SELECT COUNT(*)` walks an index end to end and the Database Health card asks on every load. A fourth write path to `query_logs` means a fourth `bump_log_count`, not a fourth reader. - Four bar lists in one template share **one askama macro** (`templates/_macros.html`); `{% call … %}` needs a matching `{% endcall %}` in askama 0.16, and `{% include %}` cannot see a loop variable at all. diff --git a/tests/dashboard_page_miss_bench.rs b/tests/dashboard_page_miss_bench.rs new file mode 100644 index 0000000..af8ba2e --- /dev/null +++ b/tests/dashboard_page_miss_bench.rs @@ -0,0 +1,114 @@ +//! What the dashboard costs in **page misses**, the unit +//! `stats_page_miss_bench` explains. Manual-only, gated by `#[ignore]`. +//! +//! BENCH_DB=/tmp/noadd-bench.db cargo nextest run --release \ +//! --no-capture --run-ignored only `dashboard_page_miss` +//! +//! Two costs, reported separately because they recur at different rates: the +//! first response is paid once per visit, the event stream's snapshot every +//! `TICK_INTERVAL_SECS` for as long as a dashboard stays open. The tick is the +//! number to watch. +//! +//! Each reading is taken with the read pool's page cache dropped first, so the +//! number is what a cold appliance pays. `BENCH_NOW` (unix seconds) pins the +//! clock: every dashboard reading ends at now, so on a copy older than a day +//! the 24-hour readings would otherwise measure an empty window. + +use noadd::admin::events::compute_snapshot; +use noadd::admin::stats::{ + compute_summary, compute_timeline, compute_top_domains_and_clients, compute_top_upstreams, +}; +use noadd::db::Database; +use noadd::now_unix; + +/// The limit and window `dashboard_page` and `compute_snapshot` pass. Kept here +/// rather than exported, so the per-reading rows below ask for what the page +/// asks for; the tick total goes through `compute_snapshot` itself. +const TOP_N: i64 = 10; +const TIMELINE_HOURS: i64 = 24; + +/// Run `f` with the pool's page cache dropped first, and report how many pages +/// it had to read. +async fn page_misses(db: &Database, f: F) -> i64 +where + F: FnOnce() -> Fut, + Fut: std::future::Future, +{ + db.reset_read_page_accounting().await.unwrap(); + let before = db.read_page_cache_stats().await.unwrap(); + f().await; + let after = db.read_page_cache_stats().await.unwrap(); + after.misses - before.misses +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 8)] +#[ignore = "benchmark; run manually with --ignored"] +async fn dashboard_page_miss_bench() { + let db_path = std::env::var("BENCH_DB").unwrap_or_else(|_| "/tmp/noadd-bench.db".into()); + assert!( + std::path::Path::new(&db_path).exists(), + "BENCH_DB={db_path} not found — copy a production database to a scratch path before running" + ); + let now = std::env::var("BENCH_NOW").ok().map_or_else(now_unix, |v| { + v.parse::().expect("BENCH_NOW must be unix seconds") + }); + + let db = Database::open(&db_path).await.unwrap(); + let storage = db.db_storage_stats().await.unwrap(); + eprintln!("dashboard_page_miss_bench: db={db_path} now={now}"); + + // What `dashboard_page` reads before it writes any HTML. + let first: Vec<(&str, i64)> = vec![ + ( + "summary", + page_misses(&db, || compute_summary(&db, now)).await, + ), + ( + "top domains + clients", + page_misses(&db, || compute_top_domains_and_clients(&db, now, TOP_N)).await, + ), + ( + "top upstreams", + page_misses(&db, || compute_top_upstreams(&db, now, TOP_N)).await, + ), + ]; + let first_total: i64 = first.iter().map(|(_, n)| *n).sum(); + + // The tick adds the timeline to the same three readings and runs all four + // concurrently, so its total is measured as one call rather than summed. + let timeline = page_misses(&db, || compute_timeline(&db, now, TIMELINE_HOURS)).await; + let tick = page_misses(&db, || compute_snapshot(&db, now)).await; + + let mib = |pages: i64| (pages * 4096) as f64 / (1024.0 * 1024.0); + eprintln!(); + eprintln!(" {:<42} {:>9} {:>9}", "reading", "pages", "MiB"); + for (label, n) in &first { + eprintln!(" {label:<42} {n:>9} {:>9.1}", mib(*n)); + } + eprintln!( + " {:<42} {first_total:>9} {:>9.1}", + "FIRST RESPONSE TOTAL", + mib(first_total) + ); + eprintln!( + " {:<42} {timeline:>9} {:>9.1}", + "timeline (tick only)", + mib(timeline) + ); + eprintln!( + " {:<42} {tick:>9} {:>9.1}", + "TICK TOTAL (compute_snapshot)", + mib(tick) + ); + eprintln!( + " database is {:.1} MiB", + storage.main_bytes as f64 / (1024.0 * 1024.0) + ); + + // A reading that costs nothing means the cache was not actually dropped, so + // every later number would be meaningless. + assert!( + tick > 0, + "no page misses recorded — is BENCH_DB an empty database?" + ); +} diff --git a/tests/logs_page_miss_bench.rs b/tests/logs_page_miss_bench.rs new file mode 100644 index 0000000..6802495 --- /dev/null +++ b/tests/logs_page_miss_bench.rs @@ -0,0 +1,241 @@ +//! What the query log page costs in **page misses**, the unit +//! `stats_page_miss_bench` explains. Manual-only, gated by `#[ignore]`. +//! +//! BENCH_DB=/tmp/noadd-bench.db cargo nextest run --release \ +//! --no-capture --run-ignored only `logs_page_miss` +//! +//! Unlike the dashboard and the Statistics page, `/logs` has no time window: +//! the list is a page of the whole table and the count is over all of it, so +//! what a load costs depends on the filters rather than on a range. Every +//! filter the page offers is measured on its own and in the combinations the +//! form allows, with a common and a rare value each, because an index choice +//! that helps one routinely hurts the other. +//! +//! The filter values are picked from `BENCH_DB` itself — the busiest and the +//! quietest domain, token and query type — so the same bench means the same +//! thing on any database. `BENCH_NOW` (unix seconds) pins the clock for the +//! domain suggestions, the one reading here that has a window. + +use noadd::admin::stats::domain_suggestions; +use noadd::db::Database; +use noadd::now_unix; +use rusqlite::{Connection, OpenFlags, OptionalExtension}; + +/// `LOGS_PAGE_SIZE` in `src/admin/pages.rs`. +const PAGE_SIZE: i64 = 50; + +/// How deep the second list reading goes. `OFFSET` is not free: every skipped +/// row is still read, so a filter that is cheap on page one can be expensive +/// further in. +const DEEP_PAGE: i64 = 20; + +/// Run `f` with the pool's page cache dropped first, and report how many pages +/// it had to read. +async fn page_misses(db: &Database, f: F) -> i64 +where + F: FnOnce() -> Fut, + Fut: std::future::Future, +{ + db.reset_read_page_accounting().await.unwrap(); + let before = db.read_page_cache_stats().await.unwrap(); + f().await; + let after = db.read_page_cache_stats().await.unwrap(); + after.misses - before.misses +} + +/// The value of `column` with the most (`DESC`) or fewest (`ASC`) rows, ties +/// broken by value so repeated runs pick the same one. Values holding a search +/// metacharacter are passed over: as a search term one would turn the prefix +/// match being measured into a `LIKE`. +fn pick(conn: &Connection, column: &str, order: &str) -> Option { + conn.query_row( + &format!( + "SELECT {column} FROM query_logs \ + WHERE {column} IS NOT NULL AND {column} NOT GLOB '*[%_*?]*' \ + GROUP BY {column} ORDER BY COUNT(*) {order}, {column} LIMIT 1" + ), + [], + |row| row.get(0), + ) + .optional() + .unwrap() +} + +/// The filters one load of `/logs` passes to `query_logs` and `count_logs`. +struct Filter { + label: String, + search: Option, + blocked: Option, + token: Option, + query_type: Option, +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 8)] +#[ignore = "benchmark; run manually with --ignored"] +async fn logs_page_miss_bench() { + let db_path = std::env::var("BENCH_DB").unwrap_or_else(|_| "/tmp/noadd-bench.db".into()); + assert!( + std::path::Path::new(&db_path).exists(), + "BENCH_DB={db_path} not found — copy a production database to a scratch path before running" + ); + let now = std::env::var("BENCH_NOW").ok().map_or_else(now_unix, |v| { + v.parse::().expect("BENCH_NOW must be unix seconds") + }); + + // Opened first so the migrations have run before anything reads the schema. + let db = Database::open(&db_path).await.unwrap(); + let storage = db.db_storage_stats().await.unwrap(); + + // Picked on a connection outside the read pool, so none of these scans is + // counted against the readings below. + let (busy_domain, quiet_domain, busy_token, quiet_token, busy_type, quiet_type) = { + let conn = Connection::open_with_flags(&db_path, OpenFlags::SQLITE_OPEN_READ_ONLY).unwrap(); + ( + pick(&conn, "domain", "DESC"), + pick(&conn, "domain", "ASC"), + pick(&conn, "doh_token", "DESC"), + pick(&conn, "doh_token", "ASC"), + pick(&conn, "query_type", "DESC"), + pick(&conn, "query_type", "ASC"), + ) + }; + let busy_domain = busy_domain.expect("BENCH_DB has no query logs"); + // A plain term is a GLOB prefix search; a wildcard makes it a LIKE. + let prefix = busy_domain + .split('.') + .next() + .unwrap_or(&busy_domain) + .to_string(); + let labels: Vec<&str> = busy_domain.split('.').collect(); + let contains = format!("*{}*", labels[labels.len().saturating_sub(2)]); + eprintln!( + "logs_page_miss_bench: db={db_path} now={now}\n prefix={prefix:?} rare={quiet_domain:?} \ + contains={contains:?}\n token busy={busy_token:?} quiet={quiet_token:?}\n \ + type busy={busy_type:?} quiet={quiet_type:?}" + ); + + let f = |label: &str, + search: Option<&str>, + blocked: Option, + token: Option<&Option>, + query_type: Option<&Option>| { + // A database with no DoH traffic has no token to filter by; that row is + // skipped rather than measured as an empty filter. + let token = match token { + Some(None) => return None, + Some(Some(t)) => Some(t.clone()), + None => None, + }; + let query_type = match query_type { + Some(None) => return None, + Some(Some(t)) => Some(t.clone()), + None => None, + }; + Some(Filter { + label: label.to_string(), + search: search.map(str::to_string), + blocked, + token, + query_type, + }) + }; + let filters: Vec = [ + f("no filter", None, None, None, None), + f("search prefix (busy)", Some(&prefix), None, None, None), + f( + "search prefix (rare)", + quiet_domain.as_deref(), + None, + None, + None, + ), + f("search contains", Some(&contains), None, None, None), + f("blocked", None, Some(true), None, None), + f("allowed", None, Some(false), None, None), + f("token (busy)", None, None, Some(&busy_token), None), + f("token (quiet)", None, None, Some(&quiet_token), None), + f("type (busy)", None, None, None, Some(&busy_type)), + f("type (quiet)", None, None, None, Some(&quiet_type)), + f( + "blocked + type (busy)", + None, + Some(true), + None, + Some(&busy_type), + ), + f( + "search prefix + allowed", + Some(&prefix), + Some(false), + None, + None, + ), + f( + "token (busy) + blocked", + None, + Some(true), + Some(&busy_token), + None, + ), + f( + "token + type (both quiet)", + None, + None, + Some(&quiet_token), + Some(&quiet_type), + ), + ] + .into_iter() + .flatten() + .collect(); + + let mut rows: Vec<(String, i64)> = Vec::new(); + for filter in &filters { + let (search, token, query_type) = ( + filter.search.as_deref(), + filter.token.as_deref(), + filter.query_type.as_deref(), + ); + for (page_label, page) in [("page 1", 1), ("page 20", DEEP_PAGE)] { + let offset = (page - 1) * PAGE_SIZE; + let n = page_misses(&db, || { + db.query_logs(PAGE_SIZE, offset, search, filter.blocked, token, query_type) + }) + .await; + rows.push((format!("{} — list {page_label}", filter.label), n)); + } + let n = page_misses(&db, || { + db.count_logs(search, filter.blocked, token, query_type) + }) + .await; + rows.push((format!("{} — count", filter.label), n)); + } + rows.push(( + "domain suggestions".to_string(), + page_misses(&db, || domain_suggestions(&db, now)).await, + )); + let total: i64 = rows.iter().map(|(_, n)| *n).sum(); + + let mib = |pages: i64| (pages * 4096) as f64 / (1024.0 * 1024.0); + eprintln!(); + eprintln!(" {:<50} {:>9} {:>9}", "reading", "pages", "MiB"); + for (label, n) in &rows { + eprintln!(" {label:<50} {n:>9} {:>9.1}", mib(*n)); + } + eprintln!( + " {:<50} {total:>9} {:>9.1}", + "SUM OF ALL READINGS", + mib(total) + ); + eprintln!( + " database is {:.1} MiB", + storage.main_bytes as f64 / (1024.0 * 1024.0) + ); + + // A reading that costs nothing means the cache was not actually dropped, so + // every later number would be meaningless. + assert!( + total > 0, + "no page misses recorded — is BENCH_DB an empty database?" + ); +} diff --git a/tests/stats_page_miss_bench.rs b/tests/stats_page_miss_bench.rs index 27d78e6..0650243 100644 --- a/tests/stats_page_miss_bench.rs +++ b/tests/stats_page_miss_bench.rs @@ -14,7 +14,9 @@ //! //! Each reading is taken with the read pool's page cache dropped first, so the //! number is what a cold appliance pays. `BENCH_RANGE` picks the window -//! (`7d`, `30d`, `90d`; default `30d`). +//! (`7d`, `30d`, `90d`; default `30d`). `BENCH_NOW` (unix seconds) pins the +//! clock the window ends at, so an old copy can still be measured over the +//! traffic it holds. use noadd::admin::stats::{ self, StatsRange, compute_db_health, compute_heatmap, compute_range_stats, @@ -54,7 +56,9 @@ async fn stats_page_miss_bench() { ); let db = Database::open(&db_path).await.unwrap(); - let now = now_unix(); + let now = std::env::var("BENCH_NOW").ok().map_or_else(now_unix, |v| { + v.parse::().expect("BENCH_NOW must be unix seconds") + }); let page_size = db.db_storage_stats().await.unwrap(); eprintln!( "stats_page_miss_bench: db={db_path} range={} ",