trevato/forge

Public: anyone can read this; the crew can change it.

More
Forks1g fMapg aRuns18g rEventsFlows

Past 60 s, home still answers from the last KPI answer while one refresh runs off the request path #7952

Merged masoncrew opened this

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

ConversationFiles
Merged

mason/forge:mason/7625-past-60-s-home-still-answers-from-the-la → main 5 commits fork

  • Merged. mason/7625-past-60-s-home-still-answers-from-the-la was merged into main as 12634a4.

Review

Sign in to review this change.
5 files changed +269 −35
docs/CACHING.md +14 −6
@@ -522,12 +522,20 @@ The KPI entry is keyed by UTC hour, ceiling and data directory; a panel by
522522 its board's slug and its own definition (an edited board is a new key, as
523523 the blob id would make it). The 60 s rule (#7624): the KPIs, panels and
524524 vitals are kept 60 s from when they were computed, whatever is written
525 since (the forge writes every second, so the write stamp never hit); the
526 waiting line stays on the write stamp, 30 s at most, so the asks count is
527 exact. The builders figure is read fresh on every request (one query), so it
528 agrees with the idle reason beside it; the terminal's dashboard reads
529 `readKpis` uncached. Tests age these entries with `setHomeClock`, the one
530 test seam in `home_cache.ts`. Measured on
525 since (the forge writes every second, so the write stamp never hit). Past
526 60 s the old answer is still served at once, counted a hit, and one refresh
527 per key runs with `setTimeout(0)` after the response (#7625). A refresh that
528 throws is logged (`home.refresh_failed`), keeps the old answer and frees the
529 key for the next request. Only a cold start, or an answer past the 10 min
530 ceiling (`HOME_STALE_CEILING_MS`, ten TTLs), computes inline, so refreshes
531 that keep failing cannot pin an old answer forever. The refresh is off the
532 request, not off the event loop: it runs on the same thread, so a request
533 that lands while it runs waits for it, as it would have waited for an
534 inline recompute. The waiting line stays on the write stamp, 30 s at most,
535 so the asks count is exact. The builders figure is read fresh on every
536 request (one query), so it agrees with the idle reason beside it; the
537 terminal's dashboard reads `readKpis` uncached. Tests age these entries
538 with `setHomeClock`, the one test seam in `home_cache.ts`. Measured on
531539 `bench/snappy.ts` (`--n 50`), `/` owner: 105.7 → 90.1 statements, p50
532540 16.0 → 15.5 ms, p95 22.5 → 20.7 ms; the fixture pins no panel, and a pin
533541 adds one query per panel on a miss and none on a hit.
src/kernel/stamped.ts +16 −2
@@ -54,14 +54,28 @@ export class Stamped<V> {
5454 }
5555 this.misses++;
5656 const value = compute();
57 this.store(key, stamp, value, now);
58 return value;
59 }
60
61 /** The entry for `key` as stored, however old: for a caller that serves stale while it refreshes. Counts nothing. */
62 peek(key: string): { readonly stamp: string; readonly value: V; readonly at: number } | undefined {
63 return this.entries.get(key);
64 }
65
66 /** Store `value` for `key` under `stamp`, computed now: what a refresh off the request path lands. */
67 put(key: string, stamp: string, value: V): void {
68 this.store(key, stamp, value, this.now());
69 }
70
71 private store(key: string, stamp: string, value: V, at: number): void {
5772 this.entries.delete(key);
58 this.entries.set(key, { stamp, value, at: now });
73 this.entries.set(key, { stamp, value, at });
5974 while (this.entries.size > this.options.maxEntries) {
6075 const oldest = this.entries.keys().next().value;
6176 if (oldest === undefined) break;
6277 this.entries.delete(oldest);
6378 }
64 return value;
6579 }
6680
6781 get size(): number {
src/web/studio/home_cache.ts +80 −16
@@ -5,22 +5,32 @@
55 * `viewer.isAdmin`, never before, because the figures add up private
66 * repositories. The KPIs, panels and vitals are kept 60 seconds from when
77 * they were computed, whatever is written since (#7624): the forge writes
8 * every second, so a write-stamped entry never hit. The builders figure is
9 * the exception: it is read fresh on every request, so it always agrees with
10 * the idle reason home prints beside it. The waiting line stays on the write
11 * clock: the asks count must be exact.
8 * every second, so a write-stamped entry never hit. Past 60 s the old answer
9 * is still served at once, and one refresh per key runs after the response
10 * (#7625); only a cold start, or an answer past the 10 min ceiling, computes
11 * inline. The builders figure is the exception: it is read fresh on every
12 * request, so it always agrees with the idle reason home prints beside it.
13 * The waiting line stays on the write clock: the asks count must be exact.
1214 */
1315 import type { Database } from "bun:sqlite";
1416 import type { Answer } from "../../boards/query.ts";
1517 import { writeStamp } from "../../core/write_clock.ts";
1618 import { readBuilders, readKpis, type KpiTimer, type Kpis } from "../../flow/kpis.ts";
1719 import { readVitals, type Vitals } from "../../flow/vitals.ts";
20 import { createLog } from "../../kernel/log.ts";
1821 import { Stamped } from "../../kernel/stamped.ts";
1922
23 const log = createLog("home");
24
2025 /** The backstop of home's write-stamped caches only (the waiting line, `alarm_lines.ts`): kept while the write clock holds, 30 s at most. Not the 60 s TTL below. */
2126 export const HOME_MAX_AGE_MS = 30_000;
2227 /** How long a KPI, panel or vitals answer is served again, writes or not. */
2328 export const HOME_TTL_MS = 60_000;
29 /**
30 * Past this age a stale answer is not served: the request computes inline,
31 * so refreshes that keep failing cannot pin an old answer forever.
32 */
33 export const HOME_STALE_CEILING_MS = 10 * HOME_TTL_MS;
2434 /** The one stamp the TTL caches use: only age invalidates them. */
2535 const TTL = "ttl";
2636
@@ -67,6 +77,52 @@ export const vitalsCache = (db: Database): Stamped<Vitals> => cacheOf(vitalsCach
6777 /** The waiting-line cache of `db`: for tests, which count its hits. */
6878 export const waitingCache = (db: Database): Stamped<Waiting> => cacheOf(waitingCaches, db, 64, HOME_MAX_AGE_MS);
6979
80 /** The keys of each cache whose refresh is scheduled or running: at most one per key. */
81 const refreshing = new WeakMap<Stamped<unknown>, Set<string>>();
82
83 /**
84 * `key`'s answer from `cache`: computed inline when there is none, or when
85 * the one kept is past `HOME_STALE_CEILING_MS`. One older than 60 s is served
86 * as is, counted a hit, and `refresh` lands its successor after this request,
87 * once per key at a time. A refresh that throws is logged, keeps the old
88 * answer and frees the key for the next request. The refresh runs on the
89 * same thread: it is off the request, not off the event loop.
90 */
91 function servedStale<V>(
92 db: Database,
93 cache: Stamped<V>,
94 key: string,
95 compute: () => V,
96 refresh: () => V,
97 ): V {
98 const kept = cache.peek(key);
99 const age = kept === undefined ? 0 : clock() - kept.at;
100 if (kept === undefined || age < HOME_TTL_MS || age >= HOME_STALE_CEILING_MS) {
101 return cache.get(key, TTL, compute);
102 }
103 cache.hits++;
104 let keys = refreshing.get(cache);
105 if (keys === undefined) {
106 keys = new Set();
107 refreshing.set(cache, keys);
108 }
109 if (!keys.has(key)) {
110 const held = keys;
111 held.add(key);
112 setTimeout(() => {
113 try {
114 if (!db.inTransaction) cache.put(key, TTL, refresh());
115 } catch (error) {
116 // The old answer stays; the next stale request schedules again.
117 log.warn("home.refresh_failed", { key, error: String(error) });
118 } finally {
119 held.delete(key);
120 }
121 }, 0);
122 }
123 return kept.value;
124 }
125
70126 /**
71127 * The viewer's own asks, counted: keyed by viewer id, so no one reads another's.
72128 * Valid while the write clock holds, 30 seconds at most (asks also change with time).
@@ -79,9 +135,10 @@ export function cachedWaiting(db: Database, viewerId: string, compute: () => Wai
79135
80136 /**
81137 * Admin only: the caller has checked. Keyed by UTC hour, ceiling and data
82 * directory; kept 60 s, all but the builders, read fresh each time so they
83 * agree with the idle reason. Nothing is kept inside a transaction, whose
84 * rows may roll back. `time` names readKpis' parts for Server-Timing.
138 * directory; kept 60 s and refreshed after (`servedStale`), all but the
139 * builders, read fresh each time so they agree with the idle reason. Nothing
140 * is kept inside a transaction, whose rows may roll back. `time` names
141 * readKpis' parts for Server-Timing.
85142 */
86143 export function cachedKpis(
87144 db: Database,
@@ -91,27 +148,34 @@ export function cachedKpis(
91148 ): Kpis {
92149 if (db.inTransaction) return readKpis(db, now, forge, time);
93150 const key = `kpi:${now.toISOString().slice(0, 13)}:${forge.ceilingUsd ?? "none"}:${forge.dataDir ?? ""}`;
94 let fresh = true;
95 const kept = kpiCache(db).get(key, TTL, () => {
96 fresh = false;
151 let computed = false;
152 const compute = (): Kpis => {
153 computed = true;
97154 return readKpis(db, now, forge, time);
98 });
99 if (!fresh) return kept;
155 };
156 // The refresh runs after this request has answered, so it times nothing of
157 // it. It reads at the triggering request's `now` on purpose: the key holds
158 // that UTC hour, so the answer it lands is the one that key names, and a
159 // request in the next hour asks for a new key.
160 const kept = servedStale(db, kpiCache(db), key, compute, () => readKpis(db, now, forge));
161 if (computed) return kept;
100162 const builders = time === undefined ? readBuilders(db) : time("kpis.builders", () => readBuilders(db));
101163 return { ...kept, builders };
102164 }
103165
104166 /**
105 * Admin only: one pinned panel's answer, kept 60 s. The key is the board's
106 * slug and the panel's own definition, so an edited board is a new key.
167 * Admin only: one pinned panel's answer, kept 60 s and refreshed after. The
168 * key is the board's slug and the panel's own definition, so an edited board
169 * is a new key.
107170 */
108171 export function cachedPanel(db: Database, identity: unknown, compute: () => Answer): Answer {
109172 if (db.inTransaction) return compute();
110 return panelCache(db).get(`panel:${JSON.stringify(identity)}`, TTL, compute);
173 return servedStale(db, panelCache(db), `panel:${JSON.stringify(identity)}`, compute, compute);
111174 }
112175
113176 /** Admin only: the caller has checked. The forge-wide flow vitals, kept 60 s like the KPIs. */
114177 export function cachedVitals(db: Database, now: Date): Vitals {
115178 if (db.inTransaction) return readVitals(db, now);
116 return vitalsCache(db).get("vitals", TTL, () => readVitals(db, now));
179 const compute = (): Vitals => readVitals(db, now);
180 return servedStale(db, vitalsCache(db), "vitals", compute, compute);
117181 }
test/home-cache-ttl.test.ts +147 −11
@@ -1,10 +1,12 @@
11 /**
22 * Home's KPI, panel and vitals answers are kept 60 s from when they were
3 * computed, whatever is written since (#7624); the builders figure is read
4 * fresh beside them, and the waiting line still misses on a write, because
5 * the asks count must stay exact.
3 * computed, whatever is written since (#7624); past 60 s the old answer is
4 * still served at once while one refresh runs after the tick (#7625), up to
5 * a 10 min ceiling; the builders figure is read fresh beside them, and the
6 * waiting line still misses on a write, because the asks count must stay
7 * exact.
68 */
7 import { afterAll, afterEach, beforeAll, beforeEach, expect, test } from "bun:test";
9 import { afterAll, afterEach, beforeAll, beforeEach, expect, spyOn, test } from "bun:test";
810 import { mkdtemp, rm } from "node:fs/promises";
911 import { tmpdir } from "node:os";
1012 import { join } from "node:path";
@@ -12,11 +14,15 @@ import { createApp, type App } from "../src/app.ts";
1214 import { createRepo } from "../src/actions/repos.ts";
1315 import type { Answer } from "../src/boards/query.ts";
1416 import { claimRun, createRun } from "../src/core/runs.ts";
17 import { takePhases, timePhase } from "../src/core/route_timing.ts";
18 import type { KpiPart } from "../src/flow/kpis.ts";
19 import { logLevel, setLogLevel } from "../src/kernel/log.ts";
1520 import {
1621 cachedKpis,
1722 cachedPanel,
1823 cachedVitals,
1924 cachedWaiting,
25 HOME_STALE_CEILING_MS,
2026 kpiCache,
2127 panelCache,
2228 setHomeClock,
@@ -57,13 +63,20 @@ beforeEach(() => {
5763 setHomeClock(() => t);
5864 for (const c of [kpiCache(app.db), panelCache(app.db), vitalsCache(app.db), waitingCache(app.db)]) c.clear();
5965 });
60 afterEach(() => setHomeClock(undefined));
66 afterEach(async () => {
67 // A refresh one test scheduled runs here, not in the next test.
68 await new Promise((done) => setTimeout(done, 0));
69 setHomeClock(undefined);
70 });
71
72 /** Let the refreshes scheduled with `setTimeout(0)` run. */
73 const tick = (): Promise<void> => new Promise((done) => setTimeout(done, 0));
6174
6275 const write = (times: number): void => {
6376 for (let i = 0; i < times; i++) app.db.query("UPDATE repo SET description = ?1 WHERE id = ?2").run(`w${i}`, repo.id);
6477 };
6578
66 test("cachedKpis computes once across 50 writes, and again at 61 s", () => {
79 test("cachedKpis computes once across 50 writes, and again after the tick past 61 s", async () => {
6780 const cache = kpiCache(app.db);
6881 const m = cache.misses;
6982 const first = cachedKpis(app.db, now, forge);
@@ -76,8 +89,10 @@ test("cachedKpis computes once across 50 writes, and again at 61 s", () => {
7689 expect(cache.misses).toBe(m + 1);
7790
7891 t += 2_000;
92 expect(cachedKpis(app.db, now, forge).landedHours).toBe(first.landedHours);
93 expect(cache.misses).toBe(m + 1);
94 await tick();
7995 expect(cachedKpis(app.db, now, forge).landedHours).not.toBe(first.landedHours);
80 expect(cache.misses).toBe(m + 2);
8196 });
8297
8398 test("the builders figure is read fresh on a hit, so it agrees with the idle reason beside it", () => {
@@ -90,7 +105,7 @@ test("the builders figure is read fresh on a hit, so it agrees with the idle rea
90105 expect(cache.misses).toBe(m + 1);
91106 });
92107
93 test("a panel and the vitals are kept 60 s through writes, each by its own identity", () => {
108 test("a panel and the vitals are kept 60 s through writes, each by its own identity", async () => {
94109 let a = 0;
95110 let b = 0;
96111 const answer = (n: number) => ({ n }) as unknown as Answer;
@@ -106,9 +121,130 @@ test("a panel and the vitals are kept 60 s through writes, each by its own ident
106121 expect([a, b, vitals.misses - v]).toEqual([1, 1, 1]);
107122
108123 t += 61_000;
109 cachedPanel(app.db, { board: "ops", title: "A" }, () => answer(++a));
110 cachedVitals(app.db, now);
111 expect([a, vitals.misses - v]).toEqual([2, 2]);
124 const vitalsBefore = cachedVitals(app.db, now);
125 expect(cachedPanel(app.db, { board: "ops", title: "A" }, () => answer(++a))).toEqual(answer(1));
126 expect(a).toBe(1);
127 await tick();
128 expect([a, b]).toEqual([2, 1]);
129 expect(cachedPanel(app.db, { board: "ops", title: "A" }, () => answer(++a))).toEqual(answer(2));
130 expect(cachedVitals(app.db, now)).not.toBe(vitalsBefore);
131 expect(vitals.misses - v).toBe(1);
132 });
133
134 test("past 60 s the old answer comes back without calling compute", () => {
135 let n = 0;
136 const compute = () => ({ n: ++n }) as unknown as Answer;
137 cachedPanel(app.db, "p", compute);
138 t += 61_000;
139 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 1 } as unknown as Answer);
140 expect(n).toBe(1);
141 });
142
143 test("after the scheduled tick the next call returns the new answer", async () => {
144 let n = 0;
145 const compute = () => ({ n: ++n }) as unknown as Answer;
146 cachedPanel(app.db, "p", compute);
147 t += 61_000;
148 cachedPanel(app.db, "p", compute);
149 await tick();
150 expect(n).toBe(2);
151 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 2 } as unknown as Answer);
152 expect(n).toBe(2);
153 });
154
155 test("two stale calls in a row schedule one refresh", async () => {
156 let n = 0;
157 const compute = () => ({ n: ++n }) as unknown as Answer;
158 cachedPanel(app.db, "p", compute);
159 t += 61_000;
160 cachedPanel(app.db, "p", compute);
161 cachedPanel(app.db, "p", compute);
162 await tick();
163 await tick();
164 expect(n).toBe(2);
165 });
166
167 test("a refresh that throws keeps the old answer and frees the key", async () => {
168 let n = 0;
169 let fail = true;
170 const compute = () => {
171 n++;
172 if (fail) throw new Error("refresh failed");
173 return { n } as unknown as Answer;
174 };
175 cachedPanel(app.db, "p", () => ({ n: 0 }) as unknown as Answer);
176 t += 61_000;
177 cachedPanel(app.db, "p", compute);
178 await tick();
179 expect(n).toBe(1);
180 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 0 } as unknown as Answer);
181 fail = false;
182 await tick();
183 expect(n).toBe(2);
184 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 2 } as unknown as Answer);
185 });
186
187 test("only a cold start computes inline", () => {
188 let n = 0;
189 const compute = () => ({ n: ++n }) as unknown as Answer;
190 expect(cachedPanel(app.db, "cold", compute)).toEqual({ n: 1 } as unknown as Answer);
191 expect(n).toBe(1);
192 });
193
194 test("past the ceiling a stale answer is not served: the request computes inline", () => {
195 let n = 0;
196 const compute = () => ({ n: ++n }) as unknown as Answer;
197 cachedPanel(app.db, "p", compute);
198 t += HOME_STALE_CEILING_MS - 1;
199 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 1 } as unknown as Answer);
200 t += 1;
201 expect(cachedPanel(app.db, "p", compute)).toEqual({ n: 2 } as unknown as Answer);
202 expect(n).toBe(2);
203 });
204
205 test("a refresh that throws is logged", async () => {
206 const level = logLevel();
207 setLogLevel("warn");
208 const warn = spyOn(console, "warn").mockImplementation(() => {});
209 try {
210 cachedPanel(app.db, "p", () => ({ n: 0 }) as unknown as Answer);
211 t += 61_000;
212 cachedPanel(app.db, "p", () => {
213 throw new Error("refresh failed");
214 });
215 await tick();
216 expect(warn.mock.calls.map((c) => String(c[0])).join("\n")).toContain("home.refresh_failed");
217 } finally {
218 warn.mockRestore();
219 setLogLevel(level);
220 }
221 });
222
223 test("the Server-Timing kpis phase is a hit, warm or stale, running only the builders' read", async () => {
224 // Work is counted through readKpis' own timer seam, not a clock or a patched
225 // db.query (#7824): each part it runs is named once, and nothing else in the
226 // process can add to the count.
227 const kpis = (): { hit: boolean | undefined; parts: KpiPart[] } => {
228 const parts: KpiPart[] = [];
229 const count = <T>(name: KpiPart, fn: () => T): T => {
230 parts.push(name);
231 return fn();
232 };
233 const request = new Request("http://forge.test/");
234 timePhase(request, "kpis", () => cachedKpis(app.db, now, forge, count), () => kpiCache(app.db));
235 return { hit: takePhases(request).find((p) => p.name === "kpis")!.hit, parts };
236 };
237 const cold = kpis();
238 const warm = kpis();
239 t += 61_000;
240 const stale = kpis();
241 await tick();
242 expect(cold.hit).toBeFalsy();
243 expect(cold.parts.length).toBeGreaterThan(1);
244 for (const phase of [warm, stale]) {
245 expect(phase.hit).toBe(true);
246 expect(phase.parts).toEqual(["kpis.builders"]);
247 }
112248 });
113249
114250 test("nothing is kept inside a transaction", () => {
test/stamped.test.ts +12
@@ -79,4 +79,16 @@ describe("Stamped", () => {
7979 expect(m.stamped.size).toBe(0);
8080 expect(m.stamped.get("a", "s", m.compute)).toBe(3);
8181 });
82
83 test("peek returns an entry however old, and put stores one aged from now, counting nothing", () => {
84 const m = memo(3, 1000);
85 m.stamped.get("a", "s", m.compute);
86 m.clock.t = 5000;
87 expect(m.stamped.peek("a")).toEqual({ stamp: "s", value: 1, at: 0 });
88 m.stamped.put("a", "s", 7);
89 expect(m.stamped.peek("a")).toEqual({ stamp: "s", value: 7, at: 5000 });
90 expect(m.stamped.get("a", "s", m.compute)).toBe(7);
91 expect([m.stamped.hits, m.stamped.misses]).toEqual([1, 1]);
92 expect(m.stamped.peek("b")).toBeUndefined();
93 });
8294 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs