diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 4be4c5c..310fd76 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -276,7 +276,7 @@ The window's grain has no time bucket in it. Bucketing the shared grain was what The charts did still pay for scans of their own after that: the browser fetched the timeline, which walked the metrics index again, and the heatmap, which walked `idx_query_logs_timestamp`. They now come out of the page's scan too. `stats_scan_since` reads the metrics index once from the earlier of the range's and the heatmap's windows, folds the window readings, and counts queries per UTC quarter hour into a `QuarterSeries` the page embeds; `app.js` folds that into the viewer's hours and days, which is exact because every UTC offset in use is a whole number of quarter hours. It streams rows into Rust rather than grouping in SQL, because a grain carrying both the quarter and `response_ms` approaches one group per row. On the same database with the 30-day range — the whole table — a visit went from 13 298 page misses (51.9 MiB) to 9 758 (38.1 MiB). The API's timeline and heatmap endpoints keep their own statements, and `e2e/tests/specs/stats_charts.rs` holds the browser's folds to them. -The Database Health card's row count is the one reading that is not a scan of anything. `SELECT COUNT(*)` has no shortcut in SQLite — it walks the smallest index end to end, 1 386 pages on that database, for a number the card prints and two of its estimates divide by — so the count lives in `settings` under `query_log_count`, seeded by the version-13 migration and moved by the three statements that change how many rows `query_logs` holds: the logger's insert batch, the hourly prune, and Clear All. Each moves it inside its own transaction, which is what makes the counter unable to disagree with the table; `total_log_count` falls back to counting when the row is missing, which is the state the migration seeds it out of. The card went from 1 398 pages to 14. +The Database Health card's row count is the one reading that is not a scan of anything. `SELECT COUNT(*)` has no shortcut in SQLite — it walks the smallest index end to end, 1 386 pages on that database, for a number the card prints and two of its estimates divide by — so the count lives in `settings` under `query_log_count`, seeded by the version-13 migration and moved by the three statements that change how many rows `query_logs` holds: the logger's insert batch, the hourly prune, and Clear All. Each moves it inside its own transaction, which is what makes the counter unable to disagree with the table; `total_log_count` falls back to counting when the row is missing, which is the state the migration seeds it out of. The card went from 1 398 pages to 14. The query log's pager asks for the same number whenever no filter narrows it, so `count_logs` reads the counter in that case through the same `read_log_count`, and only counts once a filter is applied. The dashboard pays for its readings every 10 seconds rather than once a visit, which makes a scan it repeats the most expensive kind. Its summary asked two statements for totals and blocks, then cache hits and latency, over the same 30 days of the metrics index; `summary_multi_since` moves the allowed-only filter from the `WHERE` into each `CASE` and answers both from one scan, 2 152 pages a tick instead of 4 304. With the upstream index, a tick on that database dropped from 8 304 page misses to 4 755. diff --git a/CLAUDE.md b/CLAUDE.md index eb8149a..840372d 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -134,7 +134,7 @@ Statistics adds the conventions for a page whose readings sit in a **chosen wind - **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; `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. +- **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 both the Database Health card and the query log's pager (whenever no filter is applied, via `count_logs`) ask 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. Account adds the conventions for **actions that need a password proof**: diff --git a/e2e/src/server.rs b/e2e/src/server.rs index a5f3307..cbe7744 100644 --- a/e2e/src/server.rs +++ b/e2e/src/server.rs @@ -29,6 +29,13 @@ const STARTUP_TIMEOUT: Duration = Duration::from_secs(60); /// How long a SIGTERM gets before the process is killed outright. const SHUTDOWN_GRACE: Duration = Duration::from_secs(10); +/// Brings the maintained `query_logs` row count back in line after a seed — +/// see [`Server::seed`]. An upsert, because the counter row is only there once +/// noadd has migrated this database. +const RECOUNT_LOGS: &str = "INSERT INTO settings (key, value) \ + SELECT 'query_log_count', COUNT(*) FROM query_logs WHERE true \ + ON CONFLICT(key) DO UPDATE SET value = excluded.value;\n"; + /// A noadd instance: its ports, its database, and the process serving them. #[derive(Debug)] pub struct Server { @@ -127,6 +134,11 @@ impl Server { /// traffic and rewrite settings noadd reads at boot, so they are written /// between the two starts rather than underneath a live server. /// + /// Rows written here bypass the write paths that maintain `query_logs`' + /// row count in `settings`, so the count is recomputed after every seed; + /// otherwise the query log's pager and the Database Health card report the + /// total from before the fixture. + /// /// # Errors /// /// Fails when `sqlite3` is missing or exits non-zero. @@ -150,7 +162,7 @@ impl Server { .stdin .as_mut() .context("sqlite3 stdin")? - .write_all(sql.as_bytes()) + .write_all(format!("{sql}\n{RECOUNT_LOGS}").as_bytes()) .await?; drop(child.stdin.take()); let status = child.wait().await?; diff --git a/src/db.rs b/src/db.rs index 3f0f0e5..960a001 100644 --- a/src/db.rs +++ b/src/db.rs @@ -1103,6 +1103,12 @@ impl Database { token.as_deref(), query_type.as_deref(), ); + // Nothing narrowed the count, so it is the table's row count, + // which the write paths maintain. Counting it walks the smallest + // index end to end on every load of an unfiltered query log. + if param_values.is_empty() { + return read_log_count(conn); + } let params_refs: Vec<&dyn rusqlite::types::ToSql> = param_values .iter() @@ -2654,25 +2660,12 @@ impl Database { /// prints and two of its estimates divide by. The counter is one row of /// `settings`, written inside the same transaction as every insert, prune /// and clear, so it cannot report a total the table does not hold. + /// [`Self::count_logs`] reads the same counter when no filter is applied. /// /// A database with no counter row counts, which is what the migration /// seeded it from. pub async fn total_log_count(&self) -> Result { - let result = self - .reader() - .call(|conn| { - let stored: Option = conn - .prepare_cached("SELECT value FROM settings WHERE key = ?1")? - .query_row(params![QUERY_LOG_COUNT_KEY], |row| row.get(0)) - .optional()?; - if let Some(count) = stored.and_then(|v| v.parse::().ok()) { - return Ok(count); - } - let count: i64 = - conn.query_row("SELECT COUNT(*) FROM query_logs", [], |row| row.get(0))?; - Ok(count) - }) - .await?; + let result = self.reader().call(|conn| read_log_count(conn)).await?; Ok(result) } @@ -2885,6 +2878,19 @@ fn set_log_count(conn: &rusqlite::Connection, count: i64) -> rusqlite::Result<() Ok(()) } +/// The maintained `query_logs` row count, counted instead only when the +/// counter row is missing or unreadable. +fn read_log_count(conn: &rusqlite::Connection) -> rusqlite::Result { + let stored: Option = conn + .prepare_cached("SELECT value FROM settings WHERE key = ?1")? + .query_row(params![QUERY_LOG_COUNT_KEY], |row| row.get(0)) + .optional()?; + if let Some(count) = stored.and_then(|v| v.parse::().ok()) { + return Ok(count); + } + conn.query_row("SELECT COUNT(*) FROM query_logs", [], |row| row.get(0)) +} + /// Add a column to `table` if it doesn't already exist. /// /// `SQLite` doesn't support `ALTER TABLE ... ADD COLUMN IF NOT EXISTS`, so we diff --git a/tests/db_test.rs b/tests/db_test.rs index 44830c1..0040c6a 100644 --- a/tests/db_test.rs +++ b/tests/db_test.rs @@ -976,9 +976,10 @@ async fn test_filter_list_url_fetches_one_row_by_id() { ); } -/// `total_log_count` is a counter now rather than a `COUNT(*)`, so every path -/// that changes how many rows `query_logs` holds has to move it. One that does -/// not leaves the Database Health card reporting a total the table stopped +/// `total_log_count` is a counter now rather than a `COUNT(*)`, and so is an +/// unfiltered `count_logs`, so every path that changes how many rows +/// `query_logs` holds has to move it. One that does not leaves the Database +/// Health card and the query log's pager reporting a total the table stopped /// holding, and nothing else would notice. #[tokio::test] async fn the_log_count_follows_every_write_that_changes_it() { @@ -998,13 +999,23 @@ async fn the_log_count_follows_every_write_that_changes_it() { } } - // The counter and a real count of the same rows, which must never differ. + // Every reader of the counter, against the rows themselves, which must + // never differ. async fn assert_holds(db: &Database, expected: i64) { + let rows = db + .query_logs(i64::MAX, 0, None, None, None, None) + .await + .unwrap(); + assert_eq!(rows.len() as i64, expected); assert_eq!(db.total_log_count().await.unwrap(), expected); assert_eq!( db.count_logs(None, None, None, None).await.unwrap(), expected ); + assert_eq!( + db.count_logs(Some(" "), None, None, None).await.unwrap(), + expected + ); } let db = test_db().await; diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index 5a346ce..3b768ff 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -300,7 +300,8 @@ async fn the_total_log_count_is_read_rather_than_counted() { let db = seeded_db().await; let read = page_misses(&db, || db.total_log_count()).await; - let counted = page_misses(&db, || db.count_logs(None, None, None, None)).await; + // `*` matches every domain, so this is the same total arrived at by counting. + let counted = page_misses(&db, || db.count_logs(Some("*"), None, None, None)).await; assert!( counted > 0, @@ -312,3 +313,29 @@ async fn the_total_log_count_is_read_rather_than_counted() { is total_log_count back on COUNT(*)?" ); } + +/// The query log's pager asks for its total on every load, and with no filter +/// applied that total is the table's row count — the number the write paths +/// already maintain. Counting it walks the smallest index end to end, which on +/// an unfiltered first page is nearly the whole cost of the load. +#[tokio::test] +async fn the_unfiltered_query_log_count_is_read_rather_than_counted() { + let db = seeded_db().await; + + let unfiltered = page_misses(&db, || db.count_logs(None, None, None, None)).await; + // A blank search box is no filter at all, so it must take the same path. + let blank = page_misses(&db, || db.count_logs(Some(" "), None, None, None)).await; + let counted = page_misses(&db, || db.count_logs(Some("*"), None, None, None)).await; + + assert!( + counted > 0, + "counting read no pages at all — the measurement is not working" + ); + for (label, read) in [("no filter", unfiltered), ("blank search", blank)] { + assert!( + read * 4 < counted, + "{label} read {read} pages and counting the same rows read {counted} — \ + is count_logs counting when nothing narrows it?" + ); + } +}