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

When the forge's own lag explains most of an app's wait, the app's page does not call the app slow #10882

Merged opened this

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

Merged

torque/forge:torque/10858-when-the-forge-s-own-lag-explains-most-o → main 3 commits fork 2 threads · 2 unresolved

  • Merged. torque/10858-when-the-forge-s-own-lag-explains-most-o was merged into main as 1b7e5bd.

Review

Sign in to review this change.
9 files changed +196 −7
AGENTS.md +2
@@ -19,6 +19,8 @@ State shared between modules through process memory, not the database, is named
1919
2020 `src/perf/loop_worst.ts`: `loopWorst`, the worst event-loop lag of the last 10 s in ten one-second slots, fed by one unref'd 50 ms timer that the first `serve` starts (`startLoopWorst`), and read by every response's `lag;dur` and by `/healthz` asked for JSON (`loopLagMs`). Tests listing a request's phases read `requestTiming` (`test/helpers/request-timing.ts`), which leaves `lag` out.
2121
22 `src/apps/relay_wait.ts`: each app's slowest production wait relayed in the last 10 minutes, with the forge's loop lag beside it, noted by the proxy (`relayUpstream`) and read by `appVitals`; `forgeWaited` decides whose wait it was, and the speed card and terminal line say "the forge was busy" when it was the forge's (#10858). At most 2,000 apps, gone on restart.
23
2224 `src/core/transfer.ts`: the old owner/name pairs a transfer left behind (`repo_redirect`), held per database after the first request reads them and dropped by `transferRepo`, so a request under a path nothing moved from costs no statement (#569).
2325
2426 ## Awake ceiling and the boot
docs/features/app-slowest-wait.md added +11
@@ -0,0 +1,11 @@
1 # Whose wait it was: the forge's or the app's (#10858)
2
3 An app's production speed card says the slowest wait the forge relayed to it in the last 10 minutes, and whether the forge or the app spent it. When the forge's own event-loop lag (`forge-lag`) is more than half the time to the app's headers (`forge-ttfb`), the wait is the forge's (`forgeWaited`, `src/perf/loop_worst.ts`), and the card says so instead of calling the app slow.
4
5 - Page: Settings → App → **Visitors and speed**, a **Slowest wait, 10 min** row beside the p75 figures: `the forge was busy: 600 ms of the 820 ms wait`, or `820 ms, the app's own`. No row when nothing was relayed in the window.
6 - Terminal: the deploys screen's visitors line ends `· slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait`.
7 - API: `GET /api/v1/repos/:owner/:name/app`, for the app's admins, carries `vitals.wait: {ttfbMs, lagMs, at, forge}`; absent with no wait in the window.
8
9 Production only; previews are not counted. Held in the forge's memory (at most 2,000 apps), so a restart forgets it.
10
11 Try it: hold a production app's answer behind a busy forge (a long synchronous task on the forge, then load the app), then open its repository's Settings → App within 10 minutes.
src/apps/proxy.ts +8 −4
@@ -66,6 +66,7 @@ import { appMeasure } from "./measure.ts";
6666 import { holdPortRequest, holdPortSocket } from "./handoff.ts";
6767 import { secureFor } from "../http/cookie_secure.ts";
6868 import { currentLoopLag } from "../perf/loop_worst.ts";
69 import { noteRelayWait } from "./relay_wait.ts";
6970 import { cspNonce, htmlAnswer, readPage, rewritable, TOOLBAR_ASSET_PATH, TOOLBAR_ASSET_PREFIX, toolbarResponse, withToolbar, type PillWhere } from "./toolbar.ts";
7071
7172 const proxySecure = (request: Request, url: URL, forgeUrl: string): boolean =>
@@ -459,10 +460,13 @@ function relayPhase(request: Request, name: RelayPhase, ms: number): void {
459460 * so a loop blocked by something else lands in it while the app sat idle;
460461 * `forgeWaited` (the one place the rule lives) says when the wait was the forge's.
461462 */
462 function relayUpstream(request: Request, headersMs: number): void {
463 function relayUpstream(request: Request, target: AppTarget, headersMs: number): void {
464 const lag = currentLoopLag();
463465 relayPhase(request, "ttfb", headersMs);
464 relayPhase(request, "lag", currentLoopLag());
466 relayPhase(request, "lag", lag);
465467 relayPhase(request, "upstream", headersMs);
468 // Production's slowest wait, for the app's speed card (`apps/relay_wait.ts`).
469 if (target.env === "production") noteRelayWait(target.app.id, headersMs, lag);
466470 }
467471
468472 /**
@@ -1219,10 +1223,10 @@ export async function proxyApp(
12191223 } as RequestInit);
12201224 } catch {
12211225 answered();
1222 relayUpstream(request, performance.now() - sent);
1226 relayUpstream(request, target, performance.now() - sent);
12231227 return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
12241228 }
1225 relayUpstream(request, performance.now() - sent);
1229 relayUpstream(request, target, performance.now() - sent);
12261230 const out = new Headers(response.headers);
12271231 for (const name of HOP_BY_HOP) out.delete(name);
12281232 // Which app answered: a probe from outside (`spawn/reach.ts`) tells this
src/apps/relay_wait.ts added +67
@@ -0,0 +1,67 @@
1 /**
2 * The slowest wait the forge relayed to each app's production in the last
3 * ten minutes (#10858), and whose wait it was. The proxy notes every relay's
4 * time to the app's headers (`forge-ttfb`) beside the forge's worst loop lag
5 * at that moment (`forge-lag`, `perf/loop_worst.ts`); the app's speed card
6 * and its terminal line say it in words. When the lag explains more than
7 * half the wait (`forgeWaited`, the one place the rule lives), the words
8 * say the forge was busy, not the app.
9 *
10 * Process memory, not the database: one O(1) compare per relay, at most
11 * `KEEP_APPS` apps (the oldest reading goes first), gone on restart.
12 */
13
14 import { forgeWaited } from "../perf/loop_worst.ts";
15
16 /** How long a slowest wait stays told, ms. */
17 export const WAIT_WINDOW_MS = 10 * 60 * 1000;
18 /** The most apps held; past it the stalest reading is dropped. */
19 export const KEEP_APPS = 2_000;
20
21 export interface RelayWait {
22 /** Time to the app's headers, on the forge's clock, ms. */
23 readonly ttfbMs: number;
24 /** The forge's worst event-loop lag of the 10 s before, ms. */
25 readonly lagMs: number;
26 /** When it was relayed, ms since the epoch. */
27 readonly at: number;
28 /** True when the forge's lag explains most of the wait (`forgeWaited`). */
29 readonly forge: boolean;
30 }
31
32 const slowest = new Map<string, RelayWait>();
33
34 /** Note one relayed wait for `appId`; it is kept when it is the window's slowest. */
35 export function noteRelayWait(appId: string, ttfbMs: number, lagMs: number, at: number = Date.now()): void {
36 if (!Number.isFinite(ttfbMs) || ttfbMs < 0 || !Number.isFinite(lagMs) || lagMs < 0) return;
37 const held = slowest.get(appId);
38 if (held !== undefined && at - held.at < WAIT_WINDOW_MS && held.ttfbMs >= ttfbMs) return;
39 if (held === undefined && slowest.size >= KEEP_APPS) {
40 // Maps keep insertion order and a replacement re-inserts, so the first is the stalest.
41 const first = slowest.keys().next().value;
42 if (first !== undefined) slowest.delete(first);
43 }
44 slowest.delete(appId);
45 slowest.set(appId, { ttfbMs, lagMs, at, forge: forgeWaited(lagMs, ttfbMs) });
46 }
47
48 /** The slowest wait of the window ending at `at`, or undefined with none. */
49 export function relayWait(appId: string, at: number = Date.now()): RelayWait | undefined {
50 const held = slowest.get(appId);
51 return held !== undefined && at - held.at < WAIT_WINDOW_MS ? held : undefined;
52 }
53
54 /** Forget every reading (tests). */
55 export function clearRelayWaits(): void {
56 slowest.clear();
57 }
58
59 const msText = (v: number): string => (v < 1000 ? `${Math.round(v)} ms` : `${(v / 1000).toFixed(1)} s`);
60
61 /**
62 * The reading in one plain sentence, whose wait first: "the forge was busy:
63 * 600 ms of the 820 ms wait" or "820 ms, the app's own". Plain text; callers escape.
64 */
65 export function relayWaitWords(w: RelayWait): string {
66 return w.forge ? `the forge was busy: ${msText(w.lagMs)} of the ${msText(w.ttfbMs)} wait` : `${msText(w.ttfbMs)}, the app's own`;
67 }
src/apps/vitals.ts +8 −2
@@ -8,6 +8,7 @@
88 import type { Database } from "bun:sqlite";
99 import { sha256 } from "../kernel/hash.ts";
1010 import { dayOf, DAY_MAX, saltFor, type Report } from "../web/measure.ts";
11 import { relayWait, relayWaitWords, type RelayWait } from "./relay_wait.ts";
1112
1213 const KEEP_MS = 90 * 24 * 60 * 60 * 1000;
1314
@@ -50,6 +51,8 @@ export interface AppVitals {
5051 readonly clsP75: number | undefined;
5152 /** p75 load for each of the last 30 days, oldest first; null for a day with no reports. */
5253 readonly loadDays: (number | null)[];
54 /** The slowest wait the forge relayed in the last 10 minutes, and whose it was; absent with none. */
55 readonly wait?: RelayWait;
5356 }
5457
5558 const DAY = 24 * 60 * 60 * 1000;
@@ -78,6 +81,7 @@ export function appVitals(db: Database, appId: string, at: number = Date.now()):
7881 "SELECT COUNT(*) AS n FROM (SELECT DISTINCT day, visitor FROM app_vital WHERE app_id = ? AND day >= ?)",
7982 )
8083 .get(appId, from)?.n ?? 0;
84 const wait = relayWait(appId, at);
8185 return {
8286 today: count(dayOf(at)),
8387 week: count(since),
@@ -87,6 +91,7 @@ export function appVitals(db: Database, appId: string, at: number = Date.now()):
8791 inpP75: p75(db, appId, "inp", since),
8892 clsP75: p75(db, appId, "cls", since),
8993 loadDays: loadP75Days(db, appId, at),
94 ...(wait === undefined ? {} : { wait }),
9095 };
9196 }
9297
@@ -117,9 +122,10 @@ export const speedText = (v: number | undefined): string =>
117122 /** A layout shift score: "0.05", or a dash with no data. */
118123 export const shiftText = (v: number | undefined): string => (v === undefined ? "–" : v.toFixed(2));
119124
120 /** The one line the terminal shows. */
125 /** The one line the terminal shows, and the slowest relayed wait's words when there is one. */
121126 export const visitorsLine = (v: AppVitals): string =>
122 `visitors ${v.today} today, ${v.week} in 7 days · p75 TTFB ${speedText(v.ttfbP75)} · load ${speedText(v.loadP75)} · LCP ${speedText(v.lcpP75)} · INP ${speedText(v.inpP75)} · CLS ${shiftText(v.clsP75)}`;
127 `visitors ${v.today} today, ${v.week} in 7 days · p75 TTFB ${speedText(v.ttfbP75)} · load ${speedText(v.loadP75)} · LCP ${speedText(v.lcpP75)} · INP ${speedText(v.inpP75)} · CLS ${shiftText(v.clsP75)}` +
128 (v.wait === undefined ? "" : ` · slowest wait, 10 min: ${relayWaitWords(v.wait)}`);
123129
124130 /** Thirty days of load as blocks, oldest first, `·` for a silent day: "▁▃█·▂". Empty with no data. */
125131 export function loadTrend(days: readonly (number | null)[]): string {
src/web/pages/settings.ts +2
@@ -58,6 +58,7 @@ import { updateRepoSettings } from "../../actions/repos.ts";
5858 import { appsRuntime } from "../../apps/runtime.ts";
5959 import { nameFrame, notePhase, takeSessionTime, timePhase, timePhaseAsync } from "../../core/route_timing.ts";
6060 import { appVitals, shiftText, speedText as ms, type AppVitals } from "../../apps/vitals.ts";
61 import { relayWaitWords } from "../../apps/relay_wait.ts";
6162 import type { PreviewData } from "../../apps/data.ts";
6263 import {
6364 getAppByRepo,
@@ -872,6 +873,7 @@ export function appVisitorsView(v: AppVitals): Html {
872873 <div><dt>p75 LCP</dt><dd>${ms(v.lcpP75)}</dd></div>
873874 <div><dt>p75 INP</dt><dd>${ms(v.inpP75)}</dd></div>
874875 <div><dt>p75 CLS</dt><dd>${shiftText(v.clsP75)}</dd></div>
876 ${v.wait === undefined ? "" : html`<div><dt>Slowest wait, 10 min</dt><dd>${relayWaitWords(v.wait)}</dd></div>`}
875877 </dl>
876878 ${spark ? html`<div class="bar muted">${spark}</div>` : html`<p class="muted small mt">No load reports in the last 30 days</p>`}
outdated

Principle 1/8: the label "Slowest wait in the last 10 minutes:" plus the long sentence explains itself twice. Say it once, and put it in a dl row (principle 7) beside the p75 facts, not a loose paragraph.

877879 </section>`;
test/apps-measure.test.ts +20
@@ -17,6 +17,7 @@ import { appVisitors } from "../src/actions/apps.ts";
1717 import { createToken } from "../src/core/tokens.ts";
1818 import { getRepo } from "../src/core/repos.ts";
1919 import { appVitals, recordAppVital } from "../src/apps/vitals.ts";
20 import { clearRelayWaits, noteRelayWait } from "../src/apps/relay_wait.ts";
2021 import { deleteApp, getAppByRepo } from "../src/core/apps.ts";
2122 import { createUser } from "../src/core/users.ts";
2223 import { serve, type Servers } from "../src/http/server.ts";
@@ -175,6 +176,25 @@ describe("a report through the proxy", () => {
175176 expect(((await (await get(createToken(app.db, owner.id, "r2", "ro").token)).json()) as { vitals: { loadDays: unknown[] } }).vitals.loadDays).toHaveLength(30);
176177 });
177178
179 test("the API's vitals carry the slowest relayed wait and whose it was (#10858)", async () => {
180 const owner = (await import("../src/core/users.ts")).getUserByName(app.db, "alice")!;
181 const get = async () =>
182 (await (
183 await fetch(`${servers.url}/api/v1/repos/alice/notes/app`, {
184 headers: { authorization: `Bearer ${createToken(app.db, owner.id, "wait", "ro").token}` },
185 })
186 ).json()) as { vitals: Record<string, unknown> };
187 clearRelayWaits();
188 expect((await get()).vitals).not.toHaveProperty("wait");
189 // 820 ms to headers, 600 ms of it the forge's loop: the forge's wait.
190 noteRelayWait(ids.notes!, 820, 600);
191 try {
192 expect((await get()).vitals.wait).toMatchObject({ ttfbMs: 820, lagMs: 600, forge: true });
193 } finally {
194 clearRelayWaits();
195 }
196 });
197
178198 test("a sealed pull's preview refuses an anonymous report and stores nothing", async () => {
179199 const repo = getRepo(app.db, "alice", "diary")!;
180200 const alice = (await import("../src/core/users.ts")).getUserByName(app.db, "alice")!;
test/apps-proxy-timing.test.ts +8 −1
@@ -8,7 +8,9 @@ import { tmpdir } from "node:os";
88 import { join } from "node:path";
99 import { createApp, type App } from "../src/app.ts";
1010 import { AppsRuntime, type EnvStatus } from "../src/apps/runtime.ts";
11 import { newApp } from "../src/actions/apps.ts";
11 import { appVisitors, newApp } from "../src/actions/apps.ts";
12 import { clearRelayWaits } from "../src/apps/relay_wait.ts";
13 import { visitorsLine } from "../src/apps/vitals.ts";
1214 import { commitToBranch } from "../src/actions/repos.ts";
1315 import type { Repo } from "../src/core/repos.ts";
1416 import { createUser, type User } from "../src/core/users.ts";
@@ -155,10 +157,15 @@ describe("a proxied answer's Server-Timing", () => {
155157 const until = performance.now() + 250;
156158 while (performance.now() < until) {}
157159 await Bun.sleep(30);
160 clearRelayWaits();
158161 const header = (await viaHost("/ttfb")).headers.get("server-timing")!;
159162 expect(dur(header, "forge-lag")!).toBeGreaterThanOrEqual(200);
160163 // /ttfb answers in ~30 ms: the lag is more than half of it, so the wait was the forge's.
161164 expect(forgeWaited(dur(header, "forge-lag")!, dur(header, "forge-ttfb")!)).toBe(true);
165 // The app's speed card and terminal line say so: the forge was busy, not the app (#10858).
166 const vitals = appVisitors(app, alice, repo)!;
167 expect(vitals.wait?.forge).toBe(true);
168 expect(visitorsLine(vitals)).toContain("the forge was busy: ");
162169 } finally {
163170 stopLoopWorst();
164171 startLoopWorst();
test/relay-wait.test.ts added +70
@@ -0,0 +1,70 @@
1 /**
2 * The slowest wait the forge relayed to an app, and whose it was (#10858):
3 * when the forge's own loop lag explains more than half of `forge-ttfb`, the
4 * app's speed card and terminal line say the forge was busy, not the app.
5 */
6 import { beforeEach, expect, test } from "bun:test";
7 import { clearRelayWaits, KEEP_APPS, noteRelayWait, relayWait, relayWaitWords, WAIT_WINDOW_MS } from "../src/apps/relay_wait.ts";
8 import { visitorsLine, type AppVitals } from "../src/apps/vitals.ts";
9 import { appVisitorsView } from "../src/web/pages/settings.ts";
10
11 const NOW = Date.parse("2026-11-10T12:00:00Z");
12 const none: AppVitals = { today: 0, week: 0, ttfbP75: undefined, loadP75: undefined, lcpP75: undefined, inpP75: undefined, clsP75: undefined, loadDays: [] };
13
14 beforeEach(() => clearRelayWaits());
15
16 test("a wait the forge's lag explains is worded the forge's, escaped", () => {
17 // 820 ms to headers, 600 ms of it the forge's loop: 600 > 820 / 2.
18 noteRelayWait("a1", 820, 600, NOW);
19 const wait = relayWait("a1", NOW)!;
20 expect(wait.forge).toBe(true);
21 expect(relayWaitWords(wait)).toBe("the forge was busy: 600 ms of the 820 ms wait");
22 const page = String(appVisitorsView({ ...none, wait }));
23 // One row beside the p75 facts, said once.
24 expect(page).toContain("<dt>Slowest wait, 10 min</dt><dd>the forge was busy: 600 ms of the 820 ms wait</dd>");
25 expect(page.match(/600 ms/g)).toHaveLength(1);
26 expect(visitorsLine({ ...none, wait })).toEndWith(" · slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait");
27 });
28
29 test("a wait the forge's lag does not explain is the app's own", () => {
30 // 1.5 s to headers, 40 ms of lag: the app was slow.
31 noteRelayWait("a1", 1500, 40, NOW);
32 const wait = relayWait("a1", NOW)!;
33 expect(wait.forge).toBe(false);
34 expect(relayWaitWords(wait)).toBe("1.5 s, the app's own");
35 const page = String(appVisitorsView({ ...none, wait }));
36 expect(page).not.toContain("forge was busy");
37 // The apostrophe is escaped on the page; the raw words never reach it.
38 expect(page).not.toContain("app's own");
39 expect(page).toMatch(/<dd>1\.5 s, the app&#(39|x27);s own<\/dd>/);
40 });
41
42 test("exactly half is the app's: more than half is the rule", () => {
43 noteRelayWait("a1", 400, 200, NOW);
44 expect(relayWait("a1", NOW)!.forge).toBe(false);
45 });
46
47 test("the slowest of the window is kept, and falls out after ten minutes", () => {
48 noteRelayWait("a1", 300, 0, NOW);
49 noteRelayWait("a1", 100, 90, NOW + 1);
50 expect(relayWait("a1", NOW + 2)!.ttfbMs).toBe(300);
51 expect(relayWait("a1", NOW + WAIT_WINDOW_MS)).toBeUndefined();
52 // A stale reading is replaced by any newer one.
53 noteRelayWait("a1", 50, 40, NOW + WAIT_WINDOW_MS);
54 expect(relayWait("a1", NOW + WAIT_WINDOW_MS)).toMatchObject({ ttfbMs: 50, forge: true });
55 // A malformed reading is not kept.
56 noteRelayWait("a2", Number.NaN, 0, NOW);
57 noteRelayWait("a2", 10, -1, NOW);
58 expect(relayWait("a2", NOW)).toBeUndefined();
59 });
60
61 test("no reading, no words", () => {
62 expect(String(appVisitorsView(none))).not.toContain("Slowest wait");
63 expect(visitorsLine(none)).not.toContain("slowest wait");
64 });
65
66 test("at most KEEP_APPS apps are held, the stalest dropped first", () => {
67 for (let i = 0; i <= KEEP_APPS; i++) noteRelayWait(`app${i}`, 10, 0, NOW + i);
68 expect(relayWait("app0", NOW + KEEP_APPS)).toBeUndefined();
69 expect(relayWait(`app${KEEP_APPS}`, NOW + KEEP_APPS)).toBeDefined();
70 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs