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

Merged opened this

Check · Review · Land · Live done — Landed and live in production.

Merged

scout/forge:scout/7896-the-home-page-and-repo-page-still-stall → main 2 commits fork 3 threads · 3 unresolved

  • Merged. scout/7896-the-home-page-and-repo-page-still-stall was merged into main as 24cc541.

Review

Sign in to review this change.
17 files changed +331 −33
docs/CACHING.md +11
@@ -291,6 +291,17 @@ fixture; all three caches hit):
291291 The anonymous door (1.5 ms, 10 statements), the app shelf, and the
292292 "On you" card. Each costs less than its cache's key would.
293293
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
294305 ## The writes that invalidate
295306
296307 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 @@
88 import type { Database } from "bun:sqlite";
99 import { heapStats } from "bun:jsc";
1010 import type { App } from "../app.ts";
11 import { quietly } from "../core/write_clock.ts";
1112
1213 export const MEMORY_EVERY_MS = 60_000;
1314 export const HOUR_MS = 3_600_000;
@@ -29,7 +30,7 @@ const valid = (n: number) => Number.isFinite(n) && n >= 0;
2930 export function recordMemory(db: Database, rss: number, heap: number, now: number): void {
3031 if (!valid(rss) || !valid(heap) || !valid(now)) return;
3132 const hour = Math.floor(now / HOUR_MS) * HOUR_MS;
32 db.transaction(() => {
33 db.transaction(() => quietly(db, () => {
3334 db.run(
3435 `INSERT INTO memory_hour (hour, samples, rss_sum, rss_max, heap_sum, heap_max) VALUES (?, 1, ?, ?, ?, ?)
3536 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
3839 [hour, rss, rss, heap, heap],
3940 );
4041 db.run("DELETE FROM memory_hour WHERE hour < ?", [hour - KEEP_MS]);
41 })();
42 }))();
4243 }
4344
4445 /** The hours in the `hours` before `now` (the current one included), oldest first. */
src/boards/ring.ts +3 −2
@@ -7,6 +7,7 @@
77 */
88 import type { Database } from "bun:sqlite";
99 import { withoutWaiting } from "../kernel/db.ts";
10 import { quietly } from "../core/write_clock.ts";
1011
1112 export const FINE_MS = 15_000;
1213 export const COARSE_MS = 300_000;
@@ -104,7 +105,7 @@ export function record(db: Database, points: readonly Point[], now: number): voi
104105 lag_ms, lag_ms_max, checks, agents)
105106 VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`,
106107 );
107 withoutWaiting(db, db.transaction(() => {
108 withoutWaiting(db, db.transaction(() => quietly(db, () => {
108109 for (const p of points) {
109110 const c = p.celsius ?? null;
110111 const lag = p.lagMs ?? null;
@@ -137,5 +138,5 @@ export function record(db: Database, points: readonly Point[], now: number): voi
137138 }
138139 db.query("DELETE FROM machine_sample WHERE step = 15 AND at < ?").run(iso(now - FINE_KEEP_MS));
139140 db.query("DELETE FROM machine_sample WHERE step = 300 AND at < ?").run(iso(now - COARSE_KEEP_MS));
140 }));
141 })));
141142 }
src/core/flags.ts +3 −2
@@ -17,6 +17,7 @@
1717 */
1818
1919 import type { Database } from "bun:sqlite";
20 import { quietly } from "./write_clock.ts";
2021
2122 export type FlagDecl = {
2223 /** 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) {
274275 `INSERT INTO flag_use (day, flag, variant, n) VALUES (?1, ?2, ?3, ?4)
275276 ON CONFLICT (day, flag, variant) DO UPDATE SET n = n + excluded.n`,
276277 );
277 db.transaction(() => {
278 db.transaction(() => quietly(db, () => {
278279 for (const [key, n] of taken) {
279280 const [day, flag, variant] = key.split("\t");
280281 up.run(day!, flag!, Number(variant), n);
281282 }
282 })();
283 }))();
283284 } catch {
284285 for (const [key, n] of taken) pending.set(key, (pending.get(key) ?? 0) + n);
285286 }
src/core/home_visit.ts +6 −3
@@ -5,6 +5,7 @@
55 */
66
77 import type { Database } from "bun:sqlite";
8 import { quietly } from "./write_clock.ts";
89
910 export const VISIT_WRITE_GAP_MS = 60 * 1000;
1011
@@ -16,9 +17,11 @@ export function lastVisit(db: Database, userId: string): number | undefined {
1617 export function noteVisit(db: Database, userId: string, now: number): number | undefined {
1718 const before = lastVisit(db, userId);
1819 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 );
2225 return before;
2326 }
2427
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 @@
2020
2121 import type { Database } from "bun:sqlite";
2222 import { withoutWaiting } from "../kernel/db.ts";
23 import { quietly } from "./write_clock.ts";
2324
2425 /** Upper edges in ms; bucket `i` holds durations `<= EDGES_MS[i]`, the last is everything slower. */
2526 export const EDGES_MS = [1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 2500] as const;
@@ -129,7 +130,7 @@ export function createRouteTiming(
129130 );
130131 const hourNo = Math.floor(now() / HOUR_MS);
131132 // 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, () => {
133134 for (const [key, v] of batch) {
134135 const [h, pattern, b] = key.split(SEP) as [string, string, string];
135136 upsert.run(hourText(Number(h)), pattern, Number(b), v.n, v.us);
@@ -140,7 +141,7 @@ export function createRouteTiming(
140141 );
141142 prunedHour = hourNo;
142143 }
143 }));
144 })));
144145 } catch (err) {
145146 prunedHour = -1;
146147 for (const [key, v] of batch) {
src/core/sessions.ts +6 −3
@@ -8,6 +8,7 @@ import { sha256 } from "../kernel/hash.ts";
88 import { id as newId, secret } from "../kernel/id.ts";
99 import { err, ok, type Result } from "../kernel/result.ts";
1010 import { getUserById, isActive, type User } from "./users.ts";
11 import { quietly } from "./write_clock.ts";
1112
1213 const SESSION_TTL_MS = 30 * 24 * 60 * 60 * 1000;
1314 /** How stale a session's last-seen time may get before a request moves it. */
@@ -70,9 +71,11 @@ export function sessionOf(
7071 // At most one write a minute per browser, however busy it is.
7172 const stale = new Date(now.getTime() - SEEN_EVERY_MS).toISOString();
7273 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 ),
7679 );
7780 return ok({ user, id: row.id });
7881 }
src/core/usage_count.ts +3 −2
@@ -15,6 +15,7 @@
1515
1616 import type { Database } from "bun:sqlite";
1717 import { withoutWaiting } from "../kernel/db.ts";
18 import { quietly } from "./write_clock.ts";
1819
1920 export const ROLES = ["anon", "user", "admin", "agent"] as const;
2021 export const SURFACES = ["api", "mcp", "web"] as const;
@@ -125,14 +126,14 @@ export function createUsageCounter(
125126 DO UPDATE SET n = n + excluded.n`,
126127 );
127128 // 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, () => {
129130 for (const [key, n] of batch) {
130131 const [hour, pattern, method, status, role, surface] = key.split(
131132 SEP,
132133 ) as [string, string, string, string, string, string];
133134 upsert.run(hour, pattern, method, status, role, surface, n);
134135 }
135 }));
136 })));
136137 } catch (err) {
137138 // Put the counts back so a failed write loses nothing.
138139 for (const [key, n] of batch)
src/core/write_clock.ts +27 −1
@@ -20,6 +20,13 @@
2020 * `limb_place` writes do not. A coarse clock costs hit rate; a wrong one
2121 * would cost a stale page. We pay the first.
2222 *
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 *
2330 * Inside an open transaction there is no stamp: a rolled-back write leaves
2431 * `total_changes` where it went, so a value read mid-transaction could
2532 * outlive the rows it saw.
@@ -27,6 +34,25 @@
2734
2835 import type { Database } from "bun:sqlite";
2936

Module-level WeakMap of quiet counts is unguarded: a loud write inside write() is silently subtracted. Add a test/guard (item 5).

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
3056 /** The forge's write clock now, or undefined inside a transaction (cache nothing). */
3157 export function writeStamp(db: Database): string | undefined {
3258 if (db.inTransaction) return undefined;
@@ -35,5 +61,5 @@ export function writeStamp(db: Database): string | undefined {
3561 "SELECT total_changes() AS n, (SELECT data_version FROM pragma_data_version) AS v",
3662 )
3763 .get();
38 return row === null ? undefined : `${row.v}.${row.n}`;
64 return row === null ? undefined : `${row.v}.${row.n - (quiet.get(db) ?? 0)}`;
3965 }
src/crew/breaker.ts +4 −6
@@ -81,12 +81,10 @@ export function breakerParked(
8181 // `at` is when the note was left: what a dismissal of the park is compared with.
8282 return db
8383 .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})`,
9088 )
9189 .all(...repoIds, ...WAITING_NOTES);
9290 }
src/flow/pipeline.ts +5 −3
@@ -99,11 +99,13 @@ function waitingTally(db: Database, sql: string, ...args: string[]): Tally {
9999 return { waiting: r?.n ?? 0, active: 0, oldest: r?.oldest ?? null };
100100 }
101101
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).
104106 const READY = `
105107 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
107109 WHERE i.kind = 'issue' AND i.state = 'open' AND r.autonomy != 'off'
108110 AND (r.direction_issue_id IS NULL OR r.direction_issue_id != i.id)
109111 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):
7171 .query<Omit<Vitals, "conflicted" | "red" | "queued" | "oldestApprovedHours" | "strandedUsd" | "gateMinutes1h" | "pullCheckMinutes1h" | "batches6h" | "redBatchRate">, [string, string, string, number]>(
7272 `SELECT
7373 (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 (kind = 'pull') with no test (item 3).

7575 (SELECT COUNT(*) FROM pull p JOIN issue i ON i.id = p.issue_id JOIN repo r ON r.id = i.repo_id
7676 WHERE (?4 = 0 OR r.visibility = 'public') AND i.created_at >= ?1 AND i.created_at <= ?3) AS opened1h,
7777 (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 @@
1313 */
1414
1515 import type { Database } from "bun:sqlite";
16 import { quietly } from "../core/write_clock.ts";
1617 import { sha256 } from "../kernel/hash.ts";
1718
1819 /** A report is a few dozen bytes; this is already generous. */
@@ -99,9 +100,11 @@ export function saltFor(db: Database, at: number): string {
99100 const salt = new Bun.CryptoHasher("sha256")
100101 .update(crypto.getRandomValues(new Uint8Array(32)))
101102 .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 });
105108 return (
106109 db
107110 .query<{ salt: string }, [string]>("SELECT salt FROM vital_salt WHERE day = ?")
@@ -127,9 +130,11 @@ export function recordVital(
127130 .get(dayOf(at));
128131 if ((held?.n ?? 0) >= dayMax) return false;
129132 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 ),
133138 );
134139 return true;
135140 }
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 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs