Public: anyone can read this; the crew can change it.
The home page and repo page still stall for about a second on a cold authenticated request #7940
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/7896-the-home-page-and-repo-page-still-stall → main 2 commits fork 3 threads · 3 unresolved
17 files
changed +331
−33
docs/CACHING.md +11
| @@ -291,6 +291,17 @@ fixture; all three caches hit): | ||
| 291 | 291 | The anonymous door (1.5 ms, 10 statements), the app shelf, and the |
| 292 | 292 | "On you" card. Each costs less than its cache's key would. |
| 293 | 293 | |
| 294 | ## Telemetry does not invalidate (#7896) | |
| 295 | ||
| 296 | The write clock counts every row the connection changes, and a signed-in | |
| 297 | visit itself writes: route timings a second after the request, usage | |
| 298 | counts, flag reads, the session's last-seen time, the home visit, page | |
| 299 | vitals, machine and memory samples. Counted, they kept every cache cold | |
| 300 | for the next visitor. These writers run inside `quietly` (`core/write_clock.ts`), | |
| 301 | which leaves their rows out of the stamp. Wrap only a write to a table no | |
| 302 | cached page is built from; a page that shows telemetry is bounded by the | |
| 303 | 30 seconds a cache entry lives. `test/write-clock-quiet.test.ts` proves it. | |
| 304 | ||
| 294 | 305 | ## The writes that invalidate |
| 295 | 306 | |
| 296 | 307 | Each row is an action (or, for a push, the post-receive hook, the one |
src/boards/memory.ts +3 −2
| @@ -8,6 +8,7 @@ | ||
| 8 | 8 | import type { Database } from "bun:sqlite"; |
| 9 | 9 | import { heapStats } from "bun:jsc"; |
| 10 | 10 | import type { App } from "../app.ts"; |
| 11 | import { quietly } from "../core/write_clock.ts"; | |
| 11 | 12 | |
| 12 | 13 | export const MEMORY_EVERY_MS = 60_000; |
| 13 | 14 | export const HOUR_MS = 3_600_000; |
| @@ -29,7 +30,7 @@ const valid = (n: number) => Number.isFinite(n) && n >= 0; | ||
| 29 | 30 | export function recordMemory(db: Database, rss: number, heap: number, now: number): void { |
| 30 | 31 | if (!valid(rss) || !valid(heap) || !valid(now)) return; |
| 31 | 32 | const hour = Math.floor(now / HOUR_MS) * HOUR_MS; |
| 32 | db.transaction(() => { | |
| 33 | db.transaction(() => quietly(db, () => { | |
| 33 | 34 | db.run( |
| 34 | 35 | `INSERT INTO memory_hour (hour, samples, rss_sum, rss_max, heap_sum, heap_max) VALUES (?, 1, ?, ?, ?, ?) |
| 35 | 36 | ON CONFLICT(hour) DO UPDATE SET samples = samples + 1, rss_sum = rss_sum + excluded.rss_sum, |
| @@ -38,7 +39,7 @@ export function recordMemory(db: Database, rss: number, heap: number, now: numbe | ||
| 38 | 39 | [hour, rss, rss, heap, heap], |
| 39 | 40 | ); |
| 40 | 41 | db.run("DELETE FROM memory_hour WHERE hour < ?", [hour - KEEP_MS]); |
| 41 | })(); | |
| 42 | }))(); | |
| 42 | 43 | } |
| 43 | 44 | |
| 44 | 45 | /** The hours in the `hours` before `now` (the current one included), oldest first. */ |
src/boards/ring.ts +3 −2
| @@ -7,6 +7,7 @@ | ||
| 7 | 7 | */ |
| 8 | 8 | import type { Database } from "bun:sqlite"; |
| 9 | 9 | import { withoutWaiting } from "../kernel/db.ts"; |
| 10 | import { quietly } from "../core/write_clock.ts"; | |
| 10 | 11 | |
| 11 | 12 | export const FINE_MS = 15_000; |
| 12 | 13 | export const COARSE_MS = 300_000; |
| @@ -104,7 +105,7 @@ export function record(db: Database, points: readonly Point[], now: number): voi | ||
| 104 | 105 | lag_ms, lag_ms_max, checks, agents) |
| 105 | 106 | VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`, |
| 106 | 107 | ); |
| 107 | withoutWaiting(db, db.transaction(() => { | |
| 108 | withoutWaiting(db, db.transaction(() => quietly(db, () => { | |
| 108 | 109 | for (const p of points) { |
| 109 | 110 | const c = p.celsius ?? null; |
| 110 | 111 | const lag = p.lagMs ?? null; |
| @@ -137,5 +138,5 @@ export function record(db: Database, points: readonly Point[], now: number): voi | ||
| 137 | 138 | } |
| 138 | 139 | db.query("DELETE FROM machine_sample WHERE step = 15 AND at < ?").run(iso(now - FINE_KEEP_MS)); |
| 139 | 140 | db.query("DELETE FROM machine_sample WHERE step = 300 AND at < ?").run(iso(now - COARSE_KEEP_MS)); |
| 140 | })); | |
| 141 | }))); | |
| 141 | 142 | } |
src/core/flags.ts +3 −2
| @@ -17,6 +17,7 @@ | ||
| 17 | 17 | */ |
| 18 | 18 | |
| 19 | 19 | import type { Database } from "bun:sqlite"; |
| 20 | import { quietly } from "./write_clock.ts"; | |
| 20 | 21 | |
| 21 | 22 | export type FlagDecl = { |
| 22 | 23 | /** One line: what the flag switches and why it exists. */ |
| @@ -274,12 +275,12 @@ export function makeFlags<const D extends Record<string, FlagDecl>>(decls: D) { | ||
| 274 | 275 | `INSERT INTO flag_use (day, flag, variant, n) VALUES (?1, ?2, ?3, ?4) |
| 275 | 276 | ON CONFLICT (day, flag, variant) DO UPDATE SET n = n + excluded.n`, |
| 276 | 277 | ); |
| 277 | db.transaction(() => { | |
| 278 | db.transaction(() => quietly(db, () => { | |
| 278 | 279 | for (const [key, n] of taken) { |
| 279 | 280 | const [day, flag, variant] = key.split("\t"); |
| 280 | 281 | up.run(day!, flag!, Number(variant), n); |
| 281 | 282 | } |
| 282 | })(); | |
| 283 | }))(); | |
| 283 | 284 | } catch { |
| 284 | 285 | for (const [key, n] of taken) pending.set(key, (pending.get(key) ?? 0) + n); |
| 285 | 286 | } |
src/core/home_visit.ts +6 −3
| @@ -5,6 +5,7 @@ | ||
| 5 | 5 | */ |
| 6 | 6 | |
| 7 | 7 | import type { Database } from "bun:sqlite"; |
| 8 | import { quietly } from "./write_clock.ts"; | |
| 8 | 9 | |
| 9 | 10 | export const VISIT_WRITE_GAP_MS = 60 * 1000; |
| 10 | 11 | |
| @@ -16,9 +17,11 @@ export function lastVisit(db: Database, userId: string): number | undefined { | ||
| 16 | 17 | export function noteVisit(db: Database, userId: string, now: number): number | undefined { |
| 17 | 18 | const before = lastVisit(db, userId); |
| 18 | 19 | if (before === undefined || now - before >= VISIT_WRITE_GAP_MS) |
| 19 | db.query( | |
| 20 | "INSERT INTO home_visit (user_id, at) VALUES (?1, ?2) ON CONFLICT(user_id) DO UPDATE SET at = excluded.at", | |
| 21 | ).run(userId, now); | |
| 20 | quietly(db, () => | |
| 21 | db | |
| 22 | .query("INSERT INTO home_visit (user_id, at) VALUES (?1, ?2) ON CONFLICT(user_id) DO UPDATE SET at = excluded.at") | |
| 23 | .run(userId, now), | |
| 24 | ); | |
| 22 | 25 | return before; |
| 23 | 26 | } |
| 24 | 27 |
src/core/migration-pins/20261102120000-cold-home-indexes.pin added +1
| @@ -0,0 +1,1 @@ | ||
| 1 | 6f100057a211ae106d96d29d3e46bdd6afe425297b44c6206bf4135bdf42a434 |
src/core/migrations/20261102120000-cold-home-indexes.ts added +12
| @@ -0,0 +1,12 @@ | ||
| 1 | // The home and a repository page read the whole issue table cold (#7896): | |
| 2 | // the open counts of every repository, the open pulls, the newest comment of | |
| 3 | // every open issue. Each now walks an index and not the table: the counts | |
| 4 | // are answered by `issue_counts` alone, open pulls by a partial index of | |
| 5 | // just them, a time window of pulls by `issue_created`, and an issue's | |
| 6 | // newest comment by its place in `comment_issue_at`. Additive. | |
| 7 | export default ` | |
| 8 | CREATE INDEX issue_counts ON issue(repo_id, state, sealed, kind); | |
| 9 | CREATE INDEX issue_open_pull ON issue(repo_id) WHERE state = 'open' AND kind = 'pull'; | |
| 10 | CREATE INDEX issue_created ON issue(created_at); | |
| 11 | CREATE INDEX comment_issue_at ON comment(issue_id, created_at, id); | |
| 12 | `; |
src/core/route_timing.ts +3 −2
| @@ -20,6 +20,7 @@ | ||
| 20 | 20 | |
| 21 | 21 | import type { Database } from "bun:sqlite"; |
| 22 | 22 | import { withoutWaiting } from "../kernel/db.ts"; |
| 23 | import { quietly } from "./write_clock.ts"; | |
| 23 | 24 | |
| 24 | 25 | /** Upper edges in ms; bucket `i` holds durations `<= EDGES_MS[i]`, the last is everything slower. */ |
| 25 | 26 | export const EDGES_MS = [1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 2500] as const; |
| @@ -129,7 +130,7 @@ export function createRouteTiming( | ||
| 129 | 130 | ); |
| 130 | 131 | const hourNo = Math.floor(now() / HOUR_MS); |
| 131 | 132 | // Behind another process's lock this throws at once and the records go back (#6957). |
| 132 | withoutWaiting(db, db.transaction(() => { | |
| 133 | withoutWaiting(db, db.transaction(() => quietly(db, () => { | |
| 133 | 134 | for (const [key, v] of batch) { |
| 134 | 135 | const [h, pattern, b] = key.split(SEP) as [string, string, string]; |
| 135 | 136 | upsert.run(hourText(Number(h)), pattern, Number(b), v.n, v.us); |
| @@ -140,7 +141,7 @@ export function createRouteTiming( | ||
| 140 | 141 | ); |
| 141 | 142 | prunedHour = hourNo; |
| 142 | 143 | } |
| 143 | })); | |
| 144 | }))); | |
| 144 | 145 | } catch (err) { |
| 145 | 146 | prunedHour = -1; |
| 146 | 147 | for (const [key, v] of batch) { |
src/core/sessions.ts +6 −3
| @@ -8,6 +8,7 @@ import { sha256 } from "../kernel/hash.ts"; | ||
| 8 | 8 | import { id as newId, secret } from "../kernel/id.ts"; |
| 9 | 9 | import { err, ok, type Result } from "../kernel/result.ts"; |
| 10 | 10 | import { getUserById, isActive, type User } from "./users.ts"; |
| 11 | import { quietly } from "./write_clock.ts"; | |
| 11 | 12 | |
| 12 | 13 | const SESSION_TTL_MS = 30 * 24 * 60 * 60 * 1000; |
| 13 | 14 | /** How stale a session's last-seen time may get before a request moves it. */ |
| @@ -70,9 +71,11 @@ export function sessionOf( | ||
| 70 | 71 | // At most one write a minute per browser, however busy it is. |
| 71 | 72 | const stale = new Date(now.getTime() - SEEN_EVERY_MS).toISOString(); |
| 72 | 73 | if (row.last_seen_at === null || row.last_seen_at < stale) |
| 73 | db.query("UPDATE session SET last_seen_at = ?1 WHERE token_hash = ?2").run( | |
| 74 | now.toISOString(), | |
| 75 | hash, | |
| 74 | quietly(db, () => | |
| 75 | db.query("UPDATE session SET last_seen_at = ?1 WHERE token_hash = ?2").run( | |
| 76 | now.toISOString(), | |
| 77 | hash, | |
| 78 | ), | |
| 76 | 79 | ); |
| 77 | 80 | return ok({ user, id: row.id }); |
| 78 | 81 | } |
src/core/usage_count.ts +3 −2
| @@ -15,6 +15,7 @@ | ||
| 15 | 15 | |
| 16 | 16 | import type { Database } from "bun:sqlite"; |
| 17 | 17 | import { withoutWaiting } from "../kernel/db.ts"; |
| 18 | import { quietly } from "./write_clock.ts"; | |
| 18 | 19 | |
| 19 | 20 | export const ROLES = ["anon", "user", "admin", "agent"] as const; |
| 20 | 21 | export const SURFACES = ["api", "mcp", "web"] as const; |
| @@ -125,14 +126,14 @@ export function createUsageCounter( | ||
| 125 | 126 | DO UPDATE SET n = n + excluded.n`, |
| 126 | 127 | ); |
| 127 | 128 | // Behind another process's lock this throws at once and the counts go back (#6957). |
| 128 | withoutWaiting(db, db.transaction(() => { | |
| 129 | withoutWaiting(db, db.transaction(() => quietly(db, () => { | |
| 129 | 130 | for (const [key, n] of batch) { |
| 130 | 131 | const [hour, pattern, method, status, role, surface] = key.split( |
| 131 | 132 | SEP, |
| 132 | 133 | ) as [string, string, string, string, string, string]; |
| 133 | 134 | upsert.run(hour, pattern, method, status, role, surface, n); |
| 134 | 135 | } |
| 135 | })); | |
| 136 | }))); | |
| 136 | 137 | } catch (err) { |
| 137 | 138 | // Put the counts back so a failed write loses nothing. |
| 138 | 139 | for (const [key, n] of batch) |
src/core/write_clock.ts +27 −1
| @@ -20,6 +20,13 @@ | ||
| 20 | 20 | * `limb_place` writes do not. A coarse clock costs hit rate; a wrong one |
| 21 | 21 | * would cost a stale page. We pay the first. |
| 22 | 22 | * |
| 23 | * Telemetry is not a write the pages can show: route timings, usage counts, | |
| 24 | * flag reads, a session's last-seen time, page vitals, samples. They land | |
| 25 | * on this connection every second or so and would keep every cache cold | |
| 26 | * forever (#7896), so the writers that only record how the forge is used | |
| 27 | * run inside `quietly`, and the stamp does not count their rows. A page | |
| 28 | * that shows telemetry is bounded by its cache's age (30 s), not by the clock. | |
| 29 | * | |
| 23 | 30 | * Inside an open transaction there is no stamp: a rolled-back write leaves |
| 24 | 31 | * `total_changes` where it went, so a value read mid-transaction could |
| 25 | 32 | * outlive the rows it saw. |
| @@ -27,6 +34,25 @@ | ||
| 27 | 34 | |
| 28 | 35 | import type { Database } from "bun:sqlite"; |
| 29 | 36 | |
| 37 | const quiet = new WeakMap<Database, number>(); | |
| 38 | ||
| 39 | const changesOf = (db: Database): number => | |
| 40 | db.query<{ n: number }, []>("SELECT total_changes() AS n").get()?.n ?? 0; | |
| 41 | ||
| 42 | /** | |
| 43 | * Run a telemetry write: the rows it changes (kept or rolled back) are left | |
| 44 | * out of the stamp. Wrap only statements that touch tables no cached page | |
| 45 | * is built from; anything else written inside would go unseen by the caches. | |
| 46 | */ | |
| 47 | export function quietly<T>(db: Database, write: () => T): T { | |
| 48 | const before = changesOf(db); | |
| 49 | try { | |
| 50 | return write(); | |
| 51 | } finally { | |
| 52 | quiet.set(db, (quiet.get(db) ?? 0) + changesOf(db) - before); | |
| 53 | } | |
| 54 | } | |
| 55 | ||
| 30 | 56 | /** The forge's write clock now, or undefined inside a transaction (cache nothing). */ |
| 31 | 57 | export function writeStamp(db: Database): string | undefined { |
| 32 | 58 | if (db.inTransaction) return undefined; |
| @@ -35,5 +61,5 @@ export function writeStamp(db: Database): string | undefined { | ||
| 35 | 61 | "SELECT total_changes() AS n, (SELECT data_version FROM pragma_data_version) AS v", |
| 36 | 62 | ) |
| 37 | 63 | .get(); |
| 38 | return row === null ? undefined : `${row.v}.${row.n}`; | |
| 64 | return row === null ? undefined : `${row.v}.${row.n - (quiet.get(db) ?? 0)}`; | |
| 39 | 65 | } |
src/crew/breaker.ts +4 −6
| @@ -81,12 +81,10 @@ export function breakerParked( | ||
| 81 | 81 | // `at` is when the note was left: what a dismissal of the park is compared with. |
| 82 | 82 | return db |
| 83 | 83 | .query<{ issueId: string; repoId: string; at: string }, string[]>( |
| 84 | `SELECT issueId, repoId, at FROM ( | |
| 85 | SELECT i.id AS issueId, i.repo_id AS repoId, c.body AS body, c.created_at AS at, | |
| 86 | ROW_NUMBER() OVER (PARTITION BY i.id ORDER BY c.created_at DESC, c.id DESC) AS rn | |
| 87 | FROM issue i JOIN comment c ON c.issue_id = i.id | |
| 88 | WHERE i.state = 'open' AND i.repo_id IN (${marks}) | |
| 89 | ) WHERE rn = 1 AND body IN (?${repoIds.length + 1}, ?${repoIds.length + 2})`, | |
| 84 | `SELECT i.id AS issueId, i.repo_id AS repoId, c.created_at AS at | |
| 85 | FROM issue i JOIN comment c ON c.id = (SELECT id FROM comment WHERE issue_id = i.id | |
| 86 | ORDER BY created_at DESC, id DESC LIMIT 1) | |
| 87 | WHERE i.state = 'open' AND i.repo_id IN (${marks}) AND c.body IN (?${repoIds.length + 1}, ?${repoIds.length + 2})`, | |
| 90 | 88 | ) |
| 91 | 89 | .all(...repoIds, ...WAITING_NOTES); |
| 92 | 90 | } |
src/flow/pipeline.ts +5 −3
| @@ -99,11 +99,13 @@ function waitingTally(db: Database, sql: string, ...args: string[]): Tally { | ||
| 99 | 99 | return { waiting: r?.n ?? 0, active: 0, oldest: r?.oldest ?? null }; |
| 100 | 100 | } |
| 101 | 101 | |
| 102 | // CROSS JOIN keeps SQLite's order: the ask's runs, their branch's pulls by | |
| 103 | // `pull_head_branch`, then each pull's issue, never every open issue (#3693). | |
| 102 | // CROSS JOIN keeps SQLite's order: the repositories that run themselves, then | |
| 103 | // their open issues by `issue_repo_kind_state_number`, never every issue | |
| 104 | // (#7896); and the ask's runs, their branch's pulls by `pull_head_branch`, | |
| 105 | // then each pull's issue, never every open issue (#3693). | |
| 104 | 106 | const READY = ` |
| 105 | 107 | SELECT i.created_at AS since |
| 106 | FROM issue i JOIN repo r ON r.id = i.repo_id | |
| 108 | FROM repo r CROSS JOIN issue i ON i.repo_id = r.id | |
| 107 | 109 | WHERE i.kind = 'issue' AND i.state = 'open' AND r.autonomy != 'off' |
| 108 | 110 | AND (r.direction_issue_id IS NULL OR r.direction_issue_id != i.id) |
| 109 | 111 | AND NOT EXISTS (SELECT 1 FROM issue_dependency d JOIN issue b ON b.id = d.blocked_by_id |
src/flow/vitals.ts +1 −1
| @@ -71,7 +71,7 @@ export function readVitals(db: Database, now = new Date(), publicOnly = false): | ||
| 71 | 71 | .query<Omit<Vitals, "conflicted" | "red" | "queued" | "oldestApprovedHours" | "strandedUsd" | "gateMinutes1h" | "pullCheckMinutes1h" | "batches6h" | "redBatchRate">, [string, string, string, number]>( |
| 72 | 72 | `SELECT |
| 73 | 73 | (SELECT COUNT(*) FROM pull p JOIN issue i ON i.id = p.issue_id JOIN repo r ON r.id = i.repo_id |
| 74 | WHERE (?4 = 0 OR r.visibility = 'public') AND i.state = 'open' AND p.merged_at IS NULL) AS open, | |
| 74 | WHERE (?4 = 0 OR r.visibility = 'public') AND i.kind = 'pull' AND i.state = 'open' AND p.merged_at IS NULL) AS open, | |
Query semantics change ( |
||
| 75 | 75 | (SELECT COUNT(*) FROM pull p JOIN issue i ON i.id = p.issue_id JOIN repo r ON r.id = i.repo_id |
| 76 | 76 | WHERE (?4 = 0 OR r.visibility = 'public') AND i.created_at >= ?1 AND i.created_at <= ?3) AS opened1h, |
| 77 | 77 | (SELECT COUNT(*) FROM pull p JOIN issue i ON i.id = p.issue_id JOIN repo r ON r.id = i.repo_id |
src/web/measure.ts +11 −6
| @@ -13,6 +13,7 @@ | ||
| 13 | 13 | */ |
| 14 | 14 | |
| 15 | 15 | import type { Database } from "bun:sqlite"; |
| 16 | import { quietly } from "../core/write_clock.ts"; | |
| 16 | 17 | import { sha256 } from "../kernel/hash.ts"; |
| 17 | 18 | |
| 18 | 19 | /** A report is a few dozen bytes; this is already generous. */ |
| @@ -99,9 +100,11 @@ export function saltFor(db: Database, at: number): string { | ||
| 99 | 100 | const salt = new Bun.CryptoHasher("sha256") |
| 100 | 101 | .update(crypto.getRandomValues(new Uint8Array(32))) |
| 101 | 102 | .digest("hex"); |
| 102 | db.run("DELETE FROM vital_salt WHERE day <> ?", [day]); | |
| 103 | db.run("INSERT OR IGNORE INTO vital_salt (day, salt) VALUES (?, ?)", [day, salt]); | |
| 104 | db.run("DELETE FROM page_vital WHERE at < ?", [at - KEEP_MS]); | |
| 103 | quietly(db, () => { | |
| 104 | db.run("DELETE FROM vital_salt WHERE day <> ?", [day]); | |
| 105 | db.run("INSERT OR IGNORE INTO vital_salt (day, salt) VALUES (?, ?)", [day, salt]); | |
| 106 | db.run("DELETE FROM page_vital WHERE at < ?", [at - KEEP_MS]); | |
| 107 | }); | |
| 105 | 108 | return ( |
| 106 | 109 | db |
| 107 | 110 | .query<{ salt: string }, [string]>("SELECT salt FROM vital_salt WHERE day = ?") |
| @@ -127,9 +130,11 @@ export function recordVital( | ||
| 127 | 130 | .get(dayOf(at)); |
| 128 | 131 | if ((held?.n ?? 0) >= dayMax) return false; |
| 129 | 132 | const visitor = sha256(`${saltFor(db, at)}\0${client}\0${agent}`).slice(0, 32); |
| 130 | db.run( | |
| 131 | "INSERT INTO page_vital (day, at, route, visitor, ttfb, load, lcp, inp, cls) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)", | |
| 132 | [dayOf(at), at, route, visitor, report.ttfb, report.load, report.lcp, report.inp, report.cls], | |
| 133 | quietly(db, () => | |
| 134 | db.run( | |
| 135 | "INSERT INTO page_vital (day, at, route, visitor, ttfb, load, lcp, inp, cls) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)", | |
| 136 | [dayOf(at), at, route, visitor, report.ttfb, report.load, report.lcp, report.inp, report.cls], | |
| 137 | ), | |
| 133 | 138 | ); |
| 134 | 139 | return true; |
| 135 | 140 | } |
test/cold-home-queries.test.ts added +97
| @@ -0,0 +1,97 @@ | ||
| 1 | /** | |
| 2 | * The three queries #7896 rewrote for the indexes answer what the ones they | |
| 3 | * replaced did, on rows built to tell them apart: a note that parks an issue, | |
| 4 | * one that is not the newest, an open issue that is not a pull. | |
| 5 | */ | |
| 6 | import { afterAll, beforeAll, expect, test } from "bun:test"; | |
| 7 | import { breakerParked, WAITING_NOTES } from "../src/crew/breaker.ts"; | |
| 8 | import { readPipeline } from "../src/flow/pipeline.ts"; | |
| 9 | import { readVitals } from "../src/flow/vitals.ts"; | |
| 10 | import { id } from "../src/kernel/id.ts"; | |
| 11 | import { snappyFixture, type SnappyFixture } from "../bench/snappy.ts"; | |
| 12 | ||
| 13 | let f: SnappyFixture; | |
| 14 | let repoId: string; | |
| 15 | beforeAll(async () => { | |
| 16 | f = await snappyFixture({ repos: 2, issuesPerRepo: 3 }); | |
| 17 | repoId = f.app.db.query<{ id: string }, []>("SELECT id FROM repo LIMIT 1").get()!.id; | |
| 18 | }, 60_000); | |
| 19 | afterAll(async () => { | |
| 20 | await f.close(); | |
| 21 | }); | |
| 22 | ||
| 23 | const issue = (kind: string, state: string, n: number): string => { | |
| 24 | const i = id(); | |
| 25 | f.app.db | |
| 26 | .query("INSERT INTO issue (id, repo_id, number, kind, title, body, author_id, state, created_at) VALUES (?1, ?2, ?3, ?4, 't', '', ?5, ?6, ?7)") | |
| 27 | .run(i, repoId, n, kind, f.owner.id, state, new Date().toISOString()); | |
| 28 | return i; | |
| 29 | }; | |
| 30 | const note = (issueId: string, body: string, at: string) => | |
| 31 | f.app.db | |
| 32 | .query("INSERT INTO comment (id, issue_id, author_id, body, created_at) VALUES (?1, ?2, ?3, ?4, ?5)") | |
| 33 | .run(id(), issueId, f.owner.id, body, at); | |
| 34 | ||
| 35 | test("breakerParked: parked by its newest note only, open only", () => { | |
| 36 | const parked = issue("issue", "open", 9001); | |
| 37 | note(parked, "hello", "2026-01-01T00:00:00.000Z"); | |
| 38 | note(parked, WAITING_NOTES[0], "2026-01-02T00:00:00.000Z"); | |
| 39 | const spoken = issue("issue", "open", 9002); | |
| 40 | note(spoken, WAITING_NOTES[0], "2026-01-01T00:00:00.000Z"); | |
| 41 | note(spoken, "a person spoke", "2026-01-02T00:00:00.000Z"); | |
| 42 | const closed = issue("issue", "closed", 9003); | |
| 43 | note(closed, WAITING_NOTES[1], "2026-01-01T00:00:00.000Z"); | |
| 44 | ||
| 45 | const old = f.app.db | |
| 46 | .query<{ issueId: string; repoId: string; at: string }, string[]>( | |
| 47 | `SELECT issueId, repoId, at FROM ( | |
| 48 | SELECT i.id AS issueId, i.repo_id AS repoId, c.body AS body, c.created_at AS at, | |
| 49 | ROW_NUMBER() OVER (PARTITION BY i.id ORDER BY c.created_at DESC, c.id DESC) AS rn | |
| 50 | FROM issue i JOIN comment c ON c.issue_id = i.id | |
| 51 | WHERE i.state = 'open' AND i.repo_id IN (?1) | |
| 52 | ) WHERE rn = 1 AND body IN (?2, ?3)`, | |
| 53 | ) | |
| 54 | .all(repoId, ...WAITING_NOTES); | |
| 55 | const now = breakerParked(f.app.db, [repoId]); | |
| 56 | expect(now).toEqual(old); | |
| 57 | expect(now.map((r) => r.issueId)).toEqual([parked]); | |
| 58 | }); | |
| 59 | ||
| 60 | test("open pulls: an open issue that is not a pull is not counted, as before", () => { | |
| 61 | const db = f.app.db; | |
| 62 | const count = () => readVitals(db).open; | |
| 63 | const before = count(); | |
| 64 | issue("issue", "open", 9101); | |
| 65 | expect(count()).toBe(before); | |
| 66 | const pull = issue("pull", "open", 9102); | |
| 67 | db.query("INSERT INTO pull (issue_id, base_branch, head_branch, base_oid, head_oid, head_repo_id) VALUES (?1, 'main', 'b', '', '', ?2)").run(pull, repoId); | |
| 68 | expect(count()).toBe(before + 1); | |
| 69 | const old = db | |
| 70 | .query<{ n: number }, []>( | |
| 71 | `SELECT COUNT(*) AS n FROM pull p JOIN issue i ON i.id = p.issue_id JOIN repo r ON r.id = i.repo_id | |
| 72 | WHERE i.state = 'open' AND p.merged_at IS NULL`, | |
| 73 | ) | |
| 74 | .get()!.n; | |
| 75 | expect(count()).toBe(old); | |
| 76 | }); | |
| 77 | ||
| 78 | test("ready asks: the tally is the old join's, counted by hand", () => { | |
| 79 | const db = f.app.db; | |
| 80 | db.query("UPDATE repo SET autonomy = 'on'").run(); | |
| 81 | const ready = () => readPipeline(db).find((s) => s.key === "ready")!.waiting; | |
| 82 | const old = db | |
| 83 | .query<{ n: number }, []>( | |
| 84 | `SELECT COUNT(*) AS n FROM issue i JOIN repo r ON r.id = i.repo_id | |
| 85 | WHERE i.kind = 'issue' AND i.state = 'open' AND r.autonomy != 'off' | |
| 86 | AND (r.direction_issue_id IS NULL OR r.direction_issue_id != i.id) | |
| 87 | AND NOT EXISTS (SELECT 1 FROM issue_dependency d JOIN issue b ON b.id = d.blocked_by_id | |
| 88 | WHERE d.issue_id = i.id AND b.state = 'open') | |
| 89 | AND NOT EXISTS (SELECT 1 FROM run x WHERE x.issue_id = i.id AND x.kind = 'agent' | |
| 90 | AND x.state IN ('queued','running'))`, | |
| 91 | ) | |
| 92 | .get()!.n; | |
| 93 | expect(old).toBeGreaterThan(0); | |
| 94 | expect(ready()).toBe(old); | |
| 95 | db.query("UPDATE repo SET autonomy = 'off'").run(); | |
| 96 | expect(ready()).toBe(0); | |
| 97 | }); |
test/write-clock-quiet.test.ts added +135
| @@ -0,0 +1,135 @@ | ||
| 1 | /** | |
| 2 | * Telemetry does not keep the caches cold (#7896): the rows a route timing, | |
| 3 | * a usage count, a flag read, a session's last-seen time, a home visit or a | |
| 4 | * page vital writes are left out of the write clock, while any other write | |
| 5 | * still moves it. And so a home read after a second of traffic is a hit. | |
| 6 | */ | |
| 7 | import { afterAll, beforeAll, expect, test } from "bun:test"; | |
| 8 | import { Database } from "bun:sqlite"; | |
| 9 | import { createUsageCounter } from "../src/core/usage_count.ts"; | |
| 10 | import { makeFlags } from "../src/core/flags.ts"; | |
| 11 | import { sessionOf, createSession } from "../src/core/sessions.ts"; | |
| 12 | import { recordMemory } from "../src/boards/memory.ts"; | |
| 13 | import { record as recordRing } from "../src/boards/ring.ts"; | |
| 14 | import { createRouteTiming } from "../src/core/route_timing.ts"; | |
| 15 | import { noteVisit } from "../src/core/home_visit.ts"; | |
| 16 | import { quietly, writeStamp } from "../src/core/write_clock.ts"; | |
| 17 | import { recordVital } from "../src/web/measure.ts"; | |
| 18 | import { kpiCache } from "../src/web/studio/home_cache.ts"; | |
| 19 | import { snappyFixture, type SnappyFixture } from "../bench/snappy.ts"; | |
| 20 | ||
| 21 | test("a quiet write leaves the stamp; a loud one moves it", () => { | |
| 22 | const db = new Database(":memory:"); | |
| 23 | db.run("CREATE TABLE t (n INTEGER)"); | |
| 24 | const before = writeStamp(db); | |
| 25 | quietly(db, () => db.run("INSERT INTO t VALUES (1)")); | |
| 26 | expect(writeStamp(db)).toBe(before); | |
| 27 | db.run("INSERT INTO t VALUES (2)"); | |
| 28 | expect(writeStamp(db)).not.toBe(before); | |
| 29 | }); | |
| 30 | ||
| 31 | test("a quiet write that rolls back is still left out", () => { | |
| 32 | const db = new Database(":memory:"); | |
| 33 | db.run("CREATE TABLE t (n INTEGER)"); | |
| 34 | const before = writeStamp(db); | |
| 35 | expect(() => | |
| 36 | db.transaction(() => { | |
| 37 | quietly(db, () => db.run("INSERT INTO t VALUES (1)")); | |
| 38 | throw new Error("no"); | |
| 39 | })(), | |
| 40 | ).toThrow(); | |
| 41 | expect(writeStamp(db)).toBe(before); | |
| 42 | }); | |
| 43 | ||
| 44 | let f: SnappyFixture; | |
| 45 | beforeAll(async () => { | |
| 46 | f = await snappyFixture({ repos: 2, issuesPerRepo: 2 }); | |
| 47 | }, 60_000); | |
| 48 | afterAll(async () => { | |
| 49 | await f.close(); | |
| 50 | }); | |
| 51 | ||
| 52 | /** Every row of every table, so a writer's footprint can be named. */ | |
| 53 | function dump(db: Database): Map<string, string> { | |
| 54 | const out = new Map<string, string>(); | |
| 55 | const names = db | |
| 56 | .query<{ name: string }, []>("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%'") | |
| 57 | .all(); | |
| 58 | for (const { name } of names) out.set(name, JSON.stringify(db.query(`SELECT * FROM "${name}"`).all())); | |
| 59 | return out; | |
| 60 | } | |
| 61 | ||
| 62 | /** The tables no cached page is built from: the only ones a quiet writer may touch. */ | |
| 63 | const TELEMETRY = new Set([ | |
outdated
Sleeping 1.3 s makes the test slow and timing-dependent; flush the timings directly instead (item 4). |
||
| 64 | "route_timing", "usage_count", "flag_use", "session", "home_visit", | |
| 65 | "page_vital", "vital_salt", "memory_hour", "machine_sample", | |
| 66 | ]); | |
| 67 | ||
| 68 | const flags = makeFlags({ probe: { why: "test", default: false, issue: 7896 } }); | |
| 69 | ||
| 70 | const writers: Record<string, () => void> = { | |
| 71 | "route timing": () => { | |
| 72 | const t = createRouteTiming(f.app.db); | |
| 73 | t.record("GET /probe", 3); | |
| 74 | t.flush(); | |
| 75 | t.stop(); | |
| 76 | }, | |
| 77 | "usage count": () => { | |
| 78 | const c = createUsageCounter(f.app.db); | |
| 79 | c.count({ pattern: "GET /probe", method: "GET", status: 200, role: "anon", surface: "web" }); | |
| 80 | c.flush(); | |
| 81 | c.stop(); | |
| 82 | }, | |
| 83 | "flag read": () => { | |
| 84 | flags.flag("probe"); | |
| 85 | flags.flush(f.app.db); | |
| 86 | }, | |
| 87 | "session last-seen": () => { | |
| 88 | const { token } = createSession(f.app.db, f.owner.id); | |
| 89 | f.app.db.query("UPDATE session SET last_seen_at = NULL").run(); | |
| 90 | stampBase = writeStamp(f.app.db); | |
| 91 | expect(sessionOf(f.app.db, token).ok).toBe(true); | |
| 92 | }, | |
| 93 | "home visit": () => void noteVisit(f.app.db, f.owner.id, Date.now() + 3_600_000), | |
| 94 | "page vital": () => void recordVital(f.app.db, { path: "/", ttfb: 1, load: 2, lcp: 3, inp: 4, cls: 0 }, "/", "client", "agent"), | |
| 95 | "memory sample": () => recordMemory(f.app.db, 1e8, 5e7, Date.now()), | |
| 96 | "machine sample": () => | |
| 97 | recordRing(f.app.db, [{ at: Date.now(), target: "forge", cpuCores: 1, memoryBytes: 1e8, load: 0.5 }], Date.now()), | |
| 98 | }; | |
| 99 | let stampBase: string | undefined; | |
| 100 | ||
| 101 | for (const [name, write] of Object.entries(writers)) | |
| 102 | test(`the ${name} write leaves the clock, and touches only telemetry tables`, () => { | |
| 103 | const db = f.app.db; | |
| 104 | stampBase = writeStamp(db); | |
| 105 | const before = dump(db); | |
| 106 | write(); | |
| 107 | const after = dump(db); | |
| 108 | const touched = [...after].filter(([t, rows]) => before.get(t) !== rows).map(([t]) => t); | |
| 109 | expect(touched.length).toBeGreaterThan(0); | |
| 110 | for (const t of touched) expect(TELEMETRY.has(t)).toBe(true); | |
| 111 | expect(writeStamp(db)).toBe(stampBase); | |
| 112 | }); | |
| 113 | ||
| 114 | test("a loud write still moves the clock", () => { | |
| 115 | const db = f.app.db; | |
| 116 | const before = writeStamp(db); | |
| 117 | db.query("INSERT INTO forge_setting (key, value, updated_by, updated_at) VALUES ('probe', '1', ?1, 'x')").run(f.owner.id); | |
| 118 | expect(writeStamp(db)).not.toBe(before); | |
| 119 | }); | |
| 120 | ||
| 121 | test("a home read after telemetry flushed is a cache hit", async () => { | |
| 122 | await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } }).then((r) => r.text()); | |
| 123 | const kpi = kpiCache(f.app.db); | |
| 124 | const misses = kpi.misses; | |
| 125 | writers["route timing"]!(); | |
| 126 | writers["page vital"]!(); | |
| 127 | await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } }).then((r) => r.text()); | |
| 128 | expect(kpi.misses).toBe(misses); | |
| 129 | }); | |
| 130 | ||
| 131 | test("the home's since-your-last-visit is read outside every cache", async () => { | |
| 132 | const src = await Bun.file(new URL("../src/web/studio/home_cache.ts", import.meta.url)).text(); | |
| 133 | expect(src).not.toContain("home_visit"); | |
| 134 | expect(src).not.toContain("lastVisit"); | |
| 135 | }); |
new above
offline
Module-level WeakMap of quiet counts is unguarded: a loud write inside
write()is silently subtracted. Add a test/guard (item 5).