From 6505f706c3a3c093b0711a0cf279033660317434 Mon Sep 17 00:00:00 2001 From: Heng-Yi Wu <2316687+henry40408@users.noreply.github.com> Date: Sun, 13 Sep 2026 00:09:54 +0800 Subject: [PATCH 1/2] perf(stats): answer the Statistics page's metrics index in one scan MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The outcome breakdown, the query-type breakdown and the latency percentiles are three foldings of one window of idx_query_logs_ts_metrics, and were asked as two statements: one bucketed by time, one by (query_type, response_ms). Each scanned the index end to end, and the read pool spreads them over connections with 2 MiB of page cache each, so nothing was warm for the second. The bucket was never needed. The page renders no timeline — that chart is the client's — and the outcome breakdown sums across every bucket anyway, so bucketing only multiplied the rows the folds read: 68 846 at the 7-day range's hourly grain against 4 658 without it. window_metrics_since groups at (blocked, cached, has_result, query_type, response_ms) and all three readings fall out of it. The heatmap gets the opposite hint. It reads timestamp and nothing else, but the planner reached for the metrics index rather than the smallest one that covers it. Measured on a 370 k-row, 147 MiB database over a 7-day window: reading before after range_stats 8147 6053 heatmap (client fetch) 2153 1387 breakdowns alone 4174 2080 PAGE TOTAL (first response) 13163 11069 Co-Authored-By: Claude Opus 5 (1M context) --- ARCHITECTURE.md | 6 +- CLAUDE.md | 2 +- src/admin/stats.rs | 32 +++---- src/db.rs | 167 +++++++++++++++++++--------------- tests/stats_db_test.rs | 8 +- tests/stats_page_miss_test.rs | 47 ++++++++++ 6 files changed, 161 insertions(+), 101 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 9ae6572..be8eb74 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -265,7 +265,11 @@ That distinction is not hypothetical. `outcome_breakdown_since` was left uncover ### One scan per index, not one per reading -The Statistics page's five readings were four foldings of the metrics index over one window and two foldings of `(domain, timestamp)` over the same one, asked as six separate statements. Each re-walked an index another had just finished with, and the read pool round-robins them across connections holding 2 MiB of page cache each, so nothing was ever warm for the next. `range_metrics_since` groups at `(bucket, blocked, cached, has_result)` and `(query_type, response_ms)` — two statements the timeline, both breakdowns and the latency histogram are derived from — and `domain_stats_since` returns the top list and the distinct count from one materialized CTE. The single-purpose functions `/api/stats/*` calls are folds over the same statements, so there is one SQL spelling per fact. Rendering a 7-day window on that 370 k-row database went from 29 274 page misses (114 MiB) to 13 291 (52 MiB). +The Statistics page's five readings were four foldings of the metrics index over one window and two foldings of `(domain, timestamp)` over the same one, asked as six separate statements. Each re-walked an index another had just finished with, and the read pool round-robins them across connections holding 2 MiB of page cache each, so nothing was ever warm for the next. `window_metrics_since` groups at `(blocked, cached, has_result, query_type, response_ms)` — one statement both breakdowns and the latency histogram are derived from — and `domain_stats_since` returns the top list and the distinct count from one materialized CTE. The single-purpose functions `/api/stats/*` calls are folds over the same statements, so there is one SQL spelling per fact. Rendering a 7-day window on that 370 k-row database went from 29 274 page misses (114 MiB) to 11 069 (43 MiB). + +The window has no time bucket in it because the page draws no timeline — that chart is the client's, and `timeline_multi_since` is its own scan. 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. + +`INDEXED BY` appears on every statement that reads this index, in both directions. The two 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 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 c3c5c3a..7fb60d4 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -132,7 +132,7 @@ Statistics adds the conventions for a page whose readings sit in a **chosen wind - **The range is in the URL and the switcher is three ``s** (`/stats?range=30d`), because the range picks the *server's* window. `StatsRange::label()` is the one spelling shared by the link, the parse and every card title. An unrecognised range renders the default rather than 400ing — it is a link an operator can edit, and every window on offer is spelled out right above it. - **A date the server can only write in UTC ships as an ISO day plus its timestamp** (`data-date-ts`), and `app.js` restates it in the browser's locale — the same division as the query log's relative times, and for the same reason. - **This page is measured in page misses, not milliseconds.** Development is on an SSD and the appliance runs off an SD card, so a duration measured here says nothing about a Raspberry Pi; the pages a query fetches from the file are the same on both. `cargo nextest run --release --no-capture --run-ignored only stats_page_miss` with `BENCH_DB` pointed at a copy of a real database reports them. A wall-clock reading is the thing to distrust when the two disagree — it is what left the outcome breakdown scanning the whole table through version 11. -- **One scan per index, not one per reading.** `range_metrics_since` and `domain_stats_since` (`src/db.rs`) group at a grain every reading on the page can be folded out of; `compute_range_stats` (`src/admin/stats.rs`) is what the page calls. The single-purpose functions `/api/stats/*` uses are folds over the same statements — adding a seventh reading means folding it out of one of those two, not adding a statement. +- **One scan per index, not one per reading.** `window_metrics_since` and `domain_stats_since` (`src/db.rs`) group at a grain every reading on the page can be folded out of; `compute_range_stats` (`src/admin/stats.rs`) is what the page calls. The single-purpose functions `/api/stats/*` uses are folds over the same statements — adding a seventh reading means folding it out of one of those two, not adding a statement. The window carries no time bucket: the page renders no timeline, and bucketing multiplied the rows the folds read by fifteen for an answer summed across every bucket anyway. - 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/src/admin/stats.rs b/src/admin/stats.rs index aeb5b67..f8489ca 100644 --- a/src/admin/stats.rs +++ b/src/admin/stats.rs @@ -301,13 +301,12 @@ pub async fn compute_breakdowns( ) -> Result { let (window_secs, _) = range.window(); let since = now - window_secs; - let (query_types, outcomes) = tokio::try_join!( - db.query_type_breakdown_since(since), - db.outcome_breakdown_since(since), - )?; + // Both breakdowns fold out of one statement; asking for them separately is + // two scans of the index that answers either. + let metrics = db.window_metrics_since(since).await?; Ok(Breakdowns { - query_types, - outcomes, + query_types: metrics.query_types, + outcomes: metrics.outcomes, }) } @@ -337,15 +336,15 @@ pub async fn compute_highlights( /// Everything the Statistics page reads out of `query_logs` for its window, in /// the fewest scans the indexes allow. /// -/// The page used to ask for the four readings separately — a query-type -/// breakdown, an outcome breakdown, a latency summary, a unique-domain count — -/// alongside the top-domain list, and every one of them re-scanned an index -/// another had just walked. Two of them share -/// [`crate::db::Database::range_metrics_since`] and two share -/// [`crate::db::Database::domain_stats_since`], which is three index scans +/// The page used to ask for the five readings separately — a query-type +/// breakdown, an outcome breakdown, a latency summary, a unique-domain count, +/// a top-domain list — and every one of them re-scanned an index another had +/// just walked. Three of them share +/// [`crate::db::Database::window_metrics_since`] and two share +/// [`crate::db::Database::domain_stats_since`], which is two index scans /// instead of six. pub struct RangeStats { - pub metrics: crate::db::RangeMetrics, + pub metrics: crate::db::WindowMetrics, pub domains: crate::db::DomainStats, } @@ -355,13 +354,10 @@ pub async fn compute_range_stats( range: StatsRange, top_n: i64, ) -> Result { - let (window_secs, bucket_secs) = range.window(); + let (window_secs, _) = range.window(); let since = now - window_secs; - // The page renders no timeline — the chart is the client's — so the bucket - // width only bounds how many rows the outcome fold reads. Passing the - // range's own keeps it to one statement shared with the API endpoint. let (metrics, domains) = tokio::try_join!( - db.range_metrics_since(since, bucket_secs, 0), + db.window_metrics_since(since), db.domain_stats_since(since, top_n), )?; Ok(RangeStats { metrics, domains }) diff --git a/src/db.rs b/src/db.rs index 3c531ff..c9d218b 100644 --- a/src/db.rs +++ b/src/db.rs @@ -232,26 +232,38 @@ pub struct TimelineMultiPoint { } /// One grain of [`Database::metrics_by_bucket_since`]: how many queries fell in -/// a time bucket carrying a given outcome classification. Both the timeline and -/// the outcome breakdown are foldings of these. +/// a time bucket, blocked and cached counted separately. The timeline is a +/// folding of these. #[derive(Debug, Clone)] pub struct MetricsBucket { /// Start of the bucket, in **Unix seconds** — the same unit as /// [`TimelineMultiPoint::timestamp`]. pub timestamp: i64, + pub blocked: bool, + pub cached: bool, + pub count: i64, +} + +/// One grain of [`Database::metrics_window_since`]: how many queries in the +/// window carried a given outcome classification, query type and response time. +/// The outcome breakdown, the query-type breakdown and the latency percentiles +/// are all foldings of these. +#[derive(Debug, Clone)] +pub struct WindowMetricsRow { pub blocked: bool, pub cached: bool, /// Whether `result` held an answer. Carried by `idx_query_logs_ts_metrics` /// as a generated column so classifying an outcome never reads the table. pub has_result: bool, + pub query_type: String, + pub response_ms: i64, pub count: i64, } -/// The four Statistics readings that come off `idx_query_logs_ts_metrics`, -/// answered together by [`Database::range_metrics_since`]. +/// The three Statistics readings that come off `idx_query_logs_ts_metrics` in +/// one scan, answered together by [`Database::window_metrics_since`]. #[derive(Debug, Clone)] -pub struct RangeMetrics { - pub timeline: Vec, +pub struct WindowMetrics { pub outcomes: Vec<(String, i64)>, pub query_types: Vec<(String, i64)>, pub latency: LatencySummary, @@ -2149,42 +2161,38 @@ impl Database { Ok(timeline_from_buckets(&buckets)) } - /// The Statistics page's whole `idx_query_logs_ts_metrics` workload in the - /// two scans it actually needs, rather than the four it used to take. + /// Every `idx_query_logs_ts_metrics` reading the Statistics page renders, + /// in one scan of that index. /// - /// The timeline, the outcome breakdown, the query-type breakdown and the - /// latency histogram are four foldings of the same window of the same - /// index. Asked one statement each, `SQLite` reads that index end to end - /// four times — and the read pool round-robins them onto four connections - /// with 2 MiB of page cache each, so nothing is warm for the next one. - /// Grouping at a grain fine enough to derive all four collapses that to - /// two scans: 4 314 pages instead of 18 449 on a 370 k-row database. - pub async fn range_metrics_since( - &self, - since: i64, // unix seconds - bucket_secs: i64, - tz_offset_secs: i64, - ) -> Result { - let (buckets, distribution) = tokio::try_join!( - self.metrics_by_bucket_since(since, bucket_secs, tz_offset_secs), - self.metrics_distribution_since(since), - )?; - Ok(RangeMetrics { - timeline: timeline_from_buckets(&buckets), - outcomes: outcomes_from_buckets(&buckets), - query_types: query_types_from_distribution(&distribution), - latency: latency_from_distribution(&distribution), + /// The outcome breakdown, the query-type breakdown and the latency + /// histogram are three foldings of the same window of the same index. + /// Asked one statement each, `SQLite` reads that index end to end three + /// times — and the read pool round-robins them onto four connections with + /// 2 MiB of page cache each, so nothing is warm for the next one. The + /// grain below is fine enough to derive all three and costs one scan: + /// 2 157 pages instead of 6 471 on a 370 k-row database. + /// + /// The window carries no time bucket because the page renders no timeline + /// — that chart is the client's, and [`Self::timeline_multi_since`] is its + /// own scan. Bucketing here only multiplied the rows the folds read: at + /// the 7-day range's hourly grain, 68 846 of them against 4 658. + pub async fn window_metrics_since(&self, since: i64) -> Result { + let rows = self.metrics_window_since(since).await?; + Ok(WindowMetrics { + outcomes: outcomes_from_window(&rows), + query_types: query_types_from_window(&rows), + latency: latency_from_window(&rows), }) } - /// Query counts by time bucket and outcome class. Every column is carried - /// by `idx_query_logs_ts_metrics`, so the scan never looks a row up. + /// Query counts by time bucket. Every column is carried by + /// `idx_query_logs_ts_metrics`, so the scan never looks a row up. /// /// `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 - /// `has_result`. Measured on a 370 k-row database that is 12 173 page - /// misses against 2 157 for the identical answer. + /// `blocked` and `cached`. Measured on a 370 k-row database that is 12 173 + /// page misses against 2 157 for the identical answer. async fn metrics_by_bucket_since( &self, since: i64, // unix seconds @@ -2199,10 +2207,10 @@ impl Database { .call(move |conn| { let mut stmt = conn.prepare_cached( "SELECT ((timestamp + ?3) / ?1) * ?1 - ?3 AS bucket, \ - blocked, cached, has_result, COUNT(*) \ + blocked, cached, COUNT(*) \ FROM query_logs INDEXED BY idx_query_logs_ts_metrics \ WHERE timestamp >= ?2 \ - GROUP BY bucket, blocked, cached, has_result \ + GROUP BY bucket, blocked, cached \ ORDER BY bucket", )?; let rows = stmt @@ -2211,8 +2219,7 @@ impl Database { timestamp: row.get::<_, i64>(0)? / 1000, // return seconds blocked: row.get::<_, i64>(1)? != 0, cached: row.get::<_, i64>(2)? != 0, - has_result: row.get::<_, i64>(3)? != 0, - count: row.get(4)?, + count: row.get(3)?, }) })? .collect::, _>>()?; @@ -2222,31 +2229,38 @@ impl Database { Ok(result) } - /// Query counts by type and response time — the grain the query-type - /// breakdown and the latency histogram share. Both columns sit in - /// `idx_query_logs_ts_metrics` and the planner reaches for it unaided here, - /// because no other index carries `query_type` at all. - async fn metrics_distribution_since( + /// 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`. + async fn metrics_window_since( &self, since: i64, // unix seconds - ) -> Result, DbError> { + ) -> Result, DbError> { let since_ms = since * 1000; let rows = self .reader() .call(move |conn| { let mut stmt = conn.prepare_cached( - "SELECT query_type, response_ms, COUNT(*) \ - FROM query_logs \ + "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 query_type, response_ms", + GROUP BY blocked, cached, has_result, query_type, response_ms", )?; let rows = stmt .query_map(params![since_ms], |row| { - Ok(( - row.get::<_, String>(0)?, - row.get::<_, i64>(1)?, - row.get::<_, i64>(2)?, - )) + Ok(WindowMetricsRow { + blocked: row.get::<_, i64>(0)? != 0, + cached: row.get::<_, i64>(1)? != 0, + has_result: row.get::<_, i64>(2)? != 0, + query_type: row.get(3)?, + response_ms: row.get(4)?, + count: row.get(5)?, + }) })? .collect::, _>>()?; Ok(rows) @@ -2276,6 +2290,13 @@ 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, @@ -2286,7 +2307,7 @@ impl Database { "SELECT ((timestamp / 1000 + ?2) / 86400 + 4) % 7 AS wday, \ (timestamp / 1000 + ?2) % 86400 / 3600 AS hr, \ COUNT(*) \ - FROM query_logs \ + FROM query_logs INDEXED BY idx_query_logs_timestamp \ WHERE timestamp >= ?1 \ GROUP BY wday, hr \ ORDER BY wday, hr", @@ -2310,17 +2331,13 @@ impl Database { &self, since: i64, ) -> Result, DbError> { - let rows = self.metrics_distribution_since(since).await?; - Ok(query_types_from_distribution(&rows)) + let rows = self.metrics_window_since(since).await?; + Ok(query_types_from_window(&rows)) } - /// The bucket width is immaterial to the answer — the outcome counts are - /// summed across every bucket — so this asks for daily ones purely to keep - /// the row count down while sharing [`Self::metrics_by_bucket_since`]'s - /// single statement with the timeline. pub async fn outcome_breakdown_since(&self, since: i64) -> Result, DbError> { - let buckets = self.metrics_by_bucket_since(since, 86_400, 0).await?; - Ok(outcomes_from_buckets(&buckets)) + let rows = self.metrics_window_since(since).await?; + Ok(outcomes_from_window(&rows)) } pub async fn unique_domains_since(&self, since: i64) -> Result { @@ -2328,15 +2345,15 @@ impl Database { } /// Percentiles over `response_ms`, derived in Rust from the histogram - /// [`Self::metrics_distribution_since`] returns. + /// [`Self::metrics_window_since`] returns. /// /// The first implementation ran a window function /// (`ROW_NUMBER() OVER (ORDER BY response_ms)`), which forced `SQLite` to /// sort every matching row. A histogram is exact here because `response_ms` /// is integer milliseconds, and it costs one aggregate over the range. pub async fn latency_summary_since(&self, since: i64) -> Result { - let rows = self.metrics_distribution_since(since).await?; - Ok(latency_from_distribution(&rows)) + let rows = self.metrics_window_since(since).await?; + Ok(latency_from_window(&rows)) } /// On-disk storage breakdown for the Database Health card. Both figures come @@ -2451,12 +2468,12 @@ fn timeline_from_buckets(buckets: &[MetricsBucket]) -> Vec { out } -/// Classify each bucket and total across the whole window. The precedence — +/// Classify each grain and total across the whole window. The precedence — /// blocked, then cached, then whether an answer came back — is the one the /// query log's Verdict column shows, so a row cannot be counted twice. -fn outcomes_from_buckets(buckets: &[MetricsBucket]) -> Vec<(String, i64)> { +fn outcomes_from_window(rows: &[WindowMetricsRow]) -> Vec<(String, i64)> { let (mut blocked, mut cached, mut resolved, mut empty) = (0i64, 0i64, 0i64, 0i64); - for b in buckets { + for b in rows { let slot = if b.blocked { &mut blocked } else if b.cached { @@ -2484,10 +2501,10 @@ fn outcomes_from_buckets(buckets: &[MetricsBucket]) -> Vec<(String, i64)> { /// Counts per query type, busiest first — the same order the single-purpose /// `GROUP BY query_type ORDER BY cnt DESC` returned. -fn query_types_from_distribution(rows: &[(String, i64, i64)]) -> Vec<(String, i64)> { +fn query_types_from_window(rows: &[WindowMetricsRow]) -> Vec<(String, i64)> { let mut totals: HashMap<&str, i64> = HashMap::new(); - for (qtype, _, count) in rows { - *totals.entry(qtype.as_str()).or_default() += count; + for row in rows { + *totals.entry(row.query_type.as_str()).or_default() += row.count; } let mut out: Vec<(String, i64)> = totals .into_iter() @@ -2497,12 +2514,12 @@ fn query_types_from_distribution(rows: &[(String, i64, i64)]) -> Vec<(String, i6 out } -/// Collapse the (`query_type`, `response_ms`) grain down to the ascending -/// `response_ms` histogram the percentiles are read off. -fn latency_from_distribution(rows: &[(String, i64, i64)]) -> LatencySummary { +/// Collapse the window grain down to the ascending `response_ms` histogram the +/// percentiles are read off. +fn latency_from_window(rows: &[WindowMetricsRow]) -> LatencySummary { let mut hist: BTreeMap = BTreeMap::new(); - for (_, ms, count) in rows { - *hist.entry(*ms).or_default() += count; + for row in rows { + *hist.entry(row.response_ms).or_default() += row.count; } let hist: Vec<(i64, i64)> = hist.into_iter().collect(); latency_summary_from_histogram(&hist) diff --git a/tests/stats_db_test.rs b/tests/stats_db_test.rs index 2bb80df..1af1c7d 100644 --- a/tests/stats_db_test.rs +++ b/tests/stats_db_test.rs @@ -505,7 +505,7 @@ async fn both_timeline_types_report_bucket_starts_in_the_same_unit() { } #[tokio::test] -async fn range_metrics_agrees_with_the_single_purpose_queries() { +async fn window_metrics_agrees_with_the_single_purpose_queries() { let db = test_db().await; let entries = vec![ entry(600, "A", false, false, Some("1.1.1.1")), @@ -517,12 +517,8 @@ async fn range_metrics_agrees_with_the_single_purpose_queries() { ]; db.insert_query_logs(&entries).await.unwrap(); - let combined = db.range_metrics_since(0, 60, 0).await.unwrap(); + let combined = db.window_metrics_since(0).await.unwrap(); - assert_eq!( - combined.timeline, - db.timeline_multi_since(0, 60, 0).await.unwrap() - ); assert_eq!(combined.latency, db.latency_summary_since(0).await.unwrap()); assert_eq!( sorted(combined.query_types), diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index bad352e..a629684 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -137,3 +137,50 @@ async fn the_shared_scans_answer_what_the_separate_ones_did() { assert_eq!(combined.domains.unique, highlights.unique_domains); assert_eq!(combined.domains.top, top); } + +/// 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 +/// numbers were re-split across statements would pay. +#[tokio::test] +async fn the_window_readings_are_one_scan_between_them() { + let db = seeded_db().await; + + let together = page_misses(&db, || db.window_metrics_since(0)).await; + let separate = page_misses(&db, || db.outcome_breakdown_since(0)).await + + page_misses(&db, || db.query_type_breakdown_since(0)).await + + page_misses(&db, || db.latency_summary_since(0)).await; + + assert!( + together > 0, + "no pages were read at all — the measurement is not working" + ); + assert!( + together * 2 <= separate, + "the three window readings cost {together} pages together and {separate} \ + apart; one scan answering all three should be about a third of that — \ + has the page gone back to a statement per reading?" + ); +} + +/// 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. +#[tokio::test] +async fn the_heatmap_reads_the_narrowest_index_that_covers_it() { + let db = seeded_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; + + 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" + ); +} From d720340524355be3b843260d41422cbc2e9eb8e4 Mon Sep 17 00:00:00 2001 From: Heng-Yi Wu <2316687+henry40408@users.noreply.github.com> Date: Sun, 13 Sep 2026 00:35:35 +0800 Subject: [PATCH 2/2] perf(stats): maintain the query_logs row count instead of counting it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Database Health card prints how many rows query_logs holds and divides two of its estimates by it. SELECT COUNT(*) has no shortcut in SQLite: it walks the smallest index end to end, 1 386 pages on a 370 k-row database, on every Statistics page load. The count lives in settings under query_log_count now, seeded once by the version-13 migration and moved by the three statements that change how many rows the table holds — the logger's insert batch, the hourly prune, and Clear All. Each moves it inside its own transaction, so the counter cannot report a total the table stopped holding. A database with no counter row counts, which is what the migration seeded it out of. settings needs no new table and nothing enumerates its keys, so the row is invisible to the settings page. Measured on a 370 k-row, 147 MiB database over a 7-day window: reading before after db_health 1398 14 PAGE TOTAL (first response) 11069 9674 Co-Authored-By: Claude Opus 5 (1M context) --- ARCHITECTURE.md | 4 +- CLAUDE.md | 1 + src/db.rs | 125 +++++++++++++++++++++++++++++++++- tests/db_test.rs | 55 +++++++++++++++ tests/stats_page_miss_test.rs | 22 ++++++ 5 files changed, 203 insertions(+), 4 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index be8eb74..a8c1426 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -265,10 +265,12 @@ That distinction is not hypothetical. `outcome_breakdown_since` was left uncover ### One scan per index, not one per reading -The Statistics page's five readings were four foldings of the metrics index over one window and two foldings of `(domain, timestamp)` over the same one, asked as six separate statements. Each re-walked an index another had just finished with, and the read pool round-robins them across connections holding 2 MiB of page cache each, so nothing was ever warm for the next. `window_metrics_since` groups at `(blocked, cached, has_result, query_type, response_ms)` — one statement both breakdowns and the latency histogram are derived from — and `domain_stats_since` returns the top list and the distinct count from one materialized CTE. The single-purpose functions `/api/stats/*` calls are folds over the same statements, so there is one SQL spelling per fact. Rendering a 7-day window on that 370 k-row database went from 29 274 page misses (114 MiB) to 11 069 (43 MiB). +The Statistics page's five readings were four foldings of the metrics index over one window and two foldings of `(domain, timestamp)` over the same one, asked as six separate statements. Each re-walked an index another had just finished with, and the read pool round-robins them across connections holding 2 MiB of page cache each, so nothing was ever warm for the next. `window_metrics_since` groups at `(blocked, cached, has_result, query_type, response_ms)` — one statement both breakdowns and the latency histogram are derived from — and `domain_stats_since` returns the top list and the distinct count from one materialized CTE. The single-purpose functions `/api/stats/*` calls are folds over the same statements, so there is one SQL spelling per fact. Rendering a 7-day window on that 370 k-row database went from 29 274 page misses (114 MiB) to 9 674 (38 MiB). The window has no time bucket in it because the page draws no timeline — that chart is the client's, and `timeline_multi_since` is its own scan. 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 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. + `INDEXED BY` appears on every statement that reads this index, in both directions. The two 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 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 7fb60d4..167d02c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -133,6 +133,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. 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.** `window_metrics_since` and `domain_stats_since` (`src/db.rs`) group at a grain every reading on the page can be folded out of; `compute_range_stats` (`src/admin/stats.rs`) is what the page calls. The single-purpose functions `/api/stats/*` uses are folds over the same statements — adding a seventh reading means folding it out of one of those two, not adding a statement. The window carries no time bucket: the page renders no timeline, and bucketing multiplied the rows the folds read by fifteen for an answer summed across every bucket anyway. +- **A total nobody can count cheaply is maintained, not counted.** `query_logs`' row count lives in `settings` (`query_log_count`), moved by the insert batch, the prune and Clear All inside their own transactions — `SELECT COUNT(*)` walks an index end to end and the Database Health card asks on every load. A fourth write path to `query_logs` means a fourth `bump_log_count`, not a fourth reader. - Four bar lists in one template share **one askama macro** (`templates/_macros.html`); `{% call … %}` needs a matching `{% endcall %}` in askama 0.16, and `{% include %}` cannot see a loop variable at all. Account adds the conventions for **actions that need a password proof**: diff --git a/src/db.rs b/src/db.rs index c9d218b..d4055b5 100644 --- a/src/db.rs +++ b/src/db.rs @@ -302,6 +302,11 @@ pub struct LatencySummary { pub p99_ms: i64, } +/// `settings` key holding the `query_logs` row count. Not an operator-facing +/// setting — nothing enumerates this table, so it is simply the one row-shaped +/// place a counter can live without a table of its own. +const QUERY_LOG_COUNT_KEY: &str = "query_log_count"; + /// Default rusqlite cache is 16 statements; the read connection alone has /// ~20 distinct hot SQL strings (settings, stats, filter, token lookup), /// so anything below ~32 starts evicting on every admin poll. @@ -795,7 +800,23 @@ impl Database { )?; } - const LATEST_VERSION: i64 = 12; + if version < 13 { + // `SELECT COUNT(*)` has no shortcut in `SQLite`: it walks the + // smallest index end to end, 1 386 pages on a 370 k-row database, + // and the Database Health card asks for it on every Statistics + // page load. The count lives in `settings` from here, seeded once + // and then moved by the three statements that change it. + // + // `WHERE true` is what lets an upsert follow a SELECT — without it + // the parser reads `ON CONFLICT` as part of the SELECT. + conn.execute_batch( + "INSERT INTO settings (key, value) \ + SELECT 'query_log_count', COUNT(*) FROM query_logs WHERE true \ + ON CONFLICT(key) DO UPDATE SET value = excluded.value;", + )?; + } + + const LATEST_VERSION: i64 = 13; if version < LATEST_VERSION { conn.pragma_update(None, "user_version", LATEST_VERSION)?; } @@ -875,6 +896,7 @@ impl Database { ])?; } } + bump_log_count(&tx, entries.len() as i64)?; tx.commit()?; Ok(()) }) @@ -995,7 +1017,10 @@ impl Database { pub async fn delete_all_logs(&self) -> Result<(), DbError> { self.conn .call(|conn| { - conn.execute("DELETE FROM query_logs", [])?; + let tx = conn.transaction()?; + tx.execute("DELETE FROM query_logs", [])?; + set_log_count(&tx, 0)?; + tx.commit()?; Ok(()) }) .await?; @@ -1008,10 +1033,13 @@ impl Database { let count = self .conn .call(move |conn| { - let deleted = conn.execute( + let tx = conn.transaction()?; + let deleted = tx.execute( "DELETE FROM query_logs WHERE timestamp < ?1", params![timestamp_ms], )?; + bump_log_count(&tx, -(deleted as i64))?; + tx.commit()?; Ok(deleted as u64) }) .await?; @@ -2382,10 +2410,29 @@ impl Database { Ok(stats) } + /// How many rows `query_logs` holds, read from the counter the write paths + /// maintain rather than counted. + /// + /// `SELECT COUNT(*)` has no shortcut in `SQLite` — it walks the smallest + /// index end to end, 1 386 pages on a 370 k-row database — and the Database + /// Health card asks for it on every Statistics page load, for a number it + /// 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. + /// + /// 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) @@ -2560,6 +2607,23 @@ fn latency_summary_from_histogram(hist: &[(i64, i64)]) -> LatencySummary { } } +/// Move the maintained `query_logs` row count by `delta`. Takes the connection +/// the write is on so it lands in that write's transaction: a counter updated +/// beside its table rather than inside it is a counter that can disagree. +fn bump_log_count(conn: &rusqlite::Connection, delta: i64) -> rusqlite::Result<()> { + conn.prepare_cached("UPDATE settings SET value = CAST(value AS INTEGER) + ?1 WHERE key = ?2")? + .execute(params![delta, QUERY_LOG_COUNT_KEY])?; + Ok(()) +} + +/// Set the maintained `query_logs` row count outright, for the write that +/// leaves a known number of rows behind rather than a known change. +fn set_log_count(conn: &rusqlite::Connection, count: i64) -> rusqlite::Result<()> { + conn.prepare_cached("UPDATE settings SET value = ?1 WHERE key = ?2")? + .execute(params![count, QUERY_LOG_COUNT_KEY])?; + Ok(()) +} + /// Add a column to `table` if it doesn't already exist. /// /// `SQLite` doesn't support `ALTER TABLE ... ADD COLUMN IF NOT EXISTS`, so we @@ -3123,6 +3187,61 @@ mod tests { } } + /// The counter has to arrive holding what the table already holds. A + /// database that upgrades with a million rows in it and a counter seeded at + /// zero would report zero for as long as it kept those rows, and the + /// fallback in `total_log_count` would never fire to correct it — the row + /// exists, it is just wrong. + #[tokio::test] + async fn migration_v13_seeds_the_log_count_from_the_table() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("v12.db"); + let path_str = path.to_str().unwrap().to_string(); + + let entries: Vec = (0..3) + .map(|i| QueryLogEntry { + timestamp: 1_000_000 + i, + domain: "example.com".to_string(), + query_type: "A".to_string(), + client_ip: "10.0.0.1".to_string(), + blocked: false, + cached: false, + upstream: None, + doh_token: None, + result: None, + response_ms: 1, + authenticated_data: false, + }) + .collect(); + { + let db = Database::open(&path_str).await.unwrap(); + db.insert_query_logs(&entries).await.unwrap(); + db.close().await; + } + + // Wind it back to version 12: the rows stay, the counter does not. + { + let conn = rusqlite::Connection::open(&path_str).unwrap(); + conn.execute_batch( + "DELETE FROM settings WHERE key = 'query_log_count'; + PRAGMA user_version = 12;", + ) + .unwrap(); + } + + let migrated = Database::open(&path_str).await.unwrap(); + assert_eq!( + migrated + .get_setting(QUERY_LOG_COUNT_KEY) + .await + .unwrap() + .as_deref(), + Some("3"), + "the migration did not seed the counter" + ); + assert_eq!(migrated.total_log_count().await.unwrap(), 3); + } + #[tokio::test] async fn migration_v10_adds_client_index() { let dir = tempfile::tempdir().unwrap(); diff --git a/tests/db_test.rs b/tests/db_test.rs index b7d986f..44830c1 100644 --- a/tests/db_test.rs +++ b/tests/db_test.rs @@ -975,3 +975,58 @@ async fn test_filter_list_url_fetches_one_row_by_id() { "an unknown id must not fall through to another row" ); } + +/// `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 +/// holding, and nothing else would notice. +#[tokio::test] +async fn the_log_count_follows_every_write_that_changes_it() { + fn log(timestamp: i64) -> QueryLogEntry { + QueryLogEntry { + timestamp, + domain: "example.com".to_string(), + query_type: "A".to_string(), + client_ip: "10.0.0.1".to_string(), + blocked: false, + cached: false, + upstream: None, + doh_token: None, + result: None, + response_ms: 1, + authenticated_data: false, + } + } + + // The counter and a real count of the same rows, which must never differ. + async fn assert_holds(db: &Database, expected: i64) { + assert_eq!(db.total_log_count().await.unwrap(), expected); + assert_eq!( + db.count_logs(None, None, None, None).await.unwrap(), + expected + ); + } + + let db = test_db().await; + assert_holds(&db, 0).await; + + db.insert_query_logs(&[log(1_000_000), log(1_500_000), log(3_000_000)]) + .await + .unwrap(); + assert_holds(&db, 3).await; + + db.insert_query_logs(&[log(4_000_000)]).await.unwrap(); + assert_holds(&db, 4).await; + + // Seconds in, milliseconds stored: this drops the two before 2 000 s. + let pruned = db.prune_logs_before(2_000).await.unwrap(); + assert_eq!(pruned, 2); + assert_holds(&db, 2).await; + + // A prune that matches nothing must not move it either. + assert_eq!(db.prune_logs_before(2_000).await.unwrap(), 0); + assert_holds(&db, 2).await; + + db.delete_all_logs().await.unwrap(); + assert_holds(&db, 0).await; +} diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index a629684..c59dddb 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -184,3 +184,25 @@ async fn the_heatmap_reads_the_narrowest_index_that_covers_it() { it is no longer on idx_query_logs_timestamp" ); } + +/// The Database Health card's row count is read from one row of `settings`, +/// not counted. `SELECT COUNT(*)` has no shortcut in SQLite: it walks the +/// smallest index end to end, for a number the page prints and two of its +/// estimates divide by. +#[tokio::test] +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; + + assert!( + counted > 0, + "counting read no pages at all — the measurement is not working" + ); + assert!( + read * 4 < counted, + "the total read {read} pages and counting the same rows read {counted} — \ + is total_log_count back on COUNT(*)?" + ); +}