From bba141bf59b63dbf416749531038b824dac6a48c Mon Sep 17 00:00:00 2001 From: Heng-Yi Wu <2316687+henry40408@users.noreply.github.com> Date: Sun, 13 Sep 2026 11:39:44 +0800 Subject: [PATCH] perf(stats): cut the dashboard tick's page misses by 43% The dashboard pays for its readings every 10 seconds. Two things made that tick expensive: - Totals and blocks came from one statement, and cache hits and latency from a second, but both walked the same 30 days of idx_query_logs_ts_metrics. summary_multi_since answers both from one scan by putting the allowed-only filter inside each CASE instead of the WHERE. - top_upstreams_since reads upstream and response_ms, which no index held, so it looked up the table row for every forwarded query. Migration 14 adds idx_query_logs_ts_upstream, a partial index on (timestamp, upstream, response_ms) WHERE upstream IS NOT NULL. It puts timestamp first so each logger batch is written in one place. On a 370k-row database a tick drops from 8 304 to 4 755 page misses. The index is 5.7 MiB, and a 500-row insert batch writes 56 pages instead of 53. Co-Authored-By: Claude Opus 5 (1M context) --- ARCHITECTURE.md | 11 +- src/admin/stats.rs | 41 +++---- src/db.rs | 204 ++++++++++++++++++++++------------ tests/stats_db_test.rs | 95 ++++++++-------- tests/stats_page_miss_test.rs | 50 ++++++++- 5 files changed, 254 insertions(+), 147 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 7113ce9..c6e59ed 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -238,14 +238,15 @@ Everything is in a single SQLite file (`noadd.sqlite3` by default; a legacy `noa | `sessions` | Active admin sessions (token, user_id, ip, user agent, timestamps) | | `api_keys` | Programmatic API keys (BLAKE2b hash, owning user_id, `ON DELETE CASCADE`) | -`query_logs` carries four indexes, all of them shaped by the statistics queries: +`query_logs` carries five indexes, all of them shaped by the statistics queries: | Index | Serves | | --- | --- | | `timestamp` | the time-window filter every stats query starts with | | `(domain, timestamp)` | top domains, unique domains | | `(client_ip, doh_token, timestamp)` | top clients | -| `(timestamp, blocked, cached, response_ms, query_type, has_result)` | timeline, query-type breakdown, latency histogram, outcome breakdown | +| `(timestamp, blocked, cached, response_ms, query_type, has_result)` | timeline, query-type breakdown, latency histogram, outcome breakdown, the dashboard summary | +| `(timestamp, upstream, response_ms) WHERE upstream IS NOT NULL` | top upstreams | The first two composites put the grouped columns first and `timestamp` last, which is what makes them covering for a `GROUP BY … WHERE timestamp >= ?` shape — the aggregation reads the index alone instead of scanning the window and building a temp b-tree over it. Top clients went from 143 ms to 20 ms on a 447 k-row database that way. @@ -253,6 +254,8 @@ The last one inverts that order because its queries do not group by a column at `has_result` is a VIRTUAL generated column — `result IS NOT NULL AND result != ''` — which occupies no table space and exists so the outcome breakdown can classify a query without reading one. It is the last column of the metrics index, and the query that needs it carries an `INDEXED BY`: with `timestamp` alone also matching the range the planner picks that smaller index and pays a rowid lookup per row, which is the whole table. An index on the bare expression rather than a named column was tried first and the planner would not treat it as covering. +The upstream index is partial because blocked and cached answers never reach an upstream, so more than half the rows have nothing to put in it (56% on a 370 k-row database), and its only query excludes them anyway. It is timestamp-first for the writer's sake rather than the reader's: both orders answer the dashboard's 24-hour top upstreams in about 200 pages against 1 608 through `timestamp` and a rowid lookup per row, but the logger appends at the newest end, and an upstream-first index spreads every batch across one insertion point per upstream — 65 pages written per 500-row batch against 56, where no index at all writes 53. It is 5.7 MiB on that database. + Indexes are not free here. On that same 103 MiB database `dbstat` attributes 20 MiB to `(domain, timestamp)`, 18 MiB to `(client_ip, doh_token, timestamp)`, 9 MiB to the metrics index and 7 MiB to `timestamp` — the two composites added for statistics cost about a quarter of the file. Measuring an index by the file-size delta of `CREATE INDEX` understates it whenever the database is carrying a freelist, since the new pages come out of that first; `dbstat` reports the real figure. ### Measuring these queries @@ -273,7 +276,9 @@ The charts did still pay for scans of their own after that: the browser fetched The Database Health card's row count is the one reading that is not a scan of anything. `SELECT COUNT(*)` has no shortcut in SQLite — it walks the smallest index end to end, 1 386 pages on that database, for a number the card prints and two of its estimates divide by — so the count lives in `settings` under `query_log_count`, seeded by the version-13 migration and moved by the three statements that change how many rows `query_logs` holds: the logger's insert batch, the hourly prune, and Clear All. Each moves it inside its own transaction, which is what makes the counter unable to disagree with the table; `total_log_count` falls back to counting when the row is missing, which is the state the migration seeds it out of. The card went from 1 398 pages to 14. -`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. +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. + +`INDEXED BY` appears on every statement that reads this index, in both directions. The ones that need `blocked`, `cached` or `has_result` name `idx_query_logs_ts_metrics` because the planner otherwise takes the smaller `idx_query_logs_timestamp` and pays a rowid lookup per row; top upstreams names its partial index so drifting statistics cannot send it back to that lookup; the heatmap, which reads `timestamp` and nothing else, names `idx_query_logs_timestamp` for the opposite reason — left alone the planner took the metrics index and read 2 153 pages where 1 386 answer it. 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/src/admin/stats.rs b/src/admin/stats.rs index eb9c707..06d27d5 100644 --- a/src/admin/stats.rs +++ b/src/admin/stats.rs @@ -68,15 +68,8 @@ pub async fn compute_summary(db: &Database, now: i64) -> Result f64 { @@ -95,21 +88,21 @@ pub async fn compute_summary(db: &Database, now: i64) -> Result Result<((i64, i64), (i64, i64), (i64, i64)), DbError> { + ) -> Result<[WindowSummary; 3], DbError> { let today_ms = since_today * 1000; let d7_ms = since_7d * 1000; let d30_ms = since_30d * 1000; let result = self .reader() .call(move |conn| { + // `INDEXED BY` for the reason `metrics_by_bucket_since` gives. let mut stmt = conn.prepare_cached( "SELECT COUNT(CASE WHEN timestamp >= ?1 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?1 THEN blocked ELSE 0 END), 0), + COALESCE(SUM(CASE WHEN timestamp >= ?1 THEN blocked END), 0), + COUNT(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN timestamp >= ?1 AND blocked = 0 THEN response_ms END), 0), COUNT(CASE WHEN timestamp >= ?2 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?2 THEN blocked ELSE 0 END), 0), - COUNT(CASE WHEN timestamp >= ?3 THEN 1 END), - COALESCE(SUM(CASE WHEN timestamp >= ?3 THEN blocked ELSE 0 END), 0) - FROM query_logs + COALESCE(SUM(CASE WHEN timestamp >= ?2 THEN blocked END), 0), + COUNT(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN timestamp >= ?2 AND blocked = 0 THEN response_ms END), 0), + COUNT(*), + COALESCE(SUM(blocked), 0), + COUNT(CASE WHEN blocked = 0 THEN 1 END), + COALESCE(SUM(CASE WHEN blocked = 0 THEN cached END), 0), + COALESCE(AVG(CASE WHEN blocked = 0 THEN response_ms END), 0) + FROM query_logs INDEXED BY idx_query_logs_ts_metrics WHERE timestamp >= ?3", )?; let row = stmt.query_row(params![today_ms, d7_ms, d30_ms], |row| { - Ok(( - (row.get::<_, i64>(0)?, row.get::<_, i64>(1)?), - (row.get::<_, i64>(2)?, row.get::<_, i64>(3)?), - (row.get::<_, i64>(4)?, row.get::<_, i64>(5)?), - )) - })?; - Ok(row) - }) - .await?; - Ok(result) - } - - /// Returns ((`cache_hits`, `allowed_total`, `avg_response_ms`), ...) for today / 7d / 30d in one scan. - /// All `since_*` values are in epoch seconds. Caller MUST pass the widest window as `since_30d`. - pub async fn cache_stats_multi_since( - &self, - since_today: i64, - since_7d: i64, - since_30d: i64, - ) -> Result<((i64, i64, f64), (i64, i64, f64), (i64, i64, f64)), DbError> { - let today_ms = since_today * 1000; - let d7_ms = since_7d * 1000; - let d30_ms = since_30d * 1000; - let result = self - .reader() - .call(move |conn| { - let mut stmt = conn.prepare_cached( - "SELECT - COALESCE(SUM(CASE WHEN timestamp >= ?1 THEN cached END), 0), - COUNT(CASE WHEN timestamp >= ?1 THEN 1 END), - COALESCE(AVG(CASE WHEN timestamp >= ?1 THEN response_ms END), 0), - COALESCE(SUM(CASE WHEN timestamp >= ?2 THEN cached END), 0), - COUNT(CASE WHEN timestamp >= ?2 THEN 1 END), - COALESCE(AVG(CASE WHEN timestamp >= ?2 THEN response_ms END), 0), - COALESCE(SUM(CASE WHEN timestamp >= ?3 THEN cached END), 0), - COUNT(CASE WHEN timestamp >= ?3 THEN 1 END), - COALESCE(AVG(CASE WHEN timestamp >= ?3 THEN response_ms END), 0) - FROM query_logs - WHERE timestamp >= ?3 AND blocked = 0", - )?; - let row = stmt.query_row(params![today_ms, d7_ms, d30_ms], |row| { - Ok(( - ( - row.get::<_, i64>(0)?, - row.get::<_, i64>(1)?, - row.get::<_, f64>(2)?, - ), - ( - row.get::<_, i64>(3)?, - row.get::<_, i64>(4)?, - row.get::<_, f64>(5)?, - ), - ( - row.get::<_, i64>(6)?, - row.get::<_, i64>(7)?, - row.get::<_, f64>(8)?, - ), - )) + let window = |at: usize| -> rusqlite::Result { + Ok(WindowSummary { + total: row.get(at)?, + blocked: row.get(at + 1)?, + allowed: row.get(at + 2)?, + cache_hits: row.get(at + 3)?, + avg_response_ms: row.get(at + 4)?, + }) + }; + Ok([window(0)?, window(5)?, window(10)?]) })?; Ok(row) }) @@ -2187,8 +2195,15 @@ impl Database { let rows = self .reader() .call(move |conn| { + // `INDEXED BY` so a drift in the planner's statistics cannot send + // this back to `idx_query_logs_timestamp` and a lookup per row. + // The `upstream IS NOT NULL` term is what lets the partial index + // answer at all. let mut stmt = conn.prepare_cached( - "SELECT upstream, COUNT(*) as cnt, AVG(response_ms) as avg_ms FROM query_logs WHERE timestamp >= ?1 AND upstream IS NOT NULL GROUP BY upstream ORDER BY cnt DESC LIMIT ?2", + "SELECT upstream, COUNT(*) as cnt, AVG(response_ms) as avg_ms \ + FROM query_logs INDEXED BY idx_query_logs_ts_upstream \ + WHERE timestamp >= ?1 AND upstream IS NOT NULL \ + GROUP BY upstream ORDER BY cnt DESC LIMIT ?2", )?; let rows = stmt .query_map(params![since_ms, limit], |row| { @@ -3400,6 +3415,57 @@ mod tests { assert_eq!(migrated.total_log_count().await.unwrap(), 3); } + /// A database from before version 14 has to come out of `open` holding the + /// upstream index, because `top_upstreams_since` names it with `INDEXED BY` + /// and a statement naming a missing index does not prepare at all — the + /// dashboard would lose its upstream list rather than merely run slower. + #[tokio::test] + async fn migration_v14_adds_the_upstream_index() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("v13.db"); + let path_str = path.to_str().unwrap().to_string(); + + let entries: Vec = (0..4) + .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: (i != 0).then(|| "tls://1.1.1.1:853".to_string()), + doh_token: None, + result: None, + response_ms: 10 * i, + authenticated_data: false, + }) + .collect(); + { + let db = Database::open(&path_str).await.unwrap(); + db.insert_query_logs(&entries).await.unwrap(); + db.close().await; + } + { + let conn = rusqlite::Connection::open(&path_str).unwrap(); + conn.execute_batch( + "DROP INDEX idx_query_logs_ts_upstream; + PRAGMA user_version = 13;", + ) + .unwrap(); + } + + let migrated = Database::open(&path_str).await.unwrap(); + let indexes = query_log_index_names(&migrated).await; + assert!( + indexes.iter().any(|n| n == "idx_query_logs_ts_upstream"), + "upstream index should exist after migrating: {indexes:?}" + ); + let top = migrated.top_upstreams_since(0, 10).await.unwrap(); + assert_eq!(top.len(), 1); + assert_eq!(top[0].count, 3, "the unforwarded row is not an upstream's"); + assert!((top[0].avg_ms - 20.0).abs() < 1e-9); + } + #[tokio::test] async fn migration_v10_adds_client_index() { let dir = tempfile::tempdir().unwrap(); diff --git a/tests/stats_db_test.rs b/tests/stats_db_test.rs index 21eec54..949d05e 100644 --- a/tests/stats_db_test.rs +++ b/tests/stats_db_test.rs @@ -364,75 +364,70 @@ async fn compute_summary_populates_7d_and_30d_rates() { assert!((s.avg_response_ms_30d - 5.0).abs() < 1e-9); } +/// One statement answers what the dashboard used to ask two for: totals and +/// blocks over every query, cache hits and latency over the allowed ones only. +/// The blocked rows are given a response time the allowed ones never have, so +/// an average that let them in would show it. #[tokio::test] -async fn count_queries_multi_since_matches_single_window() { +async fn summary_multi_since_computes_each_window() { let db = test_db().await; let now: i64 = 40 * 86400; let one_day: i64 = 86400; + let blocked = |ts| { + let mut e = entry(ts, "A", true, false, Some("NXDOMAIN")); + e.response_ms = 900; + e + }; let entries = vec![ - entry(now - 100, "A", true, false, Some("NXDOMAIN")), + blocked(now - 100), entry(now - 200, "A", false, true, Some("NOERROR")), entry(now - 3 * one_day, "A", false, false, Some("NOERROR")), - entry(now - 20 * one_day, "A", true, false, Some("NXDOMAIN")), + blocked(now - 20 * one_day), ]; db.insert_query_logs(&entries).await.unwrap(); - let single_today = db.count_queries_since(now - one_day).await.unwrap(); - let single_7d = db.count_queries_since(now - 7 * one_day).await.unwrap(); - let single_30d = db.count_queries_since(now - 30 * one_day).await.unwrap(); - - let (today, d7, d30) = db - .count_queries_multi_since(now - one_day, now - 7 * one_day, now - 30 * one_day) + let [today, d7, d30] = db + .summary_multi_since(now - one_day, now - 7 * one_day, now - 30 * one_day) .await .unwrap(); - // The single-window helper returns the total only, so the cross-check - // covers totals; the blocked halves are pinned directly below. - assert_eq!(today.0, single_today); - assert_eq!(d7.0, single_7d); - assert_eq!(d30.0, single_30d); + // The totals agree with the single-window count the 1-minute figure uses. + assert_eq!( + today.total, + db.count_queries_since(now - one_day).await.unwrap() + ); + assert_eq!( + d30.total, + db.count_queries_since(now - 30 * one_day).await.unwrap() + ); - // Sanity: today = (2, 1); 7d = (3, 1); 30d = (4, 2). - assert_eq!(today, (2, 1)); - assert_eq!(d7, (3, 1)); - assert_eq!(d30, (4, 2)); + // today -> 2 queries, 1 blocked, 1 allowed and cached; + // 7d -> +1 allowed, uncached; + // 30d -> +1 blocked, so the allowed figures match 7d. + let expect = |w: noadd::db::WindowSummary, total, blocked, allowed, hits| { + assert_eq!( + (w.total, w.blocked, w.allowed, w.cache_hits), + (total, blocked, allowed, hits) + ); + assert!( + (w.avg_response_ms - 5.0).abs() < 1e-9, + "blocked rows leaked into the average: {w:?}" + ); + }; + expect(today, 2, 1, 1, 1); + expect(d7, 3, 1, 2, 1); + expect(d30, 4, 2, 2, 1); } #[tokio::test] -async fn cache_stats_multi_since_computes_each_window() { - // Previously cross-checked against a single-window cache_stats_since, which - // production never called and which has been removed. The expectations are - // now stated directly so the multi-window query keeps its coverage. +async fn summary_multi_since_on_an_empty_window_reports_zeroes() { let db = test_db().await; - let now: i64 = 40 * 86400; - let one_day: i64 = 86400; - - let entries = vec![ - entry(now - 100, "A", true, false, Some("NXDOMAIN")), - entry(now - 200, "A", false, true, Some("NOERROR")), - entry(now - 3 * one_day, "A", false, false, Some("NOERROR")), - entry(now - 20 * one_day, "A", true, false, Some("NXDOMAIN")), - ]; - db.insert_query_logs(&entries).await.unwrap(); - - let (today, d7, d30) = db - .cache_stats_multi_since(now - one_day, now - 7 * one_day, now - 30 * one_day) - .await - .unwrap(); - - // Blocked rows are excluded, so only the allowed ones count: - // today -> 1 allowed, cached; 7d -> +1 allowed, uncached; - // 30d -> the 20-day-old row is blocked, so identical to 7d. - // Every seeded row has response_ms = 5. - assert_eq!((today.0, today.1), (1, 1)); - assert!((today.2 - 5.0).abs() < 1e-9); - - assert_eq!((d7.0, d7.1), (1, 2)); - assert!((d7.2 - 5.0).abs() < 1e-9); - - assert_eq!((d30.0, d30.1), (1, 2)); - assert!((d30.2 - 5.0).abs() < 1e-9); + let windows = db.summary_multi_since(0, 0, 0).await.unwrap(); + for w in windows { + assert_eq!((w.total, w.blocked, w.allowed, w.cache_hits), (0, 0, 0, 0)); + assert!(w.avg_response_ms.abs() < 1e-9); + } } #[tokio::test] diff --git a/tests/stats_page_miss_test.rs b/tests/stats_page_miss_test.rs index 400a47d..c15fc7a 100644 --- a/tests/stats_page_miss_test.rs +++ b/tests/stats_page_miss_test.rs @@ -29,7 +29,9 @@ async fn seeded_db() -> Database { client_ip: format!("10.0.0.{}", i % 20), blocked: i % 7 == 0, cached: i % 5 == 0, - upstream: None, + // About half forwarded, as on a real resolver: blocked and cached + // answers never reach an upstream. + upstream: (i % 2 == 0).then(|| format!("tls://1.1.1.{}:853", i % 4)), doh_token: None, result: if i % 11 == 0 { None @@ -194,6 +196,52 @@ async fn the_page_and_its_charts_are_one_metrics_scan() { ); } +/// The dashboard's summary asks every tick for totals, blocks, cache hits and +/// mean latency over three windows. Every one of those is a column of +/// `idx_query_logs_ts_metrics`, so together they cost one scan of it — not the +/// two that asking the blocked counts and the cache figures separately paid. +#[tokio::test] +async fn the_dashboard_summary_is_one_metrics_scan() { + let db = seeded_db().await; + let now = ROWS; // seconds; the seed runs from 0 to ROWS + + let summary = page_misses(&db, || stats::compute_summary(&db, now)).await; + let one_scan = page_misses(&db, || db.window_metrics_since(0)).await; + + assert!( + one_scan > 0, + "no pages were read at all — the measurement is not working" + ); + assert!( + summary <= one_scan + one_scan / 10, + "the summary read {summary} pages where one scan of the metrics index \ + reads {one_scan} — has it gone back to a statement per figure?" + ); +} + +/// The top upstreams read `upstream` and `response_ms`, which no index carried, +/// so every forwarded query in the window was a rowid lookup into the table — +/// on every dashboard tick. A partial index over the forwarded rows answers it +/// alone. +#[tokio::test] +async fn the_top_upstreams_never_read_the_log_table() { + let db = seeded_db().await; + let storage = db.db_storage_stats().await.unwrap(); + let db_pages = storage.main_bytes / 4096; + + let misses = page_misses(&db, || db.top_upstreams_since(0, 10)).await; + + assert!( + misses > 0, + "no pages were read at all — the measurement is not working" + ); + assert!( + misses * 4 < db_pages, + "top upstreams read {misses} of the database's {db_pages} pages; that \ + is the table, not an index — is idx_query_logs_ts_upstream missing?" + ); +} + /// 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