From efee13b869bf5f0f1bd786e5ecabc47b8d43d146 Mon Sep 17 00:00:00 2001 From: Heng-Yi Wu <2316687+henry40408@users.noreply.github.com> Date: Mon, 14 Sep 2026 15:38:07 +0800 Subject: [PATCH] perf(stats): fold the Statistics page's readings out of the statistics rollups stats_scan_since reads query_stats_quarter and query_stats_metrics_hour, plus the table rows each window starts inside, in one four-arm statement. The API-only readers follow: window_metrics_since folds the metrics rollup, and timeline_multi_since and hourly_heatmap_since fold the quarter rollup whenever the bucket and offset are whole quarters. The API rounds tz_offset to the nearest quarter hour so it always is. No reader names idx_query_logs_ts_metrics any more. Page misses on a 1.48 M-row database (main -> this): Statistics 30d visit 11 641 -> 3 644 Statistics 7d visit 10 060 -> 1 015 API timeline 30d 9 476 -> 45 API heatmap 6 030 -> 38 Dashboard and query log readings unchanged. Co-Authored-By: Claude Opus 5 (1M context) --- ARCHITECTURE.md | 6 +- CLAUDE.md | 4 +- src/admin/api.rs | 10 +- src/db.rs | 282 ++++++++++++++++++++++------------ tests/stats_api_test.rs | 78 +++++++++- tests/stats_db_test.rs | 195 +++++++++++++++++++++++ tests/stats_page_miss_test.rs | 92 +++++------ 7 files changed, 507 insertions(+), 160 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index b178a8f..ffd9453 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -277,6 +277,8 @@ A reader takes every unit from the first whole one inside its window (`first_who 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. +The Statistics page followed. `stats_scan_since` is one statement of four arms — `query_stats_quarter` from the earlier window's first whole quarter, `query_stats_metrics_hour` from the range's first whole hour, and the table rows each window starts inside — told apart by a leading column, so a table row both windows start inside is counted once per window. The API-only readers fold the same tables: `window_metrics_since` the metrics rollup, and `timeline_multi_since` and `hourly_heatmap_since` the quarter rollup whenever the bucket and the offset are whole quarters. The API rounds `tz_offset` to the nearest quarter hour for that reason; an offset no zone uses would otherwise count every row in the window, and after the metrics index goes that means the table. On the 1.48 M-row database a 30-day visit went from 11 641 page misses to 3 644 and a 7-day visit from 10 060 to 1 015; the API's timeline from 9 476 to 45 and its heatmap from 6 030 to 38. `statistics_readings_equal_a_recount_of_the_table` is the guard, over the same window starts, heatmap windows before, equal to and after the range's, and offsets including India, Nepal and a seven-minute one that takes the table path. + ### 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/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. @@ -291,13 +293,13 @@ The Statistics page's five readings were four foldings of the metrics index over The window's grain has no time bucket in it. Bucketing the shared grain was what the first version did, and it cost a scan: the outcome breakdown sums across every bucket, so the bucket only multiplied the rows the folds read, 68 846 of them against 4 658 at the 7-day range's hourly grain, while the query-type and latency folds still needed a second statement of their own. Collapsing the two into one grain fine enough for all three is 2 157 pages against 4 314. -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 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 scan and both endpoints have since moved onto the rollups (see *Rollups*). 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. 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; 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. +`INDEXED BY` appears on every statement that reads this index, in both directions. The ones that needed `blocked`, `cached` or `has_result` named `idx_query_logs_ts_metrics` because the planner otherwise takes the smaller `idx_query_logs_timestamp` and pays a rowid lookup per row — none is left, every such reading having moved onto the rollups; 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 92eea50..c13488b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -128,12 +128,12 @@ Dashboard adds the conventions for a page that is **all readings and no controls Statistics adds the conventions for a page whose readings sit in a **chosen window**, and the rule for **what the server cannot render**: - **Let the data draw the line, not the page.** Only the three charts need a calendar, and a calendar-aligned bucket needs the viewer's UTC offset, which arrives with the browser and not with the request. Everything else is a plain `now - range` window with no calendar in it, so it renders on the server and never moves again: the highlights, both breakdowns, both ranged lists and the health grid are all in the first response. -- **The charts' data is in the first response too, just not in the viewer's calendar.** `` is a `QuarterSeries` (`src/db.rs`) — query counts per quarter hour on UTC boundaries, out of the same scan as the breakdowns — and `timelineFromQuarters` / `heatmapFromQuarters` in `app.js` fold it into the browser's hours and days. That is exact, not approximate: every offset in use is a whole number of quarter hours, so no quarter straddles a local hour. The page makes no request for its charts. `/api/stats/v2/timeline` and `…/heatmap` still take `tz_offset` for API callers, and `e2e/tests/specs/stats_charts.rs` holds the JavaScript folds to them across ranges and offsets — change one and that is what fails. +- **The charts' data is in the first response too, just not in the viewer's calendar.** `` is a `QuarterSeries` (`src/db.rs`) — query counts per quarter hour on UTC boundaries, out of the same scan as the breakdowns — and `timelineFromQuarters` / `heatmapFromQuarters` in `app.js` fold it into the browser's hours and days. That is exact, not approximate: every offset in use is a whole number of quarter hours, so no quarter straddles a local hour. The page makes no request for its charts. `/api/stats/v2/timeline` and `…/heatmap` still take `tz_offset` for API callers — rounded to the nearest quarter hour, the grain of `query_stats_quarter` they fold, which no zone in use notices — and `e2e/tests/specs/stats_charts.rs` holds the JavaScript folds to them across ranges and offsets — change one and that is what fails. - **`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; `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 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. +- **One statement per rollup family, not one per reading.** `stats_scan_since` and `traffic_lists_since` (`src/db.rs`) are the page's two reads — the first folding the quarter and metrics rollups, 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, telling its four arms (two rollups, then the table rows each window starts inside) apart by a leading column. The single-purpose functions `/api/stats/*` uses are statements of their own over the same rollups — adding a seventh reading to the page means folding it out of one of those two statements, not adding one. - **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/admin/api.rs b/src/admin/api.rs index 7abfe44..2b5472c 100644 --- a/src/admin/api.rs +++ b/src/admin/api.rs @@ -3683,7 +3683,8 @@ async fn get_stats_top_upstreams( pub struct TimelineV2Query { pub range: Option, /// Viewer's east-positive UTC offset in minutes (e.g. 480 for UTC+8), used - /// to align buckets to their local calendar. Clamped to ±14h; missing ⇒ 0 + /// to align buckets to their local calendar. Clamped to ±14h and rounded to + /// the nearest 15 minutes, which every zone in use already is; missing ⇒ 0 /// (UTC-aligned). pub tz_offset: Option, } @@ -3712,8 +3713,13 @@ fn parse_stats_range(raw: Option<&str>) -> Result /// Resolve the viewer's UTC offset to seconds, clamped to the real-world range /// (±14h) so a malformed value can't shift buckets to nonsense. +/// +/// Rounded to a quarter hour because that is the grain of +/// `query_stats_quarter`: a quarter-aligned offset is answered from the rollup, +/// any other would count every row in the window. No zone in use is affected. fn resolve_tz_offset_secs(tz_offset: Option) -> i64 { - tz_offset.unwrap_or(0).clamp(-14 * 60, 14 * 60) * 60 + let minutes = tz_offset.unwrap_or(0).clamp(-14 * 60, 14 * 60); + (minutes + 7).div_euclid(15) * 15 * 60 } async fn get_stats_v2_timeline( diff --git a/src/db.rs b/src/db.rs index ff460f4..6b5edd9 100644 --- a/src/db.rs +++ b/src/db.rs @@ -2579,23 +2579,27 @@ impl Database { }) } - /// The Statistics page's window readings and its charts' series, in one - /// scan of `idx_query_logs_ts_metrics`. + /// The Statistics page's window readings and its charts' series, folded out + /// of `query_stats_quarter` and `query_stats_metrics_hour`. /// - /// The page used to pay for that index three times: once here for the - /// breakdowns and the latency histogram, once more for the timeline the - /// browser fetched with its UTC offset, and `idx_query_logs_timestamp` for - /// the heatmap on top — 5 690 pages on a 370 k-row database where 2 152 - /// answer all of it. The charts come out of the same rows as a - /// [`QuarterSeries`], which the browser folds into its own calendar. + /// Whole units come from the rollups and the part of a unit each window + /// starts inside from the table — see `STATS_ROLLUP_SCHEMA`. From the table + /// alone this was a scan of `idx_query_logs_ts_metrics` from the earlier of + /// the two windows: 9 476 pages for the 30-day range on a 1.48 M-row + /// database, because under the default retention that is the whole table. + /// The charts come out of the same statement as a [`QuarterSeries`], which + /// the browser folds into its own calendar. /// - /// The scan starts at the earlier of the two windows; `range_since` bounds - /// the metrics and the timeline, `heatmap_since` the heatmap, each exactly. + /// `range_since` bounds the metrics and the timeline, `heatmap_since` the + /// heatmap, each exactly. The first column says which arm a row came from: + /// the two rollups, then the table rows the range starts inside (the rest of + /// its first hour, which also holds the rest of its first quarter), then + /// those the heatmap starts inside. When both windows start at the same + /// instant a table row arrives once per arm, and each arm counts it only for + /// its own window. /// - /// Rows are folded here rather than grouped in SQL. A `GROUP BY` at a grain - /// carrying both the quarter and `response_ms` approaches one group per - /// row, which is a temp b-tree the size of the window held in memory on the - /// appliance; the folds below hold one entry per distinct value instead. + /// Rows are folded here rather than grouped in SQL, so the metrics grain is + /// held once per distinct value rather than sorted into a temp b-tree. pub async fn stats_scan_since( &self, range_since: i64, // unix seconds @@ -2603,15 +2607,26 @@ impl Database { ) -> Result { let range_ms = range_since * 1000; let heatmap_ms = heatmap_since * 1000; - let quarter_ms = QUARTER_SECS * 1000; + let range_quarter = first_whole_unit(range_ms, ROLLUP_QUARTER_MS); + let heatmap_quarter = first_whole_unit(heatmap_ms, ROLLUP_QUARTER_MS); + let range_hour = first_whole_unit(range_ms, ROLLUP_HOUR_MS); let scan = self .reader() .call(move |conn| { - // `INDEXED BY` for the reason `metrics_window_since` gives. let mut stmt = conn.prepare_cached( - "SELECT timestamp, blocked, cached, has_result, query_type, response_ms \ - FROM query_logs INDEXED BY idx_query_logs_ts_metrics \ - WHERE timestamp >= ?1", + "SELECT 0, quarter, blocked, cached, NULL, NULL, NULL, count + FROM query_stats_quarter WHERE quarter >= ?3 + UNION ALL + SELECT 1, hour, blocked, cached, has_result, query_type, response_ms, count + FROM query_stats_metrics_hour WHERE hour >= ?4 + UNION ALL + SELECT 2, timestamp, blocked, cached, has_result, query_type, response_ms, 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?4 * 3600000 + UNION ALL + SELECT 3, timestamp, blocked, cached, NULL, NULL, NULL, 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?2 AND timestamp < ?5 * 900000", )?; // Keyed by query type first so a row that repeats a type — nearly // all of them — is looked up by `&str` without allocating. @@ -2620,29 +2635,60 @@ impl Database { let mut grains: HashMap = HashMap::new(); // quarter index → [total, blocked, cached, heatmap] let mut quarters: BTreeMap = BTreeMap::new(); - let mut rows = stmt.query(params![range_ms.min(heatmap_ms)])?; + let args = params![ + range_ms, + heatmap_ms, + range_quarter.min(heatmap_quarter), + range_hour, + heatmap_quarter + ]; + let mut rows = stmt.query(args)?; while let Some(row) = rows.next()? { - let ts: i64 = row.get(0)?; - let blocked = row.get::<_, i64>(1)? != 0; - let cached = row.get::<_, i64>(2)? != 0; - let slot = quarters.entry(ts.div_euclid(quarter_ms)).or_default(); - if ts >= heatmap_ms { - slot[3] += 1; - } - if ts < range_ms { - continue; + let arm: i64 = row.get(0)?; + let at: i64 = row.get(1)?; + let blocked = row.get::<_, i64>(2)? != 0; + let cached = row.get::<_, i64>(3)? != 0; + let count: i64 = row.get(7)?; + match arm { + 0 => { + let slot = quarters.entry(at).or_default(); + if at >= heatmap_quarter { + slot[3] += count; + } + if at >= range_quarter { + slot[0] += count; + slot[1] += count * i64::from(blocked); + slot[2] += count * i64::from(cached); + } + continue; + } + 3 => { + quarters + .entry(at.div_euclid(ROLLUP_QUARTER_MS)) + .or_default()[3] += 1; + continue; + } + // The range's table rows run to the end of its first + // hour, and only the first quarter of that is not in + // `query_stats_quarter`'s arm. + 2 if at < range_quarter * ROLLUP_QUARTER_MS => { + let slot = quarters + .entry(at.div_euclid(ROLLUP_QUARTER_MS)) + .or_default(); + slot[0] += 1; + slot[1] += i64::from(blocked); + slot[2] += i64::from(cached); + } + _ => {} } - slot[0] += 1; - slot[1] += i64::from(blocked); - slot[2] += i64::from(cached); - let has_result = row.get::<_, i64>(3)? != 0; - let query_type = row.get_ref(4)?.as_str()?; - let key = (blocked, cached, has_result, row.get::<_, i64>(5)?); + let has_result = row.get::<_, i64>(4)? != 0; + let query_type = row.get_ref(5)?.as_str()?; + let key = (blocked, cached, has_result, row.get::<_, i64>(6)?); if let Some(by_grain) = grains.get_mut(query_type) { - *by_grain.entry(key).or_default() += 1; + *by_grain.entry(key).or_default() += count; } else { - grains.insert(query_type.to_owned(), HashMap::from([(key, 1)])); + grains.insert(query_type.to_owned(), HashMap::from([(key, count)])); } } @@ -2676,14 +2722,14 @@ impl Database { Ok(scan) } - /// Query counts by time bucket. Every column is carried by - /// `idx_query_logs_ts_metrics`, so the scan never looks a row up. + /// Query counts by time bucket, folded out of `query_stats_quarter`. /// - /// `INDEXED BY` because the planner will not choose it on its own: with - /// `idx_query_logs_timestamp` also matching the range it picks that one — - /// it is the smaller index — and then pays a rowid lookup per row to reach - /// `blocked` and `cached`. Measured on a 370 k-row database that is 12 173 - /// page misses against 2 157 for the identical answer. + /// A bucket and an offset that are both whole numbers of quarters put every + /// quarter wholly inside one bucket, so the quarter's rows can be counted + /// together; the table supplies the quarter the window starts inside — see + /// `STATS_ROLLUP_SCHEMA`. The API rounds `tz_offset` to a quarter hour for + /// this reason. Anything finer — a bucket under a quarter, which no range + /// asks for — counts the table directly. async fn metrics_by_bucket_since( &self, since: i64, // unix seconds @@ -2693,27 +2739,45 @@ impl Database { let since_ms = since * 1000; let bucket_ms = bucket_secs * 1000; let offset_ms = tz_offset_secs * 1000; + let quarter = first_whole_unit(since_ms, ROLLUP_QUARTER_MS); let result = self .reader() .call(move |conn| { - let mut stmt = conn.prepare_cached( - "SELECT ((timestamp + ?3) / ?1) * ?1 - ?3 AS bucket, \ - blocked, cached, COUNT(*) \ - FROM query_logs INDEXED BY idx_query_logs_ts_metrics \ - WHERE timestamp >= ?2 \ - GROUP BY bucket, blocked, cached \ - ORDER BY bucket", - )?; - let rows = stmt - .query_map(params![bucket_ms, since_ms, offset_ms], |row| { - Ok(MetricsBucket { - timestamp: row.get::<_, i64>(0)? / 1000, // return seconds - blocked: row.get::<_, i64>(1)? != 0, - cached: row.get::<_, i64>(2)? != 0, - count: row.get(3)?, - }) - })? - .collect::, _>>()?; + let bucket = |row: &rusqlite::Row<'_>| { + Ok(MetricsBucket { + timestamp: row.get::<_, i64>(0)? / 1000, // return seconds + blocked: row.get::<_, i64>(1)? != 0, + cached: row.get::<_, i64>(2)? != 0, + count: row.get(3)?, + }) + }; + let rows = + if bucket_ms % ROLLUP_QUARTER_MS == 0 && offset_ms % ROLLUP_QUARTER_MS == 0 { + conn.prepare_cached( + "SELECT bucket, blocked, cached, SUM(n) FROM ( + SELECT ((quarter * 900000 + ?3) / ?1) * ?1 - ?3 AS bucket, + blocked, cached, count AS n + FROM query_stats_quarter WHERE quarter >= ?4 + UNION ALL + SELECT ((timestamp + ?3) / ?1) * ?1 - ?3, blocked, cached, 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?2 AND timestamp < ?4 * 900000 + ) GROUP BY bucket, blocked, cached ORDER BY bucket", + )? + .query_map(params![bucket_ms, since_ms, offset_ms, quarter], bucket)? + .collect::, _>>()? + } else { + conn.prepare_cached( + "SELECT ((timestamp + ?3) / ?1) * ?1 - ?3 AS bucket, \ + blocked, cached, COUNT(*) \ + FROM query_logs \ + WHERE timestamp >= ?2 \ + GROUP BY bucket, blocked, cached \ + ORDER BY bucket", + )? + .query_map(params![bucket_ms, since_ms, offset_ms], bucket)? + .collect::, _>>()? + }; Ok(rows) }) .await?; @@ -2722,28 +2786,30 @@ impl Database { /// Query counts by outcome class, type and response time — the grain the /// outcome breakdown, the query-type breakdown and the latency histogram - /// all fold out of. Every column sits in `idx_query_logs_ts_metrics`. - /// - /// `INDEXED BY` for the same reason [`Self::metrics_by_bucket_since`] needs - /// it: `idx_query_logs_timestamp` also matches the range and is the smaller - /// index, so the planner picks that one and then pays a rowid lookup per - /// row to reach `has_result`. + /// all fold out of — from `query_stats_metrics_hour`, and from the table + /// for the part of an hour the window starts inside (see + /// `STATS_ROLLUP_SCHEMA`). async fn metrics_window_since( &self, since: i64, // unix seconds ) -> Result, DbError> { let since_ms = since * 1000; + let hour = first_whole_unit(since_ms, ROLLUP_HOUR_MS); let rows = self .reader() .call(move |conn| { let mut stmt = conn.prepare_cached( - "SELECT blocked, cached, has_result, query_type, response_ms, COUNT(*) \ - FROM query_logs INDEXED BY idx_query_logs_ts_metrics \ - WHERE timestamp >= ?1 \ - GROUP BY blocked, cached, has_result, query_type, response_ms", + "SELECT blocked, cached, has_result, query_type, response_ms, SUM(n) FROM ( + SELECT blocked, cached, has_result, query_type, response_ms, count AS n + FROM query_stats_metrics_hour WHERE hour >= ?2 + UNION ALL + SELECT blocked, cached, has_result, query_type, response_ms, 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?2 * 3600000 + ) GROUP BY blocked, cached, has_result, query_type, response_ms", )?; let rows = stmt - .query_map(params![since_ms], |row| { + .query_map(params![since_ms, hour], |row| { Ok(WindowMetricsRow { blocked: row.get::<_, i64>(0)? != 0, cached: row.get::<_, i64>(1)? != 0, @@ -2766,12 +2832,19 @@ impl Database { /// [`Self::timeline_multi_since`] applies, and carries the same DST caveat: /// a single offset can misplace rows recorded under the other DST phase. /// Pass 0 for plain UTC buckets. + /// + /// An offset that is a whole number of quarters — every zone in use, and + /// every offset the API passes — puts each quarter wholly inside one local + /// hour, so this folds `query_stats_quarter` and reads the table only for + /// the quarter the window starts inside (see `STATS_ROLLUP_SCHEMA`). Any + /// other offset counts the table directly. pub async fn hourly_heatmap_since( &self, since: i64, // unix seconds tz_offset_secs: i64, ) -> Result, DbError> { let since_ms = since * 1000; + let quarter = first_whole_unit(since_ms, ROLLUP_QUARTER_MS); let result = self .reader() .call(move |conn| { @@ -2781,37 +2854,48 @@ impl Database { // most expensive thing the Statistics page did (155 ms, versus // 61 ms for this form on a 447 k-row database). // - // `INDEXED BY` because this reads nothing but `timestamp`, - // and `idx_query_logs_timestamp` is the smallest index that - // covers it. Left to itself the planner took - // `idx_query_logs_ts_metrics` — also covering, also correct, - // and 2 153 pages against 1 386 on a 370 k-row database purely - // because it carries four columns this query never reads. - // // The `+ 4` is because Unix day 0 (1970-01-01) was a Thursday // and `strftime('%w')` counts from Sunday = 0. Truncating // division is only equal to flooring for non-negative inputs, - // which is what `timestamp / 1000 + ?2` always is here: + // which is what the shifted seconds always are here: // timestamps come from the system clock and the offset is at // most ±14 h. - let mut stmt = conn.prepare_cached( - "SELECT ((timestamp / 1000 + ?2) / 86400 + 4) % 7 AS wday, \ - (timestamp / 1000 + ?2) % 86400 / 3600 AS hr, \ - COUNT(*) \ - FROM query_logs INDEXED BY idx_query_logs_timestamp \ - WHERE timestamp >= ?1 \ - GROUP BY wday, hr \ - ORDER BY wday, hr", - )?; - let rows = stmt - .query_map(params![since_ms, tz_offset_secs], |row| { - Ok(HeatmapCell { - weekday: row.get(0)?, - hour: row.get(1)?, - count: row.get(2)?, - }) - })? - .collect::, _>>()?; + let cell = |row: &rusqlite::Row<'_>| { + Ok(HeatmapCell { + weekday: row.get(0)?, + hour: row.get(1)?, + count: row.get(2)?, + }) + }; + let rows = if tz_offset_secs % QUARTER_SECS == 0 { + conn.prepare_cached( + "SELECT (s / 86400 + 4) % 7 AS wday, s % 86400 / 3600 AS hr, SUM(n) FROM ( + SELECT quarter * 900 + ?2 AS s, count AS n + FROM query_stats_quarter WHERE quarter >= ?3 + UNION ALL + SELECT timestamp / 1000 + ?2, 1 + FROM query_logs INDEXED BY idx_query_logs_timestamp + WHERE timestamp >= ?1 AND timestamp < ?3 * 900000 + ) GROUP BY wday, hr ORDER BY wday, hr", + )? + .query_map(params![since_ms, tz_offset_secs, quarter], cell)? + .collect::, _>>()? + } else { + // `INDEXED BY` because this reads nothing but `timestamp`, + // and left to itself the planner takes a wider index that + // also covers it. + conn.prepare_cached( + "SELECT ((timestamp / 1000 + ?2) / 86400 + 4) % 7 AS wday, \ + (timestamp / 1000 + ?2) % 86400 / 3600 AS hr, \ + COUNT(*) \ + FROM query_logs INDEXED BY idx_query_logs_timestamp \ + WHERE timestamp >= ?1 \ + GROUP BY wday, hr \ + ORDER BY wday, hr", + )? + .query_map(params![since_ms, tz_offset_secs], cell)? + .collect::, _>>()? + }; Ok(rows) }) .await?; diff --git a/tests/stats_api_test.rs b/tests/stats_api_test.rs index c36359e..2efa6e0 100644 --- a/tests/stats_api_test.rs +++ b/tests/stats_api_test.rs @@ -18,6 +18,11 @@ use noadd::upstream::forwarder::{UpstreamConfig, UpstreamForwarder}; use tokio::sync::mpsc; async fn setup() -> (axum::Router, String) { + let (router, token, _db) = setup_with_db().await; + (router, token) +} + +async fn setup_with_db() -> (axum::Router, String, Database) { let dir = tempfile::tempdir().unwrap(); // Persist the tempdir (no Drop cleanup) so the DB file lives for the test. let path = dir.keep().join("test.db"); @@ -76,7 +81,7 @@ async fn setup() -> (axum::Router, String) { ); let router = admin_router(AppState { - db, + db: db.clone(), sessions, filter, cache, @@ -102,7 +107,7 @@ async fn setup() -> (axum::Router, String) { trusted_proxies: std::sync::Arc::new(noadd::net::TrustedProxies::default()), forward_auth: None, }); - (router, token) + (router, token, db) } #[tokio::test] @@ -269,3 +274,72 @@ async fn stats_v2_timeline_accepts_both_parameters() { StatusCode::OK ); } + +/// The offset is rounded to the nearest quarter hour, the grain the charts' +/// rollup is kept at. A query at ten to the hour shows it: fifteen minutes +/// either way moves it across the hour, so an offset that is not rounded lands +/// it in a different cell from the quarter it rounds to. +#[tokio::test] +async fn stats_v2_tz_offset_is_rounded_to_a_quarter_hour() { + let (app, token, db) = setup_with_db().await; + let ten_to = (noadd::now_unix() / 3600 - 2) * 3600 + 3000; + db.insert_query_logs(&[noadd::db::QueryLogEntry { + timestamp: ten_to * 1000, + domain: "example.com".into(), + query_type: "A".into(), + client_ip: "10.0.0.1".into(), + blocked: false, + cached: false, + response_ms: 3, + upstream: None, + doh_token: None, + result: None, + authenticated_data: false, + }]) + .await + .unwrap(); + + let body = |offset: i64| { + let app = app.clone(); + let token = token.clone(); + async move { + let resp = app + .oneshot( + Request::builder() + .uri(format!("/api/stats/v2/heatmap?tz_offset={offset}")) + .header("cookie", format!("session={token}")) + .body(Body::empty()) + .unwrap(), + ) + .await + .unwrap(); + assert_eq!(resp.status(), StatusCode::OK); + let bytes = axum::body::to_bytes(resp.into_body(), usize::MAX) + .await + .unwrap(); + serde_json::from_slice::(&bytes).unwrap() + } + }; + + assert_ne!( + body(480).await, + body(495).await, + "the query must straddle the hour" + ); + assert_eq!( + body(487).await, + body(480).await, + "487 min rounds down to 480" + ); + assert_eq!(body(488).await, body(495).await, "488 min rounds up to 495"); + assert_eq!( + body(-487).await, + body(-480).await, + "-487 min rounds to -480" + ); + assert_eq!( + body(-488).await, + body(-495).await, + "-488 min rounds to -495" + ); +} diff --git a/tests/stats_db_test.rs b/tests/stats_db_test.rs index dc068e3..2d22558 100644 --- a/tests/stats_db_test.rs +++ b/tests/stats_db_test.rs @@ -1054,3 +1054,198 @@ async fn dashboard_readings_equal_a_recount_of_the_table() { } } } + +/// The Statistics page's scan and the API's timeline, heatmap and window +/// readings fold rollups and the table only where a window starts inside a +/// unit, so each is checked against a count of the table itself, for every +/// window start and for heatmap windows before, equal to and after the range's. +/// The offsets include half- and three-quarter-hour zones, and one — seven +/// minutes — that no zone uses, which the readers answer from the table. +#[tokio::test] +async fn statistics_readings_equal_a_recount_of_the_table() { + let (db, path) = recount_db().await; + let raw = rusqlite::Connection::open(&path).unwrap(); + let pairs = |sql: &str, since_ms: i64| -> Vec<(String, i64)> { + let mut rows: Vec<(String, i64)> = raw + .prepare(sql) + .unwrap() + .query_map([since_ms], |r| Ok((r.get(0)?, r.get(1)?))) + .unwrap() + .collect::>() + .unwrap(); + rows.sort(); + rows + }; + let per_quarter = |since_ms: i64| -> std::collections::BTreeMap { + raw.prepare( + "SELECT timestamp / 900000, COUNT(*), SUM(blocked), SUM(cached) \ + FROM query_logs WHERE timestamp >= ?1 GROUP BY 1", + ) + .unwrap() + .query_map([since_ms], |r| { + Ok((r.get(0)?, [r.get(1)?, r.get(2)?, r.get(3)?])) + }) + .unwrap() + .collect::>() + .unwrap() + }; + + for since in recount_sinces() { + let since_ms = since * 1000; + let outcomes = pairs( + "SELECT CASE WHEN blocked = 1 THEN 'Blocked' WHEN cached = 1 THEN 'Cached' \ + WHEN result IS NOT NULL AND result != '' THEN 'Resolved' \ + ELSE 'Empty' END, COUNT(*) \ + FROM query_logs WHERE timestamp >= ?1 GROUP BY 1", + since_ms, + ); + let query_types = pairs( + "SELECT query_type, COUNT(*) FROM query_logs WHERE timestamp >= ?1 GROUP BY 1", + since_ms, + ); + let latencies: Vec = raw + .prepare("SELECT response_ms FROM query_logs WHERE timestamp >= ?1 ORDER BY 1") + .unwrap() + .query_map([since_ms], |r| r.get(0)) + .unwrap() + .collect::>() + .unwrap(); + let percentile = |p: f64| { + let rank = usize::try_from(((latencies.len() as f64 * p) as i64).max(1)).unwrap(); + latencies.get(rank - 1).copied().unwrap_or(0) + }; + let expected_latency = ( + i64::try_from(latencies.len()).unwrap(), + percentile(0.50), + percentile(0.95), + percentile(0.99), + ); + let latency = + |l: &noadd::db::LatencySummary| (l.sample_count, l.p50_ms, l.p95_ms, l.p99_ms); + + let window = db.window_metrics_since(since).await.unwrap(); + assert_eq!( + sorted(window.outcomes), + outcomes, + "window outcomes from {since}" + ); + assert_eq!( + sorted(window.query_types), + query_types, + "window types from {since}" + ); + assert_eq!( + latency(&window.latency), + expected_latency, + "window latency from {since}" + ); + + for heatmap_since in [since - 3 * 3_600 - 437, since, since + 3_600 + 5] { + let tag = format!("range from {since}, heatmap from {heatmap_since}"); + let scan = db.stats_scan_since(since, heatmap_since).await.unwrap(); + assert_eq!( + sorted(scan.metrics.outcomes), + outcomes, + "scan outcomes, {tag}" + ); + assert_eq!( + sorted(scan.metrics.query_types), + query_types, + "scan types, {tag}" + ); + assert_eq!( + latency(&scan.metrics.latency), + expected_latency, + "scan latency, {tag}" + ); + + let mut quarters: std::collections::BTreeMap = + std::collections::BTreeMap::new(); + for (q, [total, blocked, cached]) in per_quarter(since_ms) { + let slot = quarters.entry(q).or_default(); + slot[..3].copy_from_slice(&[total, blocked, cached]); + } + for (q, [total, _, _]) in per_quarter(heatmap_since * 1000) { + quarters.entry(q).or_default()[3] = total; + } + let mut expected = QuarterSeries::default(); + if let (Some(&first), Some(&last)) = (quarters.keys().next(), quarters.keys().last()) { + let len = usize::try_from(last - first + 1).unwrap(); + expected = QuarterSeries { + start: first * QUARTER_SECS, + total: vec![0; len], + blocked: vec![0; len], + cached: vec![0; len], + heatmap: vec![0; len], + }; + for (q, [total, blocked, cached, heatmap]) in quarters { + let i = usize::try_from(q - first).unwrap(); + expected.total[i] = total; + expected.blocked[i] = blocked; + expected.cached[i] = cached; + expected.heatmap[i] = heatmap; + } + } + assert_eq!(scan.series, expected, "series, {tag}"); + } + + for offset_minutes in [0_i64, 480, -300, 330, 345, -570, 7] { + let offset = offset_minutes * 60; + for bucket in [60, 900, 3_600, 6 * 3_600, 86_400] { + let expected: Vec = raw + .prepare( + "SELECT ((timestamp + ?3) / ?1) * ?1 - ?3 AS bucket, COUNT(*), \ + SUM(blocked), SUM(cached) \ + FROM query_logs WHERE timestamp >= ?2 GROUP BY bucket ORDER BY bucket", + ) + .unwrap() + .query_map( + rusqlite::params![bucket * 1000, since_ms, offset * 1000], + |r| { + Ok(TimelineMultiPoint { + timestamp: r.get::<_, i64>(0)? / 1000, + total: r.get(1)?, + blocked: r.get(2)?, + cached: r.get(3)?, + }) + }, + ) + .unwrap() + .collect::>() + .unwrap(); + assert_eq!( + db.timeline_multi_since(since, bucket, offset) + .await + .unwrap(), + expected, + "timeline from {since}, offset {offset_minutes} min, bucket {bucket} s" + ); + } + + let expected: Vec<(i64, i64, i64)> = raw + .prepare( + "SELECT ((timestamp / 1000 + ?2) / 86400 + 4) % 7 AS wday, \ + (timestamp / 1000 + ?2) % 86400 / 3600 AS hr, COUNT(*) \ + FROM query_logs WHERE timestamp >= ?1 GROUP BY wday, hr ORDER BY wday, hr", + ) + .unwrap() + .query_map(rusqlite::params![since_ms, offset], |r| { + Ok((r.get(0)?, r.get(1)?, r.get(2)?)) + }) + .unwrap() + .collect::>() + .unwrap(); + let got: Vec<(i64, i64, i64)> = db + .hourly_heatmap_since(since, offset) + .await + .unwrap() + .into_iter() + .map(|c| (c.weekday, c.hour, c.count)) + .collect(); + assert_eq!( + got, expected, + "heatmap from {since}, offset {offset_minutes} min" + ); + } + } +} diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index b66734a..19b8aeb 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -60,9 +60,8 @@ where } /// Classifying an outcome needs to know whether `result` held an answer. Read -/// off the table that is a rowid lookup per row and so the whole file; read off -/// `idx_query_logs_ts_metrics`, which carries the answer as a generated column, -/// it is the index alone. +/// off the table that is a rowid lookup per row and so the whole file; +/// `query_stats_metrics_hour` carries the answer, so it never has to be. #[tokio::test] async fn the_outcome_breakdown_never_reads_the_log_table() { let db = seeded_db().await; @@ -78,8 +77,7 @@ async fn the_outcome_breakdown_never_reads_the_log_table() { assert!( misses * 4 < db_pages, "outcome breakdown read {misses} of the database's {db_pages} pages; \ - that is the table, not the metrics index — has the planner stopped \ - honouring INDEXED BY, or has has_result left the index?" + that is the table — is the breakdown still folding query_stats_metrics_hour?" ); } @@ -145,8 +143,8 @@ async fn the_shared_scans_answer_what_the_separate_ones_did() { } /// The outcome breakdown, the query-type breakdown and the latency percentiles -/// are three foldings of one statement. Asked together they must cost one scan -/// of `idx_query_logs_ts_metrics`, not one each — which is what a page whose +/// are three foldings of one statement. Asked together they must cost one read +/// of `query_stats_metrics_hour`, not one each — which is what a page whose /// numbers were re-split across statements would pay. #[tokio::test] async fn the_window_readings_are_one_scan_between_them() { @@ -169,37 +167,6 @@ async fn the_window_readings_are_one_scan_between_them() { ); } -/// The charts ride the scan that answers the breakdowns. Before, the browser -/// fetched the timeline and the heatmap after the page landed, which walked -/// the metrics index a second time and the timestamp index on top — so the -/// page's readings and its charts together must cost what the readings alone -/// did, and less than the three statements they replaced. -#[tokio::test] -async fn the_page_and_its_charts_are_one_metrics_scan() { - let db = seeded_db().await; - - let scan = page_misses(&db, || db.stats_scan_since(0, 0)).await; - let window = page_misses(&db, || db.window_metrics_since(0)).await; - let replaced = window - + page_misses(&db, || db.timeline_multi_since(0, 3600, 0)).await - + page_misses(&db, || db.hourly_heatmap_since(0, 0)).await; - - assert!( - window > 0, - "no pages were read at all — the measurement is not working" - ); - assert!( - scan <= window + window / 10, - "the page's scan read {scan} pages against {window} for the window readings \ - alone — is it off idx_query_logs_ts_metrics, or reading the table?" - ); - assert!( - scan * 2 < replaced, - "the page's scan read {scan} pages and the statements it replaced {replaced} — \ - are the charts back on a scan of their own?" - ); -} - /// 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. @@ -277,26 +244,45 @@ async fn the_dashboard_readings_fold_rollups_rather_than_the_table() { } } -/// The heatmap reads `timestamp` and nothing else, so it belongs on the -/// smallest index that carries it. `idx_query_logs_ts_metrics` also covers it -/// and the planner will take it unaided, paying for four columns the query -/// never looks at. +/// The Statistics page's scan and the API's timeline, heatmap and window +/// readings fold the rollups too. Before, the page's scan and each of these was +/// a walk of an index as long as the window — the whole table under the +/// default retention. #[tokio::test] -async fn the_heatmap_reads_the_narrowest_index_that_covers_it() { - let db = seeded_db().await; +async fn the_statistics_readings_fold_rollups_rather_than_the_table() { + let db = dense_db().await; - let heatmap = page_misses(&db, || db.hourly_heatmap_since(0, 0)).await; - let metrics_scan = page_misses(&db, || db.timeline_multi_since(0, 3600, 0)).await; + let scan = page_misses(&db, || db.count_logs(Some("*"), None, None, None)).await; + let readings = [ + ( + "stats scan", + page_misses(&db, || db.stats_scan_since(0, 0)).await, + ), + ( + "window metrics", + page_misses(&db, || db.window_metrics_since(0)).await, + ), + ( + "timeline", + page_misses(&db, || db.timeline_multi_since(0, 3_600, 8 * 3_600)).await, + ), + ( + "heatmap", + page_misses(&db, || db.hourly_heatmap_since(0, 8 * 3_600)).await, + ), + ]; assert!( - heatmap > 0, - "no pages were read at all — the measurement is not working" - ); - assert!( - heatmap < metrics_scan, - "the heatmap read {heatmap} pages and a metrics scan {metrics_scan} — \ - it is no longer on idx_query_logs_timestamp" + 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 Database Health card's row count is read from one row of `settings`,