trevato/forge

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

More
Forks1g fMapg aRunsg rEventsFlows

/system shows the last 20 idle loop-lag readings against the 100 ms bar, each over it named by its `loopWorstWhat` #11236

Merged torquecrew opened this

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

ConversationFiles
Merged

torque/forge:torque/11220-system-shows-the-last-20-idle-loop-lag-r → main 4 commits fork 2 threads · 2 unresolved

  • Merged. torque/11220-system-shows-the-last-20-idle-loop-lag-r was merged into main as 7563727.

Review

Sign in to review this change.
10 files changed +397 −14
docs/features/stalls-by-route.md +12
@@ -16,10 +16,22 @@ palette entry):
1616 when the hour had one: the five worst single stalls, each with what ran (the route pattern, `job:<name>` for a job
1717 marked with `jobWatch.during`, or `unknown`), its ms and when. Kept in a
1818 fixed ring of 256 (`src/perf/stall_blame.ts`).
19 - **`/system`**, "Loop lag, last 20 minutes" (#11220), just above the stalls
20 card: a badge counts how many of the last 20 full minutes' worst loop lag
21 are over the 100 ms bar (strictly: exactly 100 ms holds); then one row a
22 minute, oldest first: its start, its worst ms (marked "over" past the
23 bar), and what its worst stall ran under (the `loopWorstWhat` name), or
24 "not named" when no wake in that minute passed 200 ms. A fixed ring of 20 written once a minute
25 (`src/perf/lag_minutes.ts`); the open minute is not shown. The MCP `system`
26 tool answers the same as `readings: [{ at, ms, what }]` (`at` the minute's
27 start, ISO), with `barMs` and `over`.
1928 - **`/healthz`** with `Accept: application/json`: beside `loopLagMs`,
2029 `loopWorstWhat` names the worst stall of the same 10 s (null when none).
2130 - **The terminal**: `:` → "Main-thread stalls", the same rows, then the same
2231 worst single stalls (what ran, ms, when in UTC) when the hour had one.
32 Above them, the same loop-lag readings (#11220): "Loop lag, last 20
33 minutes: N of M over 100 ms", then a minute a row — its start in UTC, its
34 worst ms, `over` past the bar, and what ran or "not named".
2335 - **`GET /metrics`** (an admin `ro` token): `forge_loop_stall_milliseconds_total`
2436 and `forge_loop_stalls_total` by `route` since the process started, and the
2537 last hour as `forge_loop_stall_hour_milliseconds` / `forge_loop_stall_hour_count`
src/http/mcp/tools/system.ts +7 −3
@@ -3,12 +3,13 @@ import { systemWithReaders } from "../../../system/telemetry.ts";
33 import { violationsByDirective, windowStart } from "../../csp_report.ts";
44 import { countRead } from "../../../system/telemetry_reads.ts";
55 import { stallHour, TOP_ROUTES } from "../../../metrics/stalls.ts";
6 import { loopWatch } from "../../../perf/live.ts";
6 import { lagMinutes, loopWatch } from "../../../perf/live.ts";
7 import { LAG_BAR_MS, overBar } from "../../../perf/lag_minutes.ts";
78 import { good, bad, type Tool } from "../shared.ts";
89
910 export const tool: Tool = {
1011 name: "system",
11 doc: "the machine the forge runs on, now: CPU, load, memory, disk, network, processes, `stalls`: the last hour's main-thread stalls by route or `job:<name>` as {cause, ms, count}, and `readers`: who polls the telemetry and how fast; a forge admin, or an agent granted `telemetry:read`. `{ kind: \"csp\" }`: the last 24 h of Content-Security-Policy violations browsers reported, `{ directive, n, newest }` per directive (`newest` the blocked host last counted), most first, counted per UTC hour from `since`, as the security page reads them; a forge admin only",
12 doc: "the machine the forge runs on, now: CPU, load, memory, disk, network, processes, `stalls`: the last hour's main-thread stalls by route or `job:<name>` as {cause, ms, count}, `readings`: the last 20 minutes' worst loop lag as {at, ms, what} beside `barMs` (100) and `over`, and `readers`: who polls the telemetry and how fast; a forge admin, or an agent granted `telemetry:read`. `{ kind: \"csp\" }`: the last 24 h of Content-Security-Policy violations browsers reported, `{ directive, n, newest }` per directive (`newest` the blocked host last counted), most first, counted per UTC hour from `since`, as the security page reads them; a forge admin only",
1213 description:
1314 "The forge machine now: CPU, memory, disk, network. Admin or telemetry:read; `kind: csp`: 24 h of CSP violations (admin).",
1415 inputSchema: { type: "object", properties: { kind: { type: "string", enum: ["csp"] } } },
@@ -29,6 +30,9 @@ export const tool: Tool = {
2930 const stalls = stallHour(loopWatch.tally(performance.now()))
3031 .slice(0, TOP_ROUTES)
3132 .map((r) => ({ cause: r.route, ms: Math.round(r.ms), count: r.count }));
32 return good({ ...out, stalls });
33 // The same 20 minutes /system draws (#11220); `what` is null when no stall past 200 ms was named.
34 const rows = lagMinutes.readings();
35 const readings = rows.map((r) => ({ at: new Date(r.at).toISOString(), ms: Math.round(r.ms * 10) / 10, what: r.what }));
36 return good({ ...out, stalls, barMs: LAG_BAR_MS, over: overBar(rows), readings });
3337 },
3438 };
src/main.ts +2 −1
@@ -108,7 +108,7 @@ import { watchStalls } from "./kernel/loop_lag.ts";
108108 import { startPerfWatcher, TICK_MS } from "./perf/duty.ts";
109109 import { during } from "./perf/jobs.ts";
110110 import { stallLine } from "./perf/loop.ts";
111 import { bootStall, gitRecord, loopWatch, perfRecord, stallBlame } from "./perf/live.ts";
111 import { bootStall, gitRecord, lagMinutes, loopWatch, perfRecord, stallBlame } from "./perf/live.ts";
112112 import { timeStatements } from "./kernel/slow_sql.ts";
113113 import { waitForPeer } from "./runs/peer.ts";
114114 import { closeStaleSessions } from "./machines/shell.ts";
@@ -240,6 +240,7 @@ if (parentProblem !== null) {
240240 const loopLog = createLog("loop");
241241 watchStalls(loopLog, undefined, undefined, undefined, (late, at) => {
242242 bootStall.note(late, at);
243 lagMinutes.note(late, at);
243244 const stall = loopWatch.stalled(late, at);
244245 if (stall === null) return;
245246 loopLog.warn(stallLine(stall));
src/perf/lag_minutes.ts added +107
@@ -0,0 +1,107 @@
1 /**
2 * The last 20 one-minute worst loop-lag readings (#11220), so /system and the
3 * MCP `system` tool show by eye whether the forge's idle `forge-lag` holds
4 * under the 100 ms bar, without reading `/healthz` by hand.
5 *
6 * Fed by the same lag sampler as the boot stall and the loop watch (main.ts,
7 * `kernel/loop_lag.ts`, a wake every 50 ms): each wake's lateness is folded
8 * into the current minute's worst — a division, a compare and a store, no
9 * allocation. When a wake lands in a new minute the old one is closed into a
10 * fixed ring of `LAG_READINGS`: once a minute, its worst ms, the wall time it
11 * began, and what it is blamed on — the worst stall `stallBlame` named in that
12 * minute (the same name `/healthz` calls `loopWorstWhat`), or null when no
13 * wake in it passed the 200 ms stall limit (`loop.ts`), so nothing was named.
14 *
15 * A minute the sampler never woke in (a suspended process) is not a reading:
16 * the ring holds the last 20 minutes that were measured, oldest first.
17 */
18
19 /** How many closed minutes the ring keeps. */
20 export const LAG_READINGS = 20;
21 /** The bar a minute's worst lag is held to, ms: over it is a miss (#11119). */
22 export const LAG_BAR_MS = 100;
23 /** One reading's span, ms. */
24 export const LAG_MINUTE_MS = 60_000;
25
26 export interface LagReading {
27 /** When the minute began, wall clock ms since the epoch. */
28 readonly at: number;
29 /** The worst wake lateness in that minute, ms. */
30 readonly ms: number;
31 /** The route, `job:<name>` or `unknown` the minute's worst named stall ran under; null when none was named. */
32 readonly what: string | null;
33 }
34
35 /** What ran under the worst named stall in `(to - spanMs, to]`, on the sampler's clock; null for none. */
36 export type MinuteBlame = (to: number, spanMs: number) => string | null;
37
38 export interface LagMinutes {
39 /** A wake `lateMs` late at `at` (ms, the sampler's monotonic clock). O(1), allocates nothing until a minute closes. */
40 note(lateMs: number, at: number): void;
41 /** The closed minutes, oldest first; at most `LAG_READINGS`. */
42 readings(): LagReading[];
43 /** Forget every reading and the open minute. */
44 clear(): void;
45 }
46
47 /** How many readings are over the bar (strictly: exactly 100 ms holds it). */
48 export const overBar = (rows: readonly LagReading[], barMs = LAG_BAR_MS): number =>
49 rows.reduce((n, r) => (r.ms > barMs ? n + 1 : n), 0);
50
51 /**
52 * `mono` and `wall` are one instant on the sampler's clock and the wall clock,
53 * read when a minute closes, so a minute that began at `start` (mono) began at
54 * `wall - (mono - start)`.
55 */
56 export function createLagMinutes(
57 blame: MinuteBlame = () => null,
58 wall: () => number = () => Date.now(),
59 kept = LAG_READINGS,
60 minuteMs = LAG_MINUTE_MS,
61 ): LagMinutes {
62 const n = Math.max(1, Math.floor(kept));
63 const at = new Float64Array(n);
64 const ms = new Float64Array(n);
65 const what: (string | null)[] = new Array<string | null>(n).fill(null);
66 let next = 0;
67 let count = 0;
68 // The open minute: its index (floor(at / minuteMs)), -1 for none, and its worst.
69 let minute = -1;
70 let worst = 0;
71 const close = (mono: number) => {
72 const start = minute * minuteMs;
73 at[next] = wall() - (mono - start);
74 ms[next] = worst;
75 what[next] = blame(start + minuteMs, minuteMs);
76 next = (next + 1) % n;
77 if (count < n) count++;
78 };
79 return {
80 note(lateMs, now) {
81 if (!Number.isFinite(lateMs) || lateMs < 0 || !Number.isFinite(now)) return;
82 const m = Math.floor(now / minuteMs);
83 if (m === minute) {
84 if (lateMs > worst) worst = lateMs;
85 return;
86 }
87 if (m < minute) return; // a clock that stepped back: keep the open minute
88 if (minute >= 0) close(now);
89 minute = m;
90 worst = lateMs;
91 },
92 readings() {
93 const out: LagReading[] = [];
94 for (let k = 0; k < count; k++) {
95 const i = (next - count + k + n) % n;
96 out.push({ at: at[i]!, ms: ms[i]!, what: what[i]! });
97 }
98 return out;
99 },
100 clear() {
101 next = 0;
102 count = 0;
103 minute = -1;
104 worst = 0;
105 },
106 };
107 }
src/perf/live.ts +6
@@ -8,6 +8,7 @@ import { createCaptureStore } from "./capture.ts";
88 import { createReadLedger } from "./reads.ts";
99 import { createStallBlame } from "./stall_blame.ts";
1010 import { createPerfRecord } from "./record.ts";
11 import { createLagMinutes } from "./lag_minutes.ts";
1112
1213 export const perfRecord = createPerfRecord();
1314 /** A stall no request ran across names the background jobs that did (#10834). */
@@ -20,3 +21,8 @@ export const readLedger = createReadLedger();
2021 export const captureStore = createCaptureStore();
2122 /** Each stall over 200 ms with what ran (#11069): the last hour's worst on /system, the last 10 s's on `/healthz`. */
2223 export const stallBlame = createStallBlame();
24 /**
25 * The last 20 minutes' worst loop lag (#11220), each blamed on the worst stall
26 * `stallBlame` named in it: /system and the MCP `system` tool read it.
27 */
28 export const lagMinutes = createLagMinutes((to, span) => stallBlame.worst(to, span, 1)[0]?.what ?? null);
src/tui/screens/loopstalls.ts +45 −6
@@ -4,12 +4,16 @@
44 * /api/v1/telemetry/flow always listed — the rows `/system` and `/metrics`
55 * read (`stallHour`); then, as /system draws them (#11069), the last hour's
66 * worst single stalls — what ran, its ms, and when, in UTC — only when there
7 * is one. The gate is `/system`'s: a forge admin who is a person. Read-only.
7 * is one. Above them, as /system draws it (#11220), the last 20 minutes'
8 * worst loop lag against the 100 ms bar: how many are over, then each minute,
9 * its ms, "over" when past the bar, and what its worst named stall ran under.
10 * The gate is `/system`'s: a forge admin who is a person. Read-only.
811 */
912
1013 import { stallHour } from "../../metrics/stalls.ts";
1114 import { HOUR_MS, type RouteStall } from "../../perf/loop.ts";
12 import { loopWatch, stallBlame } from "../../perf/live.ts";
15 import { lagMinutes, loopWatch, stallBlame } from "../../perf/live.ts";
16 import { LAG_BAR_MS, LAG_READINGS, overBar, type LagReading } from "../../perf/lag_minutes.ts";
1317 import { WORST_STALLS, type BlamedStall } from "../../perf/stall_blame.ts";
1418 import type { Ctx, Screen } from "../app/app.ts";
1519 import { binding } from "../app/keys.ts";
@@ -61,6 +65,42 @@ export function stallLines(
6165 ];
6266 }
6367
68 /**
69 * The loop-lag readings as /system's "Loop lag" section reads them: a header
70 * with the count over the 100 ms bar, then a minute a row, oldest first, its
71 * start in UTC, its worst ms, `over` when strictly past the bar, and what ran
72 * (or "not named"). Empty for anyone the gate refuses.
73 */
74 export function lagLines(session: Session, rows: readonly LagReading[] = lagMinutes.readings()): string[] {
75 if (!mayRead(session)) return [];
76 const head = `Loop lag, last ${String(LAG_READINGS)} minutes`;
77 if (rows.length === 0) return [head, "No full minute measured yet."];
78 const over = overBar(rows);
79 const tally = over === 0 ? `all ${String(rows.length)} under ${String(LAG_BAR_MS)} ms` : `${String(over)} of ${String(rows.length)} over ${String(LAG_BAR_MS)} ms`;
80 return [
81 `${head}: ${tally}`,
82 `${pad("Minute (UTC)", 14)}${pad("Worst ms", 10, "right")}${pad("", 6)}What ran`,
83 ...rows.map((r) => {
84 const isOver = r.ms > LAG_BAR_MS;
85 return `${pad(`${new Date(r.at).toISOString().slice(11, 16)}`, 14)}${pad(String(Math.round(r.ms)), 10, "right")}${pad(isOver ? " over" : "", 6)}${r.what ?? "not named"}`;
86 }),
87 ];
88 }
89
90 /** Everything the screen draws: the loop lag, a blank line, then the stalls; with the header rows' indexes. */
91 function screenLines(session: Session): { lines: string[]; heads: Set<number> } {
92 const lag = lagLines(session);
93 const stalls = stallLines(session);
94 const lines = lag.length === 0 ? stalls : [...lag, "", ...stalls];
95 const base = lag.length === 0 ? 0 : lag.length + 1;
96 const heads = new Set<number>();
97 if (lag.length > 0) heads.add(0);
98 if (stalls.length > 0) heads.add(base);
99 const worstGap = stalls.indexOf("");
100 if (worstGap >= 0) heads.add(base + worstGap + 1);
101 return { lines, heads };
102 }
103
64104 export function stallsScreen(session: Session, ctx: Ctx): Screen {
65105 const scroll = new Scroll();
66106 return {
@@ -68,14 +108,13 @@ export function stallsScreen(session: Session, ctx: Ctx): Screen {
68108 keys: [binding(["j", "k"], "scroll"), binding(["esc", "q"], "back")],
69109 render(area, s) {
70110 const c = ctx.theme.c;
71 const lines = stallLines(session);
72 const worstHead = lines.indexOf("") + 1; // 0 when there is no worst list
73 const spans = lines.map((text, i) => [{ text, style: style(i === 0 || i === worstHead ? c.fg : c.mutedFg, c.bg) }]);
111 const { lines, heads } = screenLines(session);
112 const spans = lines.map((text, i) => [{ text, style: style(heads.has(i) ? c.fg : c.mutedFg, c.bg) }]);
74113 drawLines(s, area, c, scroll, spans);
75114 hitScroll(ctx, area, scroll, lines.length);
76115 },
77116 key(e) {
78 if (scroll.key(e, stallLines(session).length)) return true;
117 if (scroll.key(e, screenLines(session).lines.length)) return true;
79118 if (e.key === "esc" || e.key === "q") {
80119 ctx.pop();
81120 return true;
src/web/pages/system.ts +27 −1
@@ -12,6 +12,8 @@
1212 * Between them, the main-thread stalls of the last hour by route (#9016),
1313 * read once at first paint from the loop watch: the top routes plus
1414 * /api/v1/telemetry/flow always, as /metrics exports them.
15 * Just above the stalls, the last 20 minutes' worst loop lag against the
16 * 100 ms bar (#11220, `perf/lag_minutes.ts`), each minute over it named.
1517 * Then the in-process caches that answer strangers' code pages (#9514), each
1618 * with its entries, bytes held beside its cap, and hits and misses: together
1719 * they may hold ~128 MB, so what they hold is shown where memory is.
@@ -31,7 +33,8 @@ import { readerPaces, type ReaderPace } from "../../system/telemetry_reads.ts";
3133 import { slowPageLine, slowPages, type SlowPage } from "../../perf/watch.ts";
3234 import { stallHour } from "../../metrics/stalls.ts";
3335 import { HOUR_MS, type RouteStall } from "../../perf/loop.ts";
34 import { loopWatch, stallBlame } from "../../perf/live.ts";
36 import { lagMinutes, loopWatch, stallBlame } from "../../perf/live.ts";
37 import { LAG_BAR_MS, LAG_READINGS, overBar, type LagReading } from "../../perf/lag_minutes.ts";
3538 import { WORST_STALLS, type BlamedStall } from "../../perf/stall_blame.ts";
3639 import { notePhase, takeSessionTime, timePhase } from "../../core/route_timing.ts";
3740 import { notFoundPage, signInFirst } from "../chrome.ts";
@@ -228,6 +231,28 @@ export function worstStallsTable(rows: readonly BlamedStall[], nowMono: number,
228231 </table></div>`;
229232 }
230233
234 /**
235 * The last 20 minutes' worst loop lag against the 100 ms bar (#11220): how many
236 * are over it, then one row a minute, oldest first — its worst ms, and what its
237 * worst named stall ran under (`loopWorstWhat`'s name), or "not named" when no
238 * wake in it passed the 200 ms stall limit. A row over the bar is marked.
239 */
240 export function lagSection(rows: readonly LagReading[]): Html {
241 const over = overBar(rows);
242 return html`<div id="sys-lag" data-readings="${String(rows.length)}" data-over="${String(over)}"><section class="settings-block"><h2>Loop lag, last ${String(LAG_READINGS)} minutes</h2>${
243 rows.length === 0
244 ? html`<p class="muted">No full minute measured yet.</p>`
245 : html`<div class="row-meta">${over === 0 ? badge(`all ${String(rows.length)} under ${String(LAG_BAR_MS)} ms`) : badge(`${String(over)} of ${String(rows.length)} over ${String(LAG_BAR_MS)} ms`, { tone: "danger" })}</div>
246 <div class="table-scroll"><table class="table" aria-label="Worst loop lag each minute against the ${String(LAG_BAR_MS)} ms bar">
247 <thead><tr><th scope="col">Minute</th><th scope="col" class="num">Worst ms</th><th scope="col">What ran</th></tr></thead>
248 <tbody>${rows.map((r) => {
249 const isOver = r.ms > LAG_BAR_MS;
250 return html`<tr data-lag-over="${isOver ? "1" : "0"}"><td>${time(new Date(r.at).toISOString())}</td><td class="num mono">${String(Math.round(r.ms))}${isOver ? html` ${badge("over", { tone: "danger" })}` : null}</td><td class="mono">${r.what ?? html`<span class="muted">not named</span>`}</td></tr>`;
251 })}</tbody>
252 </table></div>`
253 }</section></div>`;
254 }
sentinelcrew outdated

Principle 7: the over-minutes are drawn twice, once as bars and again as a table. Keep the one that shows the rows; and the terminal door is missing (see body).
255
231256 const SLOW_TTL_MS = 5000;
232257 let slowKept: { db: object; at: number; rows: SlowPage[] } | undefined;
233258 /** `slowPages`, kept a few seconds so a busy /system never repeats the query; changes show on reload. */
@@ -377,6 +402,7 @@ export async function systemPage(ctx: Ctx): Promise<Response> {
377402 <button class="btn" data-size="sm" type="button" data-sort="mem" aria-pressed="false"><kbd>m</kbd> memory</button></div>
378403 <div id="sys-procs">${at("sys-procs")}</div></section>
379404 ${featuresSection(timePhase(ctx.request, "features", () => featureHealth(ctx.app, reader)))}
405 ${lagSection(lagMinutes.readings())}
380406 <div id="sys-stalls">${stallSection(stalls, worstStallsTable(worst, nowMono, Date.now()))}</div>
381407 <div id="sys-slow-pages">${slowPagesSection(timePhase(ctx.request, "slowpages", () => slowPagesCached(ctx.app.db)))}</div>
382408 <div id="sys-readers">${readersSection(readerPaces())}</div>
test/loop-stall-by-route.test.ts +40 −2
@@ -11,14 +11,15 @@ import { serve, type Servers } from "../src/http/server.ts";
1111 import { watchStalls } from "../src/kernel/loop_lag.ts";
1212 import { openMetrics } from "../src/metrics/openmetrics.ts";
1313 import { stallFamilies, TOP_ROUTES } from "../src/metrics/stalls.ts";
14 import { loopWatch, stallBlame } from "../src/perf/live.ts";
14 import { lagMinutes, loopWatch, stallBlame } from "../src/perf/live.ts";
1515 import { WORST_STALLS } from "../src/perf/stall_blame.ts";
1616 import { createLoopWatch, HOUR_MS, NO_REQUEST } from "../src/perf/loop.ts";
1717 import { createAgent } from "../src/actions/crew.ts";
1818 import type { User } from "../src/core/users.ts";
1919 import { stallSection } from "../src/web/pages/system.ts";
2020 import { createForgeApp, forgeCommands, Session } from "../src/tui/forge.ts";
21 import { stallLines } from "../src/tui/screens/loopstalls.ts";
21 import { lagLines, stallLines, stallsScreen } from "../src/tui/screens/loopstalls.ts";
22 import { settleApp } from "./helpers/tui.ts";
2223 import { headlessTerminal } from "../src/tui/term/terminal.ts";
2324 import { quietLogs } from "./helpers/globals.ts";
2425 import { freshStallState } from "./helpers/stall-state.ts";
@@ -232,3 +233,40 @@ test("the Stalls screen reads the process's stall blame by default, the five /sy
232233 expect(stallBlame.worst(performance.now(), HOUR_MS, WORST_STALLS).map((s) => s.what)).toEqual(named);
233234 stallBlame.clear();
234235 });
236
237 test("the Stalls screen shows the last 20 minutes' loop lag as /system does: over count, each minute, what ran (#11220)", async () => {
238 const at = (m: number) => Date.parse(`2026-11-11T09:0${String(m)}:00Z`);
239 const rows = [
240 { at: at(0), ms: 12.4, what: null },
241 { at: at(1), ms: 340.2, what: "/<owner>/<repo>/pulls" },
242 { at: at(2), ms: 100, what: null }, // exactly the bar holds it
243 { at: at(3), ms: 140.6, what: null },
244 ];
245 const lines = lagLines(new Session(app, identity(alice)), rows);
246 expect(lines[0]).toBe("Loop lag, last 20 minutes: 2 of 4 over 100 ms");
247 expect(lines[1]).toMatch(/^Minute \(UTC\)\s+Worst ms\s+What ran$/);
248 expect(lines[2]).toMatch(/^09:00\s+12\s+not named$/);
249 expect(lines[3]).toMatch(/^09:01\s+340\s+over\s*\/<owner>\/<repo>\/pulls$/);
250 expect(lines[4]).toMatch(/^09:02\s+100\s+not named$/);
251 expect(lines[5]).toMatch(/^09:03\s+141\s+over\s*not named$/);
252 expect(lines).toHaveLength(6);
253 expect(lagLines(new Session(app, identity(alice)), rows.slice(0, 1))[0]).toBe("Loop lag, last 20 minutes: all 1 under 100 ms");
254 expect(lagLines(new Session(app, identity(alice)), [])).toEqual(["Loop lag, last 20 minutes", "No full minute measured yet."]);
255 for (const who of [bob, bot, undefined]) expect(lagLines(new Session(app, identity(who)), rows)).toEqual([]);
256
257 // The screen itself draws the process's readings above the stalls.
258 lagMinutes.clear();
259 lagMinutes.note(250, 0);
260 lagMinutes.note(0, 60_000); // closes the first minute
261 const { app: tui, session } = createForgeApp(app, identity(alice), { terminal: headlessTerminal(120, 40), exitHooks: false });
262 tui.start();
263 await settleApp(tui);
264 tui.push(stallsScreen(session, tui.ctx));
265 await settleApp(tui);
266 const shown = tui.screen.toText();
267 tui.stop();
268 lagMinutes.clear();
269 expect(shown).toContain("Loop lag, last 20 minutes: 1 of 1 over 100 ms");
270 expect(shown).toContain("Route (last hour)");
271 expect(shown.indexOf("Loop lag")).toBeLessThan(shown.indexOf("Route (last hour)"));
272 });
test/perf-lag-minutes.test.ts added +149
@@ -0,0 +1,149 @@
1 /**
2 * The last 20 one-minute worst loop-lag readings (#11220): the ring keeps 20,
3 * the oldest falls off, the over-the-bar count is right, each minute is named
4 * by the worst stall blamed in it, /system draws them against the 100 ms bar
5 * and the MCP `system` tool answers the same readings.
6 */
7 import { afterAll, beforeAll, describe, expect, test } from "bun:test";
8 import { mkdtemp, rm } from "node:fs/promises";
9 import { tmpdir } from "node:os";
10 import { join } from "node:path";
11 import { createApp, type App } from "../src/app.ts";
12 import { createToken } from "../src/core/tokens.ts";
13 import { createUser } from "../src/core/users.ts";
14 import { serve, type Servers } from "../src/http/server.ts";
15 import { createLagMinutes, LAG_BAR_MS, LAG_MINUTE_MS, LAG_READINGS, overBar } from "../src/perf/lag_minutes.ts";
16 import { lagMinutes } from "../src/perf/live.ts";
17 import { lagSection } from "../src/web/pages/system.ts";
18 import { quietLogs } from "./helpers/globals.ts";
19
20 quietLogs();
21
22 const MIN = LAG_MINUTE_MS;
23
24 describe("the ring of minutes", () => {
25 test("is 20 minutes against a 100 ms bar", () => {
26 expect(LAG_READINGS).toBe(20);
27 expect(LAG_BAR_MS).toBe(100);
28 expect(MIN).toBe(60_000);
29 });
30
31 test("a minute's reading is its worst wake, closed by the first wake of the next", () => {
32 const ring = createLagMinutes(() => null, () => 0);
33 ring.note(3, 0);
34 ring.note(40, 10_000);
35 ring.note(7, 59_999);
36 expect(ring.readings()).toEqual([]); // the open minute is not a reading
37 ring.note(1, MIN);
38 expect(ring.readings().map((r) => r.ms)).toEqual([40]);
39 });
40
41 test("filled past 20, the oldest falls off and the over count is right", () => {
42 const ring = createLagMinutes();
43 // 25 minutes, minute k's worst k * 10 ms: 0, 10, …, 240. The 26th wake closes the 25th.
44 for (let k = 0; k <= 25; k++) {
45 ring.note(k * 10, k * MIN + 5);
46 ring.note(k * 5, k * MIN + 30_000);
47 }
48 const rows = ring.readings();
49 expect(rows).toHaveLength(20);
50 // Minutes 0–4 fell off; 5–24 remain, oldest first.
51 expect(rows.map((r) => r.ms)).toEqual(Array.from({ length: 20 }, (_, i) => (i + 5) * 10));
52 // Over 100 ms (strictly): 110, 120, …, 240 → minutes 11–24, 14 of them. 100 itself holds the bar.
53 expect(overBar(rows)).toBe(14);
54 expect(rows.some((r) => r.ms === 100)).toBe(true);
55 });
56
57 test("each minute is named by the blame for its own span, read once as it closes", () => {
58 const asked: [number, number][] = [];
59 const ring = createLagMinutes((to, span) => {
60 asked.push([to, span]);
61 return to === 2 * MIN ? "job:snapshot" : null;
62 }, () => 1_000_000);
63 ring.note(10, 0);
64 ring.note(250, MIN + 10);
65 for (let t = MIN + 50; t < 2 * MIN; t += 50) ring.note(1, t); // ticks inside a minute ask nothing
66 ring.note(5, 2 * MIN + 20);
67 expect(asked).toEqual([[MIN, MIN], [2 * MIN, MIN]]);
68 const rows = ring.readings();
69 expect(rows.map((r) => r.what)).toEqual([null, "job:snapshot"]);
70 // A minute began `wall − (mono − start)`: closed at mono 2·MIN+20 when the wall read 1,000,000.
71 expect(rows[1]!.at).toBe(1_000_000 - (2 * MIN + 20 - MIN));
72 });
73
74 test("a bad reading or a clock stepping back changes nothing", () => {
75 const ring = createLagMinutes();
76 ring.note(30, 5 * MIN);
77 ring.note(Number.NaN, 5 * MIN + 1);
78 ring.note(-4, 5 * MIN + 2);
79 ring.note(900, 4 * MIN);
80 ring.note(0, 6 * MIN);
81 expect(ring.readings().map((r) => r.ms)).toEqual([30]);
82 ring.clear();
83 expect(ring.readings()).toEqual([]);
84 });
85 });
86
87 describe("drawn on /system", () => {
88 test("the count over the bar, and each minute over it named", () => {
89 const rows = [
90 { at: Date.UTC(2026, 10, 11, 9, 0), ms: 12, what: null },
91 { at: Date.UTC(2026, 10, 11, 9, 1), ms: 340, what: "/<owner>/<repo>/pulls" },
92 { at: Date.UTC(2026, 10, 11, 9, 2), ms: 140, what: null },
93 ];
94 const text = lagSection(rows).text;
95 expect(text).toContain('data-readings="3"');
96 expect(text).toContain('data-over="2"');
97 expect(text).toContain("2 of 3 over 100 ms");
98 expect(text).toContain("/&lt;owner&gt;/&lt;repo&gt;/pulls"); // escaped
99 expect(text).toContain("not named");
100 // One table: every minute a row, the two over the bar marked, no second view of them.
101 expect(text.match(/<tr data-lag-over=/g)?.length).toBe(3);
102 expect(text.match(/data-lag-over="1"/g)?.length).toBe(2);
103 expect(text).not.toContain("<svg");
104 expect(lagSection(rows.slice(0, 1)).text).toContain("all 1 under 100 ms");
105 expect(lagSection([]).text).toContain("No full minute measured yet.");
106 });
107 });
108
109 describe("the MCP system tool", () => {
110 let dataDir = "";
111 let app: App;
112 let servers: Servers;
113 let token = "";
114
115 beforeAll(async () => {
116 dataDir = await mkdtemp(join(tmpdir(), "forge-lag-minutes-"));
117 app = createApp({ dataDir, port: 0 });
118 servers = await serve(app);
119 const u = await createUser(app.db, { origin: "seed", trusted: true, username: "alice", email: "[email protected]", password: "correct horse battery 9", isAdmin: true });
120 if (!u.ok) throw new Error("alice");
121 token = createToken(app.db, u.value.id, "t", "admin").token;
122 }, 30_000);
123
124 afterAll(async () => {
125 lagMinutes.clear();
126 servers.stop();
127 app.close();
128 await rm(dataDir, { recursive: true, force: true });
129 });
130
131 test("answers the same readings as {at, ms, what}, with the bar and the count over it", async () => {
132 lagMinutes.clear();
133 const base = 1_000 * MIN;
134 lagMinutes.note(20, base);
135 lagMinutes.note(180.04, base + MIN);
136 lagMinutes.note(1, base + 2 * MIN);
137 const res = await fetch(`${servers.url}/mcp`, {
138 method: "POST",
139 headers: { "content-type": "application/json", accept: "application/json, text/event-stream", authorization: `Bearer ${token}` },
140 body: JSON.stringify({ jsonrpc: "2.0", id: 1, method: "tools/call", params: { name: "system", arguments: {} } }),
141 });
142 const out = JSON.parse(((await res.json()) as any).result.content[0].text);
143 expect(out.barMs).toBe(100);
144 expect(out.over).toBe(1);
145 expect(out.readings.map((r: any) => r.ms)).toEqual([20, 180]);
146 expect(out.readings.map((r: any) => r.what)).toEqual([null, null]);
147 for (const r of out.readings) expect(new Date(r.at).toISOString()).toBe(r.at);
148 });
149 });
test/system-parts.test.ts +2 −1
@@ -52,13 +52,14 @@ test("one <h2> per part, each in a settings-block, and no card", async () => {
5252 "Machine",
5353 "Disks and network",
5454 "Processes",
55 "Loop lag, last 20 minutes",
5556 "Main-thread stalls, last hour",
5657 "Telemetry readers",
5758 "Code page caches, since start",
5859 "Forge memory",
5960 ]);
6061 expect(main.match(/<section class="settings-block"/g)?.length).toBe(heads.length);
61 for (const id of ["sys-dup", "summary", "cores", "mem", "temps", "sys-disks", "sys-procs", "sys-stalls", "sys-readers", "sys-caches"]) {
62 for (const id of ["sys-dup", "summary", "cores", "mem", "temps", "sys-disks", "sys-procs", "sys-lag", "sys-stalls", "sys-readers", "sys-caches"]) {
6263 expect(main).toContain(`id="${id}"`);
6364 }
6465 expect(main).toMatch(/<section class="settings-block"><h2>Disks and network<\/h2>\s*<ul class="list" id="sys-disks">/);

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs