diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 9ae6572..a8c1426 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -265,7 +265,13 @@ 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 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 c3c5c3a..167d02c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -132,7 +132,8 @@ 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. +- **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/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..d4055b5 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, @@ -290,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. @@ -783,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)?; } @@ -863,6 +896,7 @@ impl Database { ])?; } } + bump_log_count(&tx, entries.len() as i64)?; tx.commit()?; Ok(()) }) @@ -983,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?; @@ -996,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?; @@ -2149,42 +2189,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 +2235,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 +2247,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 +2257,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 +2318,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 +2335,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 +2359,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 +2373,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 @@ -2365,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) @@ -2451,12 +2515,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 +2548,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 +2561,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) @@ -2543,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 @@ -3106,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_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..c59dddb 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -137,3 +137,72 @@ 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" + ); +} + +/// 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(*)?" + ); +}