From ab0981d11fb16d65ec08ae07151f084596b97cf8 Mon Sep 17 00:00:00 2001 From: Heng-Yi Wu <2316687+henry40408@users.noreply.github.com> Date: Mon, 14 Sep 2026 00:33:00 +0800 Subject: [PATCH] perf(stats): fold the dashboard's readings out of the statistics rollups Every dashboard tick scanned 30 days of idx_query_logs_ts_metrics for its summary, and the top domain, client and upstream lists scanned their own indexes over 24 hours. Under the default retention those windows are the whole table, so the tick cost an index's length every 10 seconds. summary_multi_since, timeline_since, traffic_lists_since, domain_stats_since and top_upstreams_since now take every whole unit from the rollups and only the part of a unit their window starts inside from query_logs, in one statement. Nothing is read at the far end: the rollups are written with the rows, so the current unit is complete. timeline_since keeps counting the table when its bucket is finer than a quarter hour, which only happens while the log is a few hours old. Top upstreams now break ties by name, as the other lists do. Page misses, same database copies and BENCH_NOW as the baseline: - 370 677 rows: tick 3 408 -> 190, first response 3 117 -> 180, domain suggestions 3 973 -> 557, Statistics visit 7 937 -> 2 718 - 1 482 708 rows: tick 10 774 -> 227, first response 10 444 -> 215, domain suggestions 6 192 -> 559, Statistics visit 31 883 -> 11 641 No reading in any of the three benches got worse. Co-Authored-By: Claude Opus 5 (1M context) --- ARCHITECTURE.md | 18 +- CLAUDE.md | 2 +- src/db.rs | 317 ++++++++++++++++++++-------------- tests/stats_db_test.rs | 221 ++++++++++++++++++++++++ tests/stats_page_miss_test.rs | 128 +++++++------- 5 files changed, 485 insertions(+), 201 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 4b1b907..b178a8f 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -244,10 +244,10 @@ Everything is in a single SQLite file (`noadd.sqlite3` by default; a legacy `noa | Index | Serves | | --- | --- | | `timestamp` | the time-window filter every stats query starts with | -| `(domain, timestamp)` | the query log's domain search; top and unique domains for callers asking for domains alone | -| `(timestamp, domain, client_ip, doh_token)` | top domains and top clients together, on the Statistics page and the dashboard | -| `(timestamp, blocked, cached, response_ms, query_type, has_result)` | timeline, query-type breakdown, latency histogram, outcome breakdown, the dashboard summary | -| `(timestamp, upstream, response_ms) WHERE upstream IS NOT NULL` | top upstreams | +| `(domain, timestamp)` | the query log's domain search | +| `(timestamp, domain, client_ip, doh_token)` | nothing since the top domain and client lists moved onto the rollups (*Rollups* below) | +| `(timestamp, blocked, cached, response_ms, query_type, has_result)` | the Statistics page's scan, the `/api/stats/*` timeline and breakdowns, the query log's action and type filters | +| `(timestamp, upstream, response_ms) WHERE upstream IS NOT NULL` | nothing since top upstreams moved onto the rollups | `(domain, timestamp)` puts the grouped column first and `timestamp` last, which made it covering for a `GROUP BY … WHERE timestamp >= ?` shape — the aggregation reads the index alone instead of scanning the window and building a temp b-tree over it. The client index that sat beside it, `(client_ip, doh_token, timestamp)`, did the same for top clients and took them from 143 ms to 20 ms on a 447 k-row database. The cost of that order is that the window cannot restrict it: a 24-hour question skip-scans the whole index, one seek per distinct group. @@ -271,7 +271,11 @@ The quarter hour is there because it is the finest bucket any chart draws and th Deletes are not a trigger. A `DELETE` trigger would unwind a prune row by row and turn off SQLite's truncate optimisation for Clear All, so both do it in their own transaction instead: Clear All empties the five tables, and `prune_logs_before` calls `unwind_stats_rollups` before its delete. That drops whole units before the cutoff and, for the one quarter and one hour the cutoff falls inside, recounts the rows about to go and subtracts them — so the prune keeps its exact cutoff rather than rounding retention to the hour. Pruning a day from that database writes 5 151 pages and misses 13 971, against 5 020 and 12 282 without rollups. `rollups_follow_every_write_that_changes_query_logs` (`src/db.rs`) is the guard: it compares every table with its recount after batches, a direct SQL insert, prunes inside and on a unit boundary, and Clear All. -Version 16 fills the rollups from the rows already logged, which on that database reads 101 420 pages and writes 3 714. The fill replaces rather than adds, so a migration interrupted before `user_version` moved is safe to run again. Nothing reads the rollups yet; the dashboard and the Statistics page move onto them in later changes. +Version 16 fills the rollups from the rows already logged, which on that database reads 101 420 pages and writes 3 714. The fill replaces rather than adds, so a migration interrupted before `user_version` moved is safe to run again. + +A reader takes every unit from the first whole one inside its window (`first_whole_unit`) from a rollup, and only the rest of the unit the window starts inside from `query_logs`, through `idx_query_logs_timestamp`. Nothing is read from the table at the other end: the rollups are written in the same transaction as the rows, so the unit still filling up is already complete. Both halves are one statement, so they read one snapshot. `summary_multi_since` tells its three windows apart by which arm a table row came from — a row belongs to the one window whose partial quarter it fills, while the wider windows count that quarter through the rollup. `timeline_since` reads `query_stats_quarter` when its bucket is a whole number of quarters and counts the table directly otherwise, which only happens while the log is younger than a few hours. + +The dashboard reads nothing else: `summary_multi_since`, `timeline_since`, `traffic_lists_since` and `top_upstreams_since` all fold rollups, and so does `domain_stats_since`, which answers the domain suggestions. On the 1.48 M-row database a dashboard tick went from 10 774 page misses to 227, the first response from 10 444 to 215, and the domain suggestions from 6 192 to 559; a Statistics visit over 30 days went from 31 883 to 11 641, the rest of it being `stats_scan_since`. `dashboard_readings_equal_a_recount_of_the_table` (`tests/stats_db_test.rs`) holds every one of these to the statement it replaced, run on the same rows, for windows starting before the data, on an hour, on a quarter, inside each, and after it. ### Measuring these queries @@ -291,9 +295,9 @@ The charts did still pay for scans of their own after that: the browser fetched 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. +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. Those readings have since moved onto the rollups (see *Rollups*), which no longer read either index. -`INDEXED BY` appears on every statement that reads this index, in both directions. The ones that need `blocked`, `cached` or `has_result` name `idx_query_logs_ts_metrics` because the planner otherwise takes the smaller `idx_query_logs_timestamp` and pays a rowid lookup per row; top upstreams names its partial index so drifting statistics cannot send it back to that lookup; the heatmap, which reads `timestamp` and nothing else, names `idx_query_logs_timestamp` for the opposite reason — left alone the planner took the metrics index and read 2 153 pages where 1 386 answer it. +`INDEXED BY` appears on every statement that reads this index, in both directions. The ones that need `blocked`, `cached` or `has_result` name `idx_query_logs_ts_metrics` because the planner otherwise takes the smaller `idx_query_logs_timestamp` and pays a rowid lookup per row; the rollup readers' table arms name `idx_query_logs_timestamp`, where that lookup is the point — they read at most one unit of rows; the heatmap, which reads `timestamp` and nothing else, names `idx_query_logs_timestamp` for the opposite reason — left alone the planner took the metrics index and read 2 153 pages where 1 386 answer it. Every index migration runs `ANALYZE`. A new index alone is not always enough — the planner keeps its old plan until `sqlite_stat1` is refreshed — and the hourly `PRAGMA optimize` lets those statistics drift a long way in the meantime. diff --git a/CLAUDE.md b/CLAUDE.md index 6434000..92eea50 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -133,7 +133,7 @@ Statistics adds the conventions for a page whose readings sit in a **chosen wind - **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; `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. +- **One scan per index, not one per reading.** `stats_scan_since` and `traffic_lists_since` (`src/db.rs`) are the page's two reads — the second answering top domains, the distinct-domain count and top clients from one statement over the domain and client rollups — 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 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. - **The same holds for the statistics rollups** (`query_stats_*`, see ARCHITECTURE.md *Rollups*), which must always equal a recount of `query_logs`. Inserts are covered by the `query_logs_maintain_stats` trigger whatever writes them; a new path that *deletes* from `query_logs` has to unwind them in its own transaction, as `prune_logs_before` (`unwind_stats_rollups`) and Clear All do. - 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/src/db.rs b/src/db.rs index 4b1bd56..ff460f4 100644 --- a/src/db.rs +++ b/src/db.rs @@ -369,6 +369,17 @@ const ROLLUP_QUARTER_MS: i64 = QUARTER_SECS * 1000; /// Width of one row of the hourly rollups, in milliseconds. const ROLLUP_HOUR_MS: i64 = 3_600_000; +/// The first rollup unit wholly inside a window that starts at `since_ms`. +/// +/// A reader takes that unit and every later one from the rollup, and +/// `[since_ms, first * unit_ms)` — the rest of the unit the window starts +/// inside, empty when it starts on a boundary — from `query_logs`. Nothing is +/// needed at the other end: the rollups are written in the same transaction as +/// the rows, so even the unit still filling up is complete. +fn first_whole_unit(since_ms: i64, unit_ms: i64) -> i64 { + since_ms.div_euclid(unit_ms) + i64::from(since_ms.rem_euclid(unit_ms) != 0) +} + /// Pre-aggregated counts of `query_logs`, one table per grain a reader folds. /// /// Every statistic the dashboard and the Statistics page show is a count, a @@ -2224,14 +2235,17 @@ impl Database { Ok(result) } - /// The dashboard summary's figures for three nested windows, in one scan of - /// `idx_query_logs_ts_metrics`. + /// The dashboard summary's figures for three nested windows, folded out of + /// `query_stats_quarter`. /// - /// Totals and blocks came from one statement and cache hits and latency - /// from another, each walking the same 30 days of the same index — on every - /// dashboard tick, 4 304 pages on a 370 k-row database where 2 152 answer - /// both. The allowed-only figures take their filter into the `CASE` rather - /// than the `WHERE`, so one pass serves both halves. + /// Each window reads its whole quarters from the rollup and, from the table, + /// only the part of a quarter it starts inside — see `STATS_ROLLUP_SCHEMA`. + /// Answered from the table this was one scan of 30 days of + /// `idx_query_logs_ts_metrics` on every dashboard tick: 9 480 pages on a + /// 1.48 M-row database, because under the default retention those 30 days + /// are the whole table. The three windows are told apart by which arm a row + /// came from — a table row belongs to the one window whose partial quarter + /// it fills, and the wider windows count that quarter through the rollup. /// /// All `since_*` values are in epoch seconds. Caller MUST pass the widest /// window as `since_30d`. @@ -2244,31 +2258,64 @@ impl Database { let today_ms = since_today * 1000; let d7_ms = since_7d * 1000; let d30_ms = since_30d * 1000; + let quarters = [today_ms, d7_ms, d30_ms].map(|ms| first_whole_unit(ms, ROLLUP_QUARTER_MS)); let result = self .reader() .call(move |conn| { - // `INDEXED BY` for the reason `metrics_by_bucket_since` gives. let mut stmt = conn.prepare_cached( - "SELECT - COUNT(CASE WHEN timestamp >= ?1 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?1 THEN blocked END), 0), - COUNT(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN cached END), 0), - COALESCE(AVG(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN response_ms END), 0), - COUNT(CASE WHEN timestamp >= ?2 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?2 THEN blocked END), 0), - COUNT(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN cached END), 0), - COALESCE(AVG(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN response_ms END), 0), - COUNT(*), - COALESCE(SUM(blocked), 0), - COUNT(CASE WHEN blocked = 0 THEN 1 END), - COALESCE(SUM(CASE WHEN blocked = 0 THEN cached END), 0), - COALESCE(AVG(CASE WHEN blocked = 0 THEN response_ms END), 0) - FROM query_logs INDEXED BY idx_query_logs_ts_metrics - WHERE timestamp >= ?3", + "WITH p AS ( + SELECT 'r' AS kind, quarter AS k, blocked, cached, count AS n, sum_ms AS ms + FROM query_stats_quarter WHERE quarter >= ?6 + UNION ALL + SELECT 'h1', 0, blocked, cached, 1, response_ms + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?4 * 900000 + UNION ALL + SELECT 'h7', 0, blocked, cached, 1, response_ms + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?2 AND timestamp < ?5 * 900000 + UNION ALL + SELECT 'h30', 0, blocked, cached, 1, response_ms + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?3 AND timestamp < ?6 * 900000 + ), + w AS ( + SELECT (kind = 'h1' OR (kind = 'r' AND k >= ?4)) AS in1, + (kind = 'h7' OR (kind = 'r' AND k >= ?5)) AS in7, + (kind = 'h30' OR kind = 'r') AS in30, + blocked, cached, n, ms + FROM p + ) + SELECT + COALESCE(SUM(CASE WHEN in1 THEN n END), 0), + COALESCE(SUM(CASE WHEN in1 THEN n * blocked END), 0), + COALESCE(SUM(CASE WHEN in1 AND blocked = 0 THEN n END), 0), + COALESCE(SUM(CASE WHEN in1 AND blocked = 0 THEN n * cached END), 0), + COALESCE(CAST(SUM(CASE WHEN in1 AND blocked = 0 THEN ms END) AS REAL) + / SUM(CASE WHEN in1 AND blocked = 0 THEN n END), 0), + COALESCE(SUM(CASE WHEN in7 THEN n END), 0), + COALESCE(SUM(CASE WHEN in7 THEN n * blocked END), 0), + COALESCE(SUM(CASE WHEN in7 AND blocked = 0 THEN n END), 0), + COALESCE(SUM(CASE WHEN in7 AND blocked = 0 THEN n * cached END), 0), + COALESCE(CAST(SUM(CASE WHEN in7 AND blocked = 0 THEN ms END) AS REAL) + / SUM(CASE WHEN in7 AND blocked = 0 THEN n END), 0), + COALESCE(SUM(CASE WHEN in30 THEN n END), 0), + COALESCE(SUM(CASE WHEN in30 THEN n * blocked END), 0), + COALESCE(SUM(CASE WHEN in30 AND blocked = 0 THEN n END), 0), + COALESCE(SUM(CASE WHEN in30 AND blocked = 0 THEN n * cached END), 0), + COALESCE(CAST(SUM(CASE WHEN in30 AND blocked = 0 THEN ms END) AS REAL) + / SUM(CASE WHEN in30 AND blocked = 0 THEN n END), 0) + FROM w", )?; - let row = stmt.query_row(params![today_ms, d7_ms, d30_ms], |row| { + let args = params![ + today_ms, + d7_ms, + d30_ms, + quarters[0], + quarters[1], + quarters[2] + ]; + let row = stmt.query_row(args, |row| { let window = |at: usize| -> rusqlite::Result { Ok(WindowSummary { total: row.get(at)?, @@ -2295,27 +2342,38 @@ impl Database { } /// The busiest domains in the window and how many distinct ones there were, - /// from one pass over `idx_query_logs_domain_ts`. + /// folded out of `query_stats_domain_hour`. /// - /// Asked separately these are two statements — `GROUP BY domain ORDER BY - /// cnt DESC LIMIT n` and `COUNT(DISTINCT domain)` — that group the same - /// rows the same way and each scan the whole index, because the index is - /// ordered `(domain, timestamp)` and a timestamp range cannot restrict it. - /// The CTE is materialized once and read twice, which is 3 977 page misses - /// instead of 7 954 on a 370 k-row database. + /// Whole hours come from the rollup and the part of an hour the window + /// starts inside from the table — see `STATS_ROLLUP_SCHEMA`. From the table + /// alone this read `idx_query_logs_domain_ts`, which a timestamp range + /// cannot restrict because the domain comes first: 6 192 pages for the + /// week of domain suggestions on a 1.48 M-row database. The CTE is + /// materialized once and read twice, so the count and the list share one + /// grouping. /// /// `unique` is 0 when the window is empty, which is also when `top` is: the /// count rides on the rows, so there is nothing to report either way. pub async fn domain_stats_since(&self, since: i64, limit: i64) -> Result { let since_ms = since * 1000; + let hour = first_whole_unit(since_ms, ROLLUP_HOUR_MS); let stats = self .reader() .call(move |conn| { let mut stmt = conn.prepare_cached( - "WITH d AS ( SELECT domain, COUNT(*) AS cnt FROM query_logs WHERE timestamp >= ?1 GROUP BY domain ) SELECT (SELECT COUNT(*) FROM d), domain, cnt FROM d ORDER BY cnt DESC, domain LIMIT ?2", + "WITH d AS ( + SELECT domain, SUM(n) AS cnt FROM ( + SELECT domain, count AS n FROM query_stats_domain_hour WHERE hour >= ?2 + UNION ALL + SELECT domain, 1 FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?2 * 3600000 + ) GROUP BY domain + ) + SELECT (SELECT COUNT(*) FROM d), domain, cnt + FROM d ORDER BY cnt DESC, domain LIMIT ?3", )?; let rows = stmt - .query_map(params![since_ms, limit], |row| { + .query_map(params![since_ms, hour, limit], |row| { Ok(( row.get::<_, i64>(0)?, TopDomain { @@ -2335,8 +2393,7 @@ impl Database { Ok(stats) } - /// A fold over [`Self::traffic_lists_since`], whose index is the only one - /// carrying the client columns. + /// A fold over [`Self::traffic_lists_since`]. pub async fn top_clients_since( &self, since: i64, @@ -2346,14 +2403,16 @@ impl Database { } /// The busiest domains, how many distinct ones there were, and the busiest - /// clients, from one scan of `idx_query_logs_ts_domain_client`. + /// clients, folded out of `query_stats_domain_hour` and + /// `query_stats_client_hour`. /// - /// The Statistics page and every dashboard tick want both lists, and used - /// to read two indexes for them. Grouped at `(domain, client_ip, - /// doh_token)`, one statement carries both: the rows are one per pairing a - /// window actually held, which on a home network is a few thousand, and - /// both lists are folded out of them here. The index is timestamp-first, - /// so a short window reads a short stretch of it. + /// The Statistics page and every dashboard tick want both lists. Whole + /// hours come from the rollups and the part of an hour the window starts + /// inside from the table — see `STATS_ROLLUP_SCHEMA`. From the table alone + /// this was a scan of `idx_query_logs_ts_domain_client` as long as the + /// window: 22 394 pages for the Statistics page's 30 days on a 1.48 M-row + /// database. Both lists are one statement so they read one snapshot; the + /// first column says which list a row belongs to. /// /// Ties in either list break by name, the same way /// [`Self::domain_stats_since`] breaks them, so the two spellings of top @@ -2364,26 +2423,40 @@ impl Database { limit: i64, ) -> Result { let since_ms = since * 1000; + let hour = first_whole_unit(since_ms, ROLLUP_HOUR_MS); let limit = usize::try_from(limit).unwrap_or(0); let lists = self .reader() .call(move |conn| { - // `INDEXED BY` because `idx_query_logs_timestamp` also matches - // the range and is smaller; taking it would be a rowid lookup - // per row. + // The rollup stores plain DNS's missing token as '', which a + // real token never is, so `NULLIF` restores the `NULL`. let mut stmt = conn.prepare_cached( - "SELECT domain, client_ip, doh_token, COUNT(*) \ - FROM query_logs INDEXED BY idx_query_logs_ts_domain_client \ - WHERE timestamp >= ?1 \ - GROUP BY domain, client_ip, doh_token", + "SELECT 0, domain, NULL, SUM(n) FROM ( + SELECT domain, count AS n FROM query_stats_domain_hour WHERE hour >= ?2 + UNION ALL + SELECT domain, 1 FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?2 * 3600000 + ) GROUP BY domain + UNION ALL + SELECT 1, client_ip, NULLIF(token, ''), SUM(n) FROM ( + SELECT client_ip, doh_token AS token, count AS n + FROM query_stats_client_hour WHERE hour >= ?2 + UNION ALL + SELECT client_ip, COALESCE(doh_token, ''), 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?2 * 3600000 + ) GROUP BY client_ip, token", )?; let mut domains: HashMap = HashMap::new(); let mut clients: HashMap<(String, Option), i64> = HashMap::new(); - let mut rows = stmt.query(params![since_ms])?; + let mut rows = stmt.query(params![since_ms, hour])?; while let Some(row) = rows.next()? { let count: i64 = row.get(3)?; - *domains.entry(row.get(0)?).or_default() += count; - *clients.entry((row.get(1)?, row.get(2)?)).or_default() += count; + if row.get::<_, i64>(0)? == 0 { + domains.insert(row.get(1)?, count); + } else { + clients.insert((row.get(1)?, row.get(2)?), count); + } } Ok((domains, clients)) }) @@ -2420,27 +2493,36 @@ impl Database { }) } + /// The busiest upstreams in the window with their mean response time, + /// folded out of `query_stats_upstream_hour`. + /// + /// Whole hours come from the rollup and the part of an hour the window + /// starts inside from the table — see `STATS_ROLLUP_SCHEMA`. The mean is the + /// summed response time over the count, which is exactly what `AVG` over the + /// same integer rows returns. Ties break by name, as the other lists do. pub async fn top_upstreams_since( &self, since: i64, limit: i64, ) -> Result, DbError> { let since_ms = since * 1000; + let hour = first_whole_unit(since_ms, ROLLUP_HOUR_MS); let rows = self .reader() .call(move |conn| { - // `INDEXED BY` so a drift in the planner's statistics cannot send - // this back to `idx_query_logs_timestamp` and a lookup per row. - // The `upstream IS NOT NULL` term is what lets the partial index - // answer at all. let mut stmt = conn.prepare_cached( - "SELECT upstream, COUNT(*) as cnt, AVG(response_ms) as avg_ms \ - FROM query_logs INDEXED BY idx_query_logs_ts_upstream \ - WHERE timestamp >= ?1 AND upstream IS NOT NULL \ - GROUP BY upstream ORDER BY cnt DESC LIMIT ?2", + "SELECT upstream, SUM(n) AS cnt, CAST(SUM(ms) AS REAL) / SUM(n) AS avg_ms FROM ( + SELECT upstream, count AS n, sum_ms AS ms + FROM query_stats_upstream_hour WHERE hour >= ?2 + UNION ALL + SELECT upstream, 1, response_ms + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?2 * 3600000 + AND upstream IS NOT NULL + ) GROUP BY upstream ORDER BY cnt DESC, upstream LIMIT ?3", )?; let rows = stmt - .query_map(params![since_ms, limit], |row| { + .query_map(params![since_ms, hour, limit], |row| { Ok(TopUpstream { upstream: row.get(0)?, count: row.get(1)?, @@ -2819,25 +2901,47 @@ impl Database { since: i64, // unix seconds bucket_secs: i64, ) -> Result, DbError> { + let since_ms = since * 1000; + let bucket_ms = bucket_secs * 1000; + let quarter = first_whole_unit(since_ms, ROLLUP_QUARTER_MS); let rows = self .reader() .call(move |conn| { - let since_ms = since * 1000; - let bucket_ms = bucket_secs * 1000; - let mut stmt = conn.prepare_cached( - "SELECT (timestamp / ?1) * ?1 as bucket, COUNT(*) as total, COALESCE(SUM(blocked), 0) as blocked FROM query_logs WHERE timestamp >= ?2 GROUP BY bucket ORDER BY bucket", - )?; - let since = since_ms; - let bucket_secs = bucket_ms; - let rows = stmt - .query_map(params![bucket_secs, since], |row| { - Ok(TimelinePoint { - timestamp: row.get::<_, i64>(0)? / 1000, // return seconds - total: row.get(1)?, - blocked: row.get(2)?, - }) - })? - .collect::, _>>()?; + // A bucket that is a whole number of quarters is a sum of + // `query_stats_quarter` rows, plus the table for the quarter the + // window starts inside. A finer bucket only happens while the + // log is younger than a few hours, when the table is small + // enough to count directly. + let point = |row: &rusqlite::Row<'_>| { + Ok(TimelinePoint { + timestamp: row.get::<_, i64>(0)? / 1000, // return seconds + total: row.get(1)?, + blocked: row.get(2)?, + }) + }; + let rows = if bucket_ms % ROLLUP_QUARTER_MS == 0 { + conn.prepare_cached( + "SELECT bucket, SUM(total), SUM(blocked) FROM ( + SELECT (quarter * 900000 / ?1) * ?1 AS bucket, + count AS total, blocked * count AS blocked + FROM query_stats_quarter WHERE quarter >= ?3 + UNION ALL + SELECT (timestamp / ?1) * ?1, 1, blocked + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?2 AND timestamp < ?3 * 900000 + ) GROUP BY bucket ORDER BY bucket", + )? + .query_map(params![bucket_ms, since_ms, quarter], point)? + .collect::, _>>()? + } else { + conn.prepare_cached( + "SELECT (timestamp / ?1) * ?1 as bucket, COUNT(*) as total, \ + COALESCE(SUM(blocked), 0) as blocked FROM query_logs \ + WHERE timestamp >= ?2 GROUP BY bucket ORDER BY bucket", + )? + .query_map(params![bucket_ms, since_ms], point)? + .collect::, _>>()? + }; Ok(rows) }) .await?; @@ -3823,59 +3927,6 @@ mod tests { ); } - /// `INDEXED BY` fixes which index the lists read, but not whether that - /// index answers them alone. Assert the plan is covering, which is what - /// keeps a table lookup per row out of every dashboard tick. - #[tokio::test] - async fn the_traffic_lists_are_covered_by_their_index() { - let dir = tempfile::tempdir().unwrap(); - let path = dir.path().join("plan.db"); - let db = Database::open(path.to_str().unwrap()).await.unwrap(); - - let logs: Vec = (0..500) - .map(|i| QueryLogEntry { - timestamp: 1_000_000 + i, - domain: format!("d{}.example", i % 50), - query_type: "A".into(), - client_ip: format!("10.0.0.{}", i % 25), - blocked: false, - cached: false, - response_ms: i % 7, - upstream: None, - doh_token: None, - result: None, - authenticated_data: false, - }) - .collect(); - db.insert_query_logs(&logs).await.unwrap(); - - // The writer, not `reader()`: ANALYZE writes sqlite_stat1, and the read - // pool is opened SQLITE_OPEN_READ_ONLY. - let plan = db - .conn - .call(|conn| { - conn.execute_batch("ANALYZE;")?; - // The statement `traffic_lists_since` prepares, verbatim. - let mut stmt = conn.prepare( - "EXPLAIN QUERY PLAN SELECT domain, client_ip, doh_token, COUNT(*) \ - FROM query_logs INDEXED BY idx_query_logs_ts_domain_client \ - WHERE timestamp >= ?1 \ - GROUP BY domain, client_ip, doh_token", - )?; - let rows = stmt - .query_map(params![0_i64], |row| row.get::<_, String>(3))? - .collect::, _>>()?; - Ok::<_, tokio_rusqlite::Error>(rows.join(" | ")) - }) - .await - .unwrap(); - - assert!( - plan.contains("COVERING INDEX idx_query_logs_ts_domain_client"), - "the traffic lists should read their index alone, got: {plan}" - ); - } - #[tokio::test] async fn migration_v6_drops_credential_and_adds_tables() { let dir = tempfile::tempdir().unwrap(); diff --git a/tests/stats_db_test.rs b/tests/stats_db_test.rs index 09566e6..dc068e3 100644 --- a/tests/stats_db_test.rs +++ b/tests/stats_db_test.rs @@ -833,3 +833,224 @@ async fn the_stats_scan_of_an_empty_window_reports_nothing() { assert_eq!(scan.metrics.latency.sample_count, 0); assert!(scan.metrics.outcomes.is_empty()); } + +const HOUR_MS: i64 = 3_600_000; + +/// Three days of traffic starting 1 234 ms past an hour, one query every +/// 86 413 ms, so rows fall on both sides of every quarter and hour boundary a +/// window can start at. Every column a reading groups or sums varies. +async fn recount_db() -> (Database, String) { + let dir = tempdir().unwrap(); + let path = dir.keep().join("recount.db"); + let path_str = path.to_str().unwrap().to_string(); + let db = Database::open(&path_str).await.unwrap(); + let start = 472_222 * HOUR_MS + 1_234; + let entries: Vec = (0..3_000_usize) + .map(|n| (n, i64::try_from(n).unwrap())) + .map(|(n, i)| QueryLogEntry { + timestamp: start + i * 86_413, + domain: format!("d{}.example", (i * 7) % 23), + query_type: ["A", "AAAA", "HTTPS"][n % 3].to_string(), + client_ip: format!("10.0.0.{}", i % 5), + blocked: i % 4 == 0, + cached: i % 3 == 0, + upstream: (i % 5 != 0).then(|| format!("udp://9.9.9.{}:53", i % 3)), + doh_token: [None, Some("phone"), Some("tablet")][n % 3].map(str::to_string), + result: (i % 2 == 0).then(|| "1.2.3.4".to_string()), + response_ms: (i * 13) % 97, + authenticated_data: false, + }) + .collect(); + for chunk in entries.chunks(500) { + db.insert_query_logs(chunk).await.unwrap(); + } + (db, path_str) +} + +/// Window starts, in seconds, against [`recount_db`]: before the data, on an +/// hour, on a quarter, inside a quarter, inside an hour, and after the data. +fn recount_sinces() -> Vec { + let start_s = 472_222 * 3_600; + vec![ + 0, + start_s + 5 * 3_600, + start_s + 7 * 3_600 + 900, + start_s + 20 * 3_600 + 1_000, + start_s + 41 * 3_600 + 2_345, + start_s + 100 * 3_600, + ] +} + +/// The dashboard's readings now fold rollups and the table only where a window +/// starts inside a unit, so the answers are checked against the statements they +/// replaced, run on the same rows: any disagreement is a query reporting +/// traffic the table does not hold. +#[tokio::test] +async fn dashboard_readings_equal_a_recount_of_the_table() { + let (db, path) = recount_db().await; + let raw = rusqlite::Connection::open(&path).unwrap(); + + for since in recount_sinces() { + let (s1, s7, s30) = (since, since - 2 * 3_600 - 17, since - 30 * 3_600 - 900); + let summary = db.summary_multi_since(s1, s7, s30).await.unwrap(); + let expected: Vec<(i64, i64, i64, i64, f64)> = raw + .query_row( + "SELECT + COUNT(CASE WHEN timestamp >= ?1 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?1 THEN blocked END), 0), + COUNT(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN response_ms END), 0), + COUNT(CASE WHEN timestamp >= ?2 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?2 THEN blocked END), 0), + COUNT(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN response_ms END), 0), + COUNT(*), COALESCE(SUM(blocked), 0), COUNT(CASE WHEN blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN blocked = 0 THEN response_ms END), 0) + FROM query_logs WHERE timestamp >= ?3", + rusqlite::params![s1 * 1000, s7 * 1000, s30 * 1000], + |row| { + (0..3) + .map(|w| { + Ok(( + row.get(w * 5)?, + row.get(w * 5 + 1)?, + row.get(w * 5 + 2)?, + row.get(w * 5 + 3)?, + row.get(w * 5 + 4)?, + )) + }) + .collect() + }, + ) + .unwrap(); + let got: Vec<(i64, i64, i64, i64, f64)> = summary + .iter() + .map(|w| { + ( + w.total, + w.blocked, + w.allowed, + w.cache_hits, + w.avg_response_ms, + ) + }) + .collect(); + assert_eq!(got, expected, "summary from {since}"); + + for bucket_secs in [60, 600, 1_800, 3_600] { + let got: Vec<(i64, i64, i64)> = db + .timeline_since(since, bucket_secs) + .await + .unwrap() + .into_iter() + .map(|p| (p.timestamp, p.total, p.blocked)) + .collect(); + let expected: Vec<(i64, i64, i64)> = raw + .prepare( + "SELECT (timestamp / ?1) * ?1 / 1000, COUNT(*), COALESCE(SUM(blocked), 0) \ + FROM query_logs WHERE timestamp >= ?2 GROUP BY 1 ORDER BY 1", + ) + .unwrap() + .query_map(rusqlite::params![bucket_secs * 1000, since * 1000], |r| { + Ok((r.get(0)?, r.get(1)?, r.get(2)?)) + }) + .unwrap() + .collect::>() + .unwrap(); + assert_eq!(got, expected, "timeline from {since} by {bucket_secs}s"); + } + + for limit in [5, 1_000] { + let expected_domains: Vec<(String, i64)> = raw + .prepare( + "SELECT domain, COUNT(*) FROM query_logs WHERE timestamp >= ?1 \ + GROUP BY domain ORDER BY 2 DESC, domain LIMIT ?2", + ) + .unwrap() + .query_map(rusqlite::params![since * 1000, limit], |r| { + Ok((r.get(0)?, r.get(1)?)) + }) + .unwrap() + .collect::>() + .unwrap(); + let expected_unique: i64 = raw + .query_row( + "SELECT COUNT(DISTINCT domain) FROM query_logs WHERE timestamp >= ?1", + [since * 1000], + |r| r.get(0), + ) + .unwrap(); + let expected_clients: Vec<(String, Option, i64)> = raw + .prepare( + "SELECT client_ip, doh_token, COUNT(*) FROM query_logs WHERE timestamp >= ?1 \ + GROUP BY client_ip, doh_token ORDER BY 3 DESC, client_ip, doh_token LIMIT ?2", + ) + .unwrap() + .query_map(rusqlite::params![since * 1000, limit], |r| { + Ok((r.get(0)?, r.get(1)?, r.get(2)?)) + }) + .unwrap() + .collect::>() + .unwrap(); + let expected_upstreams: Vec<(String, i64, f64)> = raw + .prepare( + "SELECT upstream, COUNT(*), AVG(response_ms) FROM query_logs \ + WHERE timestamp >= ?1 AND upstream IS NOT NULL \ + GROUP BY upstream ORDER BY 2 DESC, upstream LIMIT ?2", + ) + .unwrap() + .query_map(rusqlite::params![since * 1000, limit], |r| { + Ok((r.get(0)?, r.get(1)?, r.get(2)?)) + }) + .unwrap() + .collect::>() + .unwrap(); + + let lists = db.traffic_lists_since(since, limit).await.unwrap(); + let domains = db.domain_stats_since(since, limit).await.unwrap(); + let upstreams = db.top_upstreams_since(since, limit).await.unwrap(); + let pairs = |top: &[noadd::db::TopDomain]| -> Vec<(String, i64)> { + top.iter().map(|d| (d.domain.clone(), d.count)).collect() + }; + + let tag = format!("from {since}, limit {limit}"); + assert_eq!( + pairs(&lists.domains.top), + expected_domains, + "traffic lists' domains {tag}" + ); + assert_eq!( + lists.domains.unique, expected_unique, + "traffic lists' unique {tag}" + ); + assert_eq!(pairs(&domains.top), expected_domains, "domain stats {tag}"); + // The count rides on the rows, so an empty window reports 0. + let unique = if expected_domains.is_empty() { + 0 + } else { + expected_unique + }; + assert_eq!(domains.unique, unique, "domain stats' unique {tag}"); + assert_eq!( + lists + .clients + .iter() + .map(|c| (c.client_ip.clone(), c.doh_token.clone(), c.count)) + .collect::>(), + expected_clients, + "traffic lists' clients {tag}" + ); + assert_eq!( + upstreams + .iter() + .map(|u| (u.upstream.clone(), u.count, u.avg_ms)) + .collect::>(), + expected_upstreams, + "top upstreams {tag}" + ); + } + } +} diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index 3b768ff..b66734a 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -200,73 +200,81 @@ async fn the_page_and_its_charts_are_one_metrics_scan() { ); } -/// The dashboard's summary asks every tick for totals, blocks, cache hits and -/// mean latency over three windows. Every one of those is a column of -/// `idx_query_logs_ts_metrics`, so together they cost one scan of it — not the -/// two that asking the blocked counts and the cache figures separately paid. -#[tokio::test] -async fn the_dashboard_summary_is_one_metrics_scan() { - let db = seeded_db().await; - let now = ROWS; // seconds; the seed runs from 0 to ROWS - - let summary = page_misses(&db, || stats::compute_summary(&db, now)).await; - let one_scan = page_misses(&db, || db.window_metrics_since(0)).await; - - assert!( - one_scan > 0, - "no pages were read at all — the measurement is not working" - ); - assert!( - summary <= one_scan + one_scan / 10, - "the summary read {summary} pages where one scan of the metrics index \ - reads {one_scan} — has it gone back to a statement per figure?" - ); -} - -/// The top upstreams read `upstream` and `response_ms`, which no index carried, -/// so every forwarded query in the window was a rowid lookup into the table — -/// on every dashboard tick. A partial index over the forwarded rows answers it -/// alone. -#[tokio::test] -async fn the_top_upstreams_never_read_the_log_table() { - let db = seeded_db().await; - let storage = db.db_storage_stats().await.unwrap(); - let db_pages = storage.main_bytes / 4096; - - let misses = page_misses(&db, || db.top_upstreams_since(0, 10)).await; +/// Twenty thousand queries inside one hour, from fifty domains and twenty +/// clients: the rollups hold a few hundred rows for what the table holds in +/// twenty thousand, which is the shape a busy resolver's hour takes. +async fn dense_db() -> Database { + let dir = tempdir().unwrap(); + let path = dir.keep().join("dense.db"); + let db = Database::open(path.to_str().unwrap()).await.unwrap(); - assert!( - misses > 0, - "no pages were read at all — the measurement is not working" - ); - assert!( - misses * 4 < db_pages, - "top upstreams read {misses} of the database's {db_pages} pages; that \ - is the table, not an index — is idx_query_logs_ts_upstream missing?" - ); + let entries: Vec = (0..ROWS) + .map(|i| QueryLogEntry { + timestamp: i * 150, + domain: format!("host{}.example.com", i % 50), + query_type: if i % 3 == 0 { "AAAA" } else { "A" }.to_string(), + client_ip: format!("10.0.0.{}", i % 20), + blocked: i % 7 == 0, + cached: i % 5 == 0, + upstream: (i % 2 == 0).then(|| format!("tls://1.1.1.{}:853", i % 4)), + doh_token: None, + result: Some("x".repeat(RESULT_PADDING)), + response_ms: i % 50, + authenticated_data: false, + }) + .collect(); + for chunk in entries.chunks(2_000) { + db.insert_query_logs(chunk).await.unwrap(); + } + db } -/// The domain and client lists read an index that starts with `timestamp`, so a -/// short window — the dashboard's 24 hours against a week of retention — reads -/// a short stretch of it. The group-first indexes they replaced could not be -/// restricted by the window at all, and read most of themselves whatever it was. +/// Every reading a dashboard tick makes folds the rollups, and reads the table +/// only for the part of a unit its window starts inside — none here, because +/// every window below starts on a unit boundary. Before the rollups each of +/// these was a scan of an index as long as the window, and the window is the +/// whole table under the default retention, every ten seconds. #[tokio::test] -async fn a_short_window_reads_a_short_stretch_of_the_traffic_lists() { - let db = seeded_db().await; - - let whole = page_misses(&db, || db.traffic_lists_since(0, 15)).await; - // The last tenth of the seed. - let tail = page_misses(&db, || db.traffic_lists_since(ROWS - ROWS / 10, 15)).await; +async fn the_dashboard_readings_fold_rollups_rather_than_the_table() { + let db = dense_db().await; + + // For scale: counting with a search that matches every domain walks an + // index over every row, which is what each reading used to cost. + let scan = page_misses(&db, || db.count_logs(Some("*"), None, None, None)).await; + let readings = [ + ( + "summary", + page_misses(&db, || db.summary_multi_since(0, 0, 0)).await, + ), + ( + "timeline", + page_misses(&db, || db.timeline_since(0, 1_800)).await, + ), + ( + "traffic lists", + page_misses(&db, || db.traffic_lists_since(0, 10)).await, + ), + ( + "domain stats", + page_misses(&db, || db.domain_stats_since(0, 20)).await, + ), + ( + "top upstreams", + page_misses(&db, || db.top_upstreams_since(0, 10)).await, + ), + ]; assert!( - tail > 0, - "no pages were read at all — the measurement is not working" - ); - assert!( - tail * 4 < whole, - "a tenth of the window read {tail} pages against {whole} for all of it — \ - is the index still timestamp-first, and still named by INDEXED BY?" + scan > 0, + "the scan read no pages at all — the measurement is not working" ); + for (label, read) in readings { + assert!( + read * 10 < scan, + "{label} read {read} pages where a scan over every row reads {scan} — \ + is it back on the table instead of the rollups?" + ); + } } /// The heatmap reads `timestamp` and nothing else, so it belongs on the