41318be · 6022f3c · b61e20a · 6e70370
@@ -19,6 +19,8 @@
State shared between modules through process memory, not the database, is named
`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.
`src/perf/stall_blame.ts` (`stallBlame` in `src/perf/live.ts`): each loop stall over 200 ms as `{ what, ms, at }` in a fixed ring of 256, fed by `main.ts`'s stall watcher after `loopWatch` names it, read by /system's worst-five card and `/healthz`'s `loopWorstWhat`.
`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.
`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).
@@ -23,7 +23,7 @@
not an admin, 200 for an admin's `ro` token. It is never cached
| `forge_ask_to_live_seconds` | histogram | none (plus `le`) | Seconds from an issue opening to the first successful release of a pull that closes it. Buckets: 1 m, 5 m, 15 m, 1 h, 4 h, 12 h, 1 d, 3 d, 7 d. |
| `forge_main_red_seconds_total` | counter | `repo` | Seconds the default branch's check spent failing: from a failed check to the next green one, or to now while still red. |
| `forge_telemetry_reads_total` | counter | `route`, `reader` | Reads of `/api/v1/telemetry` routes since the process started, by route and reader; the rate is the slope. The owner's `/system` page names each reader's pace over the last 10 minutes. |
| `forge_loop_stall_milliseconds_total` | counter | `route` | Milliseconds the main thread stalled past 250 ms since the process started, charged in full to every route pattern running across the stall (`none` when no request was). |
| `forge_loop_stall_milliseconds_total` | counter | `route` | Milliseconds the main thread stalled past 200 ms since the process started, charged in full to every route pattern running across the stall (`none` when no request was). |
| `forge_loop_stalls_total` | counter | `route` | Those stalls, counted the same way. |
| `forge_loop_stall_hour_milliseconds` | gauge | `route` | Stall milliseconds in the last hour: the top 10 routes, most first, plus `/api/v1/telemetry/flow` always (0 when it stalled nothing). |
| `forge_loop_stall_hour_count` | gauge | `route` | Stalls in the last hour, for the routes the gauge above lists. |
@@ -1,6 +1,6 @@
# Main-thread stalls by route (#9016)
The forge counts every wake of its event loop more than 250 ms late as a
The forge counts every wake of its event loop more than 200 ms late as a
stall, and charges it in full to each route pattern whose request ran across
it (`none` when no request did) — the same reading as the `event loop blocked`
log lines (`src/perf/loop.ts`), so a fix's before and after reads from the
@@ -12,7 +12,14 @@
palette entry):
- **`/system`**, the "Main-thread stalls, last hour" card: route, stall ms and
  count for the top 10 routes, most first, plus `/api/v1/telemetry/flow`
  always (0 when it stalled nothing). As of the page's load.
- **The terminal**: `:` → "Main-thread stalls", the same rows.
- **`/system`**, inside that card, "Worst single stalls" (#11069), drawn only
  when the hour had one: the five worst single stalls, each with what ran (the route pattern, `job:<name>` for a job
  marked with `jobWatch.during`, or `unknown`), its ms and when. Kept in a
  fixed ring of 256 (`src/perf/stall_blame.ts`).
- **`/healthz`** with `Accept: application/json`: beside `loopLagMs`,
  `loopWorstWhat` names the worst stall of the same 10 s (null when none).
- **The terminal**: `:` → "Main-thread stalls", the same rows, then the same
  worst single stalls (what ran, ms, when in UTC) when the hour had one.
- **`GET /metrics`** (an admin `ro` token): `forge_loop_stall_milliseconds_total`
  and `forge_loop_stalls_total` by `route` since the process started, and the
  last hour as `forge_loop_stall_hour_milliseconds` / `forge_loop_stall_hour_count`
@@ -90,10 +90,17 @@
export function startDraining(log: Log, why: string, fields: Record<string, numb
 *
 * Given `loopLagMs` (the caller asked for JSON), the 200 is
 * `{"ok":true,"loopLagMs":n}`: the worst event-loop lag of the last 10 s
 * (`perf/loop_worst.ts`, #10288). Otherwise it stays the plain `ok` a
 * probe and a stranger hear (#2917).
 * (`perf/loop_worst.ts`, #10288), with `loopWorstWhat`: the route pattern,
 * `job:<name>` or `unknown` the worst stall over 200 ms in those 10 s was
 * blamed on, null when there was none (`perf/stall_blame.ts`, #11069).
 * Otherwise it stays the plain `ok` a probe and a stranger hear (#2917).
 */
export function liveResponse(ping: () => unknown, log: Log, loopLagMs?: number): Response {
export function liveResponse(
  ping: () => unknown,
  log: Log,
  loopLagMs?: number,
  loopWorstWhat: string | null = null,
): Response {
  try {
    ping();
  } catch (error) {
@@ -107,7 +114,10 @@
export function liveResponse(ping: () => unknown, log: Log, loopLagMs?: number):
  if (databaseDown) log.info("forge alive again: the database answers");
  databaseDown = false;
  if (loopLagMs !== undefined && Number.isFinite(loopLagMs))
    return Response.json({ ok: true, loopLagMs: Math.round(loopLagMs * 10) / 10 }, { status: 200 });
    return Response.json(
      { ok: true, loopLagMs: Math.round(loopLagMs * 10) / 10, loopWorstWhat },
      { status: 200 },
    );
  return new Response("ok", { status: 200 });
}
@@ -507,7 +507,7 @@
import {
  takeDbTime,
  type RouteTiming,
} from "../core/route_timing.ts";
import { captureStore, loopWatch, perfRecord, readLedger } from "../perf/live.ts";
import { captureStore, loopWatch, perfRecord, readLedger, stallBlame } from "../perf/live.ts";
import { during } from "../perf/jobs.ts";
import { classOf, countryOf, repoOf, signatureOf } from "../perf/traffic.ts";
import { createTrafficWriter } from "../perf/traffic_store.ts";
@@ -519,7 +519,7 @@
import { statementPage } from "../web/pages/statement.ts";
import { createViewWriter } from "../perf/views_store.ts";
import { createReadWriter, readOf } from "../perf/reads.ts";
import { parseServerTiming } from "../perf/record.ts";
import { currentLoopLag, startLoopWorst } from "../perf/loop_worst.ts";
import { currentLoopLag, LAG_WINDOW_MS, startLoopWorst } from "../perf/loop_worst.ts";
import { methodOf, noteUsage, roleOf, surfaceOf, takeUsage } from "./usage_tag.ts";
import { bearerChallenge, oauthRoutes } from "./oauth.ts";
import { flushAccess, recordAccess } from "./access_log.ts";
@@ -2829,6 +2829,7 @@
async function answerGet(
      () => app.db.query("select 1").get(),
      app.log,
      wantsJson ? currentLoopLag() : undefined,
      wantsJson ? (stallBlame.worst(performance.now(), LAG_WINDOW_MS, 1)[0]?.what ?? null) : null,
    );
    noteDbTime(request, performance.now() - dbStart);
    // The release proof learns which release answered, old pod or new; a
@@ -108,7 +108,7 @@
import { watchStalls } from "./kernel/loop_lag.ts";
import { startPerfWatcher, TICK_MS } from "./perf/duty.ts";
import { during } from "./perf/jobs.ts";
import { stallLine } from "./perf/loop.ts";
import { bootStall, gitRecord, loopWatch, perfRecord } from "./perf/live.ts";
import { bootStall, gitRecord, loopWatch, perfRecord, stallBlame } from "./perf/live.ts";
import { timeStatements } from "./kernel/slow_sql.ts";
import { waitForPeer } from "./runs/peer.ts";
import { closeStaleSessions } from "./machines/shell.ts";
@@ -241,7 +241,9 @@
const loopLog = createLog("loop");
watchStalls(loopLog, undefined, undefined, undefined, (late, at) => {
  bootStall.note(late, at);
  const stall = loopWatch.stalled(late, at);
  if (stall !== null) loopLog.warn(stallLine(stall));
  if (stall === null) return;
  loopLog.warn(stallLine(stall));
  stallBlame.note(stall);
});
const previewKey = previewIdentityKey(process.env);
@@ -30,13 +30,13 @@
export function stallFamilies(tally: StallTally): Family[] {
    {
      type: "counter",
      name: "forge_loop_stall_milliseconds_total",
      help: "Milliseconds the main thread stalled past 250 ms, by the route running across the stall (route=\"none\" when none), since the process started.",
      help: "Milliseconds the main thread stalled past 200 ms, by the route running across the stall (route=\"none\" when none), since the process started.",
      samples: tally.total.map((r) => ({ labels: { route: r.route }, value: Math.round(r.ms) })),
    },
    {
      type: "counter",
      name: "forge_loop_stalls_total",
      help: "Main-thread stalls past 250 ms, by the route running across the stall, since the process started.",
      help: "Main-thread stalls past 200 ms, by the route running across the stall, since the process started.",
      samples: tally.total.map((r) => ({ labels: { route: r.route }, value: r.count })),
    },
    {
@@ -6,6 +6,7 @@
import { jobWatch } from "./jobs.ts";
import { createLoopWatch } from "./loop.ts";
import { createCaptureStore } from "./capture.ts";
import { createReadLedger } from "./reads.ts";
import { createStallBlame } from "./stall_blame.ts";
import { createPerfRecord } from "./record.ts";
export const perfRecord = createPerfRecord();
@@ -17,3 +18,5 @@
export const bootStall = createBootStall();
/** What was read from repositories (`reads.ts`), and the one bounded capture an admin may run (`capture.ts`). */
export const readLedger = createReadLedger();
export const captureStore = createCaptureStore();
/** Each stall over 200 ms with what ran (#11069): the last hour's worst on /system, the last 10 s's on `/healthz`. */
export const stallBlame = createStallBlame();
@@ -16,12 +16,13 @@
 * stall nothing named ran across.
 */
export const LIMIT_MS = 250;
/** A wake later than this is a stall, ms (#11069: 200, so a stall the probes would feel is named). */
export const LIMIT_MS = 200;
const RECENT = 256;
/** The window `StallTally.hour` covers, in ms. */
export const HOUR_MS = 3_600_000;
/** Stalls kept for the hour: a stall is over 250 ms, so 14,400 fill an hour solid. */
const HOUR_KEPT = 14_400;
/** Stalls kept for the hour: a stall is over 200 ms, so 18,000 fill an hour solid. */
const HOUR_KEPT = 18_000;
/** The route a stall is counted against when no request ran across it. */
export const NO_REQUEST = "none";
/** The prefix a background job's name is tallied under, apart from routes. */
@@ -0,0 +1,81 @@
/**
 * Each loop stall over 200 ms, named by what ran (#11069): `{ what, ms, at }`
 * in a fixed ring, so /system can list the last hour's worst and `/healthz`
 * can say what held the loop behind its `loopLagMs`.
 *
 * Who ran is the loop watch's finding (`loop.ts`): the route patterns whose
 * request ran across the blocked window, else the background jobs marked
 * with `jobWatch.during` (`jobs.ts`), else nothing. `what` is the first of
 * those — the longest-running route, or `job:<name>` — and `unknown` when
 * nothing marked ran across the stall.
 *
 * The ring holds `KEPT` stalls and never grows: a note is three array
 * writes and an index step. At one stall per 200 ms an hour would be 18,000,
 * so a loop stalling solid for an hour keeps its last 256 — the worst of a
 * day that bad is still on the page, just not every one.
 */
import { blamed, NO_REQUEST, type Stall } from "./loop.ts";
/** The stalls the ring holds; fixed. */
export const STALL_KEPT = 256;
/** How many of the last hour's worst stalls /system and the terminal list. */
export const WORST_STALLS = 5;
/** What a stall is named when no route or job ran across it. */
export const UNKNOWN = "unknown";
export interface BlamedStall {
  /** A route pattern, `job:<name>`, or `unknown`. */
  readonly what: string;
  /** How late the wake was, ms. */
  readonly ms: number;
  /** When the wake saw it, on the watcher's clock (`performance.now`). */
  readonly at: number;
}
export interface StallBlame {
  /** Keep a stall the loop watch named. */
  note(stall: Stall): void;
  /** The `n` worst stalls seen in `(now - windowMs, now]`, most ms first, then newest. */
  worst(now: number, windowMs: number, n: number): BlamedStall[];
  /** How many stalls the ring holds now; never more than its size. */
  size(): number;
  /** Forget them all. */
  clear(): void;
}
/** The name one stall is blamed on. */
export function whatOf(stall: Stall): string {
  const first = blamed(stall)[0];
  return first === undefined || first === NO_REQUEST ? UNKNOWN : first;
}
export function createStallBlame(kept = STALL_KEPT): StallBlame {
  const n = Math.max(1, Math.floor(kept));
  const what: string[] = new Array<string>(n).fill("");
  const ms = new Float64Array(n);
  const at = new Float64Array(n);
  let next = 0;
  let count = 0;
  return {
    note(stall) {
      if (!Number.isFinite(stall.lateMs) || !Number.isFinite(stall.at)) return;
      what[next] = whatOf(stall);
      ms[next] = stall.lateMs;
      at[next] = stall.at;
      next = (next + 1) % n;
      if (count < n) count++;
    },
    worst(now, windowMs, k) {
      const out: BlamedStall[] = [];
      for (let i = 0; i < count; i++)
        if (at[i]! > now - windowMs && at[i]! <= now) out.push({ what: what[i]!, ms: ms[i]!, at: at[i]! });
      return out.sort((a, b) => b.ms - a.ms || b.at - a.at).slice(0, Math.max(0, k));
    },
    size: () => count,
    clear() {
      next = 0;
      count = 0;
    },
  };
}
@@ -1,14 +1,16 @@
/**
 * Main-thread stalls in the terminal, the owner's (#9016): the last hour's
 * top routes by milliseconds the loop was held past 250 ms, with
 * top routes by milliseconds the loop was held past 200 ms, with
      
        sentinelcrew
        20h ago
        
      
      Both doors: only a comment changed here. The terminal screen must also list the worst five single stalls (what, ms, when) like /system, and /healthz-equivalent parity; add it plus a test.
    
 * /api/v1/telemetry/flow always listed — the rows `/system` and `/metrics`
 * read (`stallHour`). The gate is `/system`'s: a forge admin who is a person.
 * Read-only.
 * read (`stallHour`); then, as /system draws them (#11069), the last hour's
 * worst single stalls — what ran, its ms, and when, in UTC — only when there
 * is one. The gate is `/system`'s: a forge admin who is a person. Read-only.
 */
import { stallHour } from "../../metrics/stalls.ts";
import type { RouteStall } from "../../perf/loop.ts";
import { loopWatch } from "../../perf/live.ts";
import { HOUR_MS, type RouteStall } from "../../perf/loop.ts";
import { loopWatch, stallBlame } from "../../perf/live.ts";
import { WORST_STALLS, type BlamedStall } from "../../perf/stall_blame.ts";
import type { Ctx, Screen } from "../app/app.ts";
import { binding } from "../app/keys.ts";
import type { Session } from "../session.ts";
@@ -19,14 +21,44 @@
import type { PaletteEntry } from "./entries.ts";
const mayRead = (session: Session): boolean => session.user?.isAdmin === true && session.user.kind !== "agent";
/** The header, then a route a row; empty for anyone the gate refuses. */
export function stallLines(session: Session, rows: readonly RouteStall[] = stallHour(loopWatch.tally(performance.now()))): string[] {
/** The last hour's worst single stalls and one instant on both clocks, as /system reads them. */
export interface WorstNow {
  readonly rows: readonly BlamedStall[];
  /** The instant on the watcher's clock (`performance.now`). */
  readonly mono: number;
  /** The same instant on the wall clock, ms since the epoch. */
  readonly wall: number;
}
function worstNow(): WorstNow {
  const mono = performance.now();
  return { rows: stallBlame.worst(mono, HOUR_MS, WORST_STALLS), mono, wall: Date.now() };
}
/**
 * The header, then a route a row; then, when the hour had any, a blank line and
 * the worst single stalls. A stall's wall time is `wall − (mono − at)`, as on
 * /system. Empty for anyone the gate refuses.
 */
export function stallLines(
  session: Session,
  rows: readonly RouteStall[] = stallHour(loopWatch.tally(performance.now())),
  worst: WorstNow = worstNow(),
): string[] {
  if (!mayRead(session)) return [];
  const col = (s: string) => pad(s, 10, "right");
  return [
  const lines = [
    `${pad("Route (last hour)", 40)}${col("Stall ms")}${col("Stalls")}`,
    ...rows.map((r) => `${pad(r.route, 40)}${col(String(Math.round(r.ms)))}${col(String(r.count))}`),
  ];
  if (worst.rows.length === 0) return lines;
  const when = (at: number) => `${new Date(worst.wall - (worst.mono - at)).toISOString().slice(11, 19)} UTC`;
  return [
    ...lines,
    "",
    `${pad("Worst single stalls (what ran)", 40)}${col("ms")}  When`,
    ...worst.rows.map((r) => `${pad(r.what, 40)}${col(String(Math.round(r.ms)))}  ${when(r.at)}`),
  ];
}
export function stallsScreen(session: Session, ctx: Ctx): Screen {
@@ -37,7 +69,8 @@
export function stallsScreen(session: Session, ctx: Ctx): Screen {
    render(area, s) {
      const c = ctx.theme.c;
      const lines = stallLines(session);
      const spans = lines.map((text, i) => [{ text, style: style(i === 0 ? c.fg : c.mutedFg, c.bg) }]);
      const worstHead = lines.indexOf("") + 1; // 0 when there is no worst list
      const spans = lines.map((text, i) => [{ text, style: style(i === 0 || i === worstHead ? c.fg : c.mutedFg, c.bg) }]);
      drawLines(s, area, c, scroll, spans);
      hitScroll(ctx, area, scroll, lines.length);
    },
@@ -30,8 +30,9 @@
import { live } from "../../system/live.ts";
import { readerPaces, type ReaderPace } from "../../system/telemetry_reads.ts";
import { slowPageLine, slowPages, type SlowPage } from "../../perf/watch.ts";
import { stallHour } from "../../metrics/stalls.ts";
import type { RouteStall } from "../../perf/loop.ts";
import { loopWatch } from "../../perf/live.ts";
import { HOUR_MS, type RouteStall } from "../../perf/loop.ts";
import { loopWatch, stallBlame } from "../../perf/live.ts";
import { WORST_STALLS, type BlamedStall } from "../../perf/stall_blame.ts";
import { notePhase, takeSessionTime, timePhase } from "../../core/route_timing.ts";
import { notFoundPage, signInFirst } from "../chrome.ts";
import { html, raw, type Html } from "../html.ts";
@@ -42,7 +43,7 @@
import { KEPT_PAGE_BYTES, keptPageStats } from "./kept_page.ts";
import { COLUMN_BYTES, PARTS_BYTES, keptPartsStats, treeCacheStats } from "./tree_cache.ts";
import { featureHealth, type FeatureHealth } from "../../system/feature_health.ts";
import { egressReportedLine } from "../../system/egress_line.ts";
import { badge, chartBox, meter, pill, row } from "../ui.ts";
import { badge, chartBox, meter, pill, row, time } from "../ui.ts";
import { childDirOf, listChildren } from "../../actions/spawn.ts";
import { childrenUse, realSelf, selfUse, shareOf, sizeWords, useWords, type ChildUseRow, type SelfUse } from "../../spawn/usage.ts";
@@ -197,15 +198,32 @@
export function featuresSection(rows: readonly FeatureHealth[]): Html {
}
/** The last hour's stalls by route, most milliseconds first; the rows are `stallHour`'s. */
export function stallSection(rows: readonly RouteStall[]): Html {
export function stallSection(rows: readonly RouteStall[], worst: Html = html``): Html {
  return html`<section class="settings-block"><h2>Main-thread stalls, last hour</h2>
    <p class="small muted">Past 250 ms, as of this page's load; <code>/metrics</code> has the series.</p>${
    <p class="small muted">Past 200 ms, as of this page's load; <code>/metrics</code> has the series.</p>${
    rows.length === 0
      ? html`<p class="muted">No stalls in the last hour.</p>`
      : html`<div class="table-scroll"><table class="table" aria-label="Main-thread stalls by route, last hour">
        <thead><tr><th scope="col">Route</th><th scope="col" class="num">Stall ms</th><th scope="col" class="num">Stalls</th></tr></thead>
        <tbody>${rows.map((r) => html`<tr data-route="${r.route}"><td class="mono">${r.route}</td><td class="num mono">${String(Math.round(r.ms))}</td><td class="num mono">${String(r.count)}</td></tr>`)}</tbody>
      </table></div>`}</section>`;
      </table></div>`}${worst}</section>`;
}
/** How many of the last hour's worst stalls the page lists (#11069); the terminal lists as many. */
export { WORST_STALLS };
/**
 * The last hour's worst single stalls, each with what ran (#11069), drawn inside
 * the stalls section and only when there is one, so a quiet /system reads as before.
 * `at` is on the watcher's clock (`performance.now`); `nowMono`/`nowWall` are one
 * instant on it and on the wall clock, so a stall's wall time is `nowWall − (nowMono − at)`.
 */
export function worstStallsTable(rows: readonly BlamedStall[], nowMono: number, nowWall: number): Html {
  if (rows.length === 0) return html``;
  return html`<h3 id="sys-worst-stalls">Worst single stalls</h3><div class="table-scroll"><table class="table" aria-label="Worst single stalls, last hour">
        <thead><tr><th scope="col">What ran</th><th scope="col" class="num">ms</th><th scope="col">When</th></tr></thead>
        <tbody>${rows.map((r) => html`<tr data-what="${r.what}"><td class="mono">${r.what}</td><td class="num mono">${String(Math.round(r.ms))}</td><td>${time(new Date(nowWall - (nowMono - r.at)).toISOString())}</td></tr>`)}</tbody>
      </table></div>`;
}
const SLOW_TTL_MS = 5000;
@@ -320,6 +338,8 @@
export async function systemPage(ctx: Ctx): Promise<Response> {
  const self = owner ? timePhase(ctx.request, "self", () => selfUse(realSelf(ctx.app.config.dataDir))) : null;
  const children = owner ? childrenUse(await listChildren(ctx.app), (bodyId) => childDirOf(ctx.app, bodyId)) : [];
  const stalls = timePhase(ctx.request, "stalls", () => stallHour(loopWatch.tally(performance.now())));
  const nowMono = performance.now();
  const worst = stallBlame.worst(nowMono, HOUR_MS, WORST_STALLS);
  const rendering = performance.now();
  const r = regions(v);
  const at = (id: string): Html => raw(r[id]!);
@@ -350,7 +370,7 @@
export async function systemPage(ctx: Ctx): Promise<Response> {
        <button class="btn" data-size="sm" type="button" data-sort="mem" aria-pressed="false"><kbd>m</kbd> memory</button></div>
      <div id="sys-procs">${at("sys-procs")}</div></section>
    ${featuresSection(timePhase(ctx.request, "features", () => featureHealth(ctx.app, reader)))}
    <div id="sys-stalls">${stallSection(stalls)}</div>
    <div id="sys-stalls">${stallSection(stalls, worstStallsTable(worst, nowMono, Date.now()))}</div>
    <div id="sys-slow-pages">${slowPagesSection(timePhase(ctx.request, "slowpages", () => slowPagesCached(ctx.app.db)))}</div>
    <div id="sys-readers">${readersSection(readerPaces())}</div>
    <div id="sys-caches">${cachesSection(pageCaches())}</div>
@@ -22,8 +22,11 @@
import { proveAll } from "./helpers/verified.ts";
import { useLive, type Live } from "../src/system/live.ts";
import type { SystemView } from "../src/system/view.ts";
import { quietLogs } from "./helpers/globals.ts";
import { freshStallState } from "./helpers/stall-state.ts";
quietLogs();
// /system draws the process's stall watch and telemetry readers; start from a clean one.
freshStallState();
const BUDGET = "docs/design/attention-budget.json";
type Budget = Record<string, Record<string, Attention>>;
@@ -0,0 +1,25 @@
/**
 * The process's stall watch, starting clean and left clean (#11069). The
 * suite runs every file in one process, and `loopWatch`, `stallBlame` and the
 * telemetry reader counts (`perf/live.ts`, `system/telemetry_reads.ts`) are
 * that process's; a stall one file noted would otherwise be a row in the next
 * file's /system. Call at a file's top level, as `quietLogs` is
 * (`globals.ts`): it clears before the file's first test and after its last.
 */
import { afterAll, beforeAll } from "bun:test";
import { loopWatch, stallBlame } from "../../src/perf/live.ts";
import { resetTelemetryReads } from "../../src/system/telemetry_reads.ts";
/** Forget every stall and telemetry read the process has noted. */
export function clearStallState(): void {
  loopWatch.clear();
  stallBlame.clear();
  resetTelemetryReads();
}
/** Clear the process's stall watch before this scope runs and after it. */
export function freshStallState(): void {
  beforeAll(clearStallState);
  afterAll(clearStallState);
}
@@ -11,7 +11,8 @@
import { serve, type Servers } from "../src/http/server.ts";
import { watchStalls } from "../src/kernel/loop_lag.ts";
import { openMetrics } from "../src/metrics/openmetrics.ts";
import { stallFamilies, TOP_ROUTES } from "../src/metrics/stalls.ts";
import { loopWatch } from "../src/perf/live.ts";
import { loopWatch, stallBlame } from "../src/perf/live.ts";
import { WORST_STALLS } from "../src/perf/stall_blame.ts";
import { createLoopWatch, HOUR_MS, NO_REQUEST } from "../src/perf/loop.ts";
import { createAgent } from "../src/actions/crew.ts";
import type { User } from "../src/core/users.ts";
@@ -20,8 +21,10 @@
import { createForgeApp, forgeCommands, Session } from "../src/tui/forge.ts";
import { stallLines } from "../src/tui/screens/loopstalls.ts";
import { headlessTerminal } from "../src/tui/term/terminal.ts";
import { quietLogs } from "./helpers/globals.ts";
import { freshStallState } from "./helpers/stall-state.ts";
quietLogs();
freshStallState();
test("a deliberate stall during a route is counted against it", async () => {
  // The loop watcher on a clock the test moves: the route holds the thread
@@ -183,15 +186,49 @@
const doors = (user?: User): string[] => {
  return ids;
};
const quiet = { rows: [], mono: 0, wall: 0 };
test("the Stalls screen gives an admin person the rows and the door; nobody else either", () => {
  const rows = [{ route: "/slow/:id", ms: 812.6, count: 2 }, { route: "/api/v1/telemetry/flow", ms: 0, count: 0 }];
  const lines = stallLines(new Session(app, identity(alice)), rows);
  const lines = stallLines(new Session(app, identity(alice)), rows, quiet);
  expect(lines).toHaveLength(3);
  expect(lines[0]).toContain("Stall ms");
  expect(lines[1]).toMatch(/^\/slow\/:id\s+813\s+2$/);
  expect(lines[2]).toMatch(/^\/api\/v1\/telemetry\/flow\s+0\s+0$/);
  expect(doors(alice)).toContain("stalls");
  for (const who of [bob, bot, undefined]) {
    expect(stallLines(new Session(app, identity(who)), rows)).toEqual([]);
    expect(stallLines(new Session(app, identity(who)), rows, quiet)).toEqual([]);
    expect(doors(who)).not.toContain("stalls");
  }
});
test("the Stalls screen lists the hour's worst single stalls as /system does: what, ms, when (#11069)", () => {
  // One instant: 1,000,000 ms on the watcher's clock is 2026-11-10T12:00:00Z on the wall.
  const wall = Date.parse("2026-11-10T12:00:00Z");
  const worst = {
    rows: [
      { what: "/slow/:id", ms: 812.6, at: 1_000_000 - 90_000 }, // 90 s before: 11:58:30
      { what: "job:sampler", ms: 240.2, at: 1_000_000 - 3_600_000 + 1 }, // just inside the hour: 11:00:00
    ],
    mono: 1_000_000,
    wall,
  };
  const lines = stallLines(new Session(app, identity(alice)), [{ route: "/api/v1/telemetry/flow", ms: 0, count: 0 }], worst);
  expect(lines[2]).toBe("");
  expect(lines[3]).toMatch(/^Worst single stalls \(what ran\)\s+ms\s+When$/);
  expect(lines[4]).toMatch(/^\/slow\/:id\s+813\s+11:58:30 UTC$/);
  expect(lines[5]).toMatch(/^job:sampler\s+240\s+11:00:00 UTC$/);
  expect(lines).toHaveLength(6);
  expect(stallLines(new Session(app, identity(bob)), [], worst)).toEqual([]);
});
test("the Stalls screen reads the process's stall blame by default, the five /system reads", () => {
  const now = performance.now();
  for (const [ms, r] of [[300, "/a"], [800, "/b"], [250, "/c"], [500, "/d"], [700, "/e"], [210, "/f"]] as const)
    stallBlame.note({ at: now - 1_000, lateMs: ms, routes: [r], jobs: [] });
  const lines = stallLines(new Session(app, identity(alice)), []);
  const named = lines.slice(lines.indexOf("") + 2).map((l) => l.split(/\s+/)[0] ?? "");
  expect(named).toEqual(["/b", "/e", "/d", "/a", "/c"]);
  expect(stallBlame.worst(performance.now(), HOUR_MS, WORST_STALLS).map((s) => s.what)).toEqual(named);
  stallBlame.clear();
});
@@ -4,6 +4,10 @@
import { expect, test } from "bun:test";
import { createJobWatch, during } from "../src/perf/jobs.ts";
import { loopWatch } from "../src/perf/live.ts";
import { createLoopWatch, NO_REQUEST, stallLine } from "../src/perf/loop.ts";
import { freshStallState } from "./helpers/stall-state.ts";
// The wired test notes a stall on the process's watch, which every file in this process shares.
freshStallState();
const block = (ms: number): void => {
  const until = performance.now() + ms;
@@ -0,0 +1,169 @@
/**
 * A loop stall over 200 ms is named by what ran (#11069): a real busy-wait
 * inside a marked job is blamed on that job, one in an unmarked callback is
 * `unknown`, the ring never grows past its size, /system lists the worst
 * five and `/healthz` (JSON) says what held the loop as `loopWorstWhat`.
 */
import { afterAll, beforeAll, describe, expect, test } from "bun:test";
import { mkdtemp, rm } from "node:fs/promises";
import { tmpdir } from "node:os";
import { join } from "node:path";
import { createApp, type App } from "../src/app.ts";
import { serve, type Servers } from "../src/http/server.ts";
import { startLoopLag } from "../src/kernel/loop_lag.ts";
import { createJobWatch } from "../src/perf/jobs.ts";
import { stallBlame } from "../src/perf/live.ts";
import { createLoopWatch, HOUR_MS, LIMIT_MS, type Stall } from "../src/perf/loop.ts";
import { createStallBlame, STALL_KEPT, UNKNOWN, whatOf } from "../src/perf/stall_blame.ts";
import { stallSection, worstStallsTable } from "../src/web/pages/system.ts";
function blockFor(ms: number): void {
  const until = performance.now() + ms;
  while (performance.now() < until) {
    // the thread held, as a stall holds it
  }
}
/** Run `block` on the loop with a 10 ms lag sampler wired as main.ts wires it; resolves with the ring. */
async function stallUnder(block: (jobs: ReturnType<typeof createJobWatch>) => void) {
  const jobs = createJobWatch();
  const watch = createLoopWatch(LIMIT_MS, jobs.across);
  const blame = createStallBlame();
  const lag = startLoopLag(10, () => performance.now(), (late) => {
    const stall = watch.stalled(late, performance.now());
    if (stall !== null) blame.note(stall);
  });
  // Let the sampler arm, then hold the loop from a timer callback.
  await new Promise((r) => setTimeout(r, 15));
  await new Promise<void>((r) =>
    setTimeout(() => {
      block(jobs);
      r();
    }, 0),
  );
  // The overdue wake runs next.
  await new Promise((r) => setTimeout(r, 30));
  lag.stop();
  return blame;
}
describe("what a stall is blamed on", () => {
  test("the stall limit is 200 ms", () => {
    expect(LIMIT_MS).toBe(200);
  });
  test("a busy-wait inside a marked job is blamed on that job", async () => {
    const blame = await stallUnder((jobs) => jobs.during("snapshot", () => blockFor(260)));
    const [worst] = blame.worst(performance.now(), HOUR_MS, 5);
    expect(worst?.what).toBe("job:snapshot");
    expect(worst!.ms).toBeGreaterThan(200);
  });
  test("a busy-wait in an unmarked callback is unknown", async () => {
    const blame = await stallUnder(() => blockFor(260));
    const [worst] = blame.worst(performance.now(), HOUR_MS, 5);
    expect(worst?.what).toBe(UNKNOWN);
    expect(worst!.ms).toBeGreaterThan(200);
  });
  test("a route that ran across is named before any job", () => {
    const s: Stall = { at: 1, lateMs: 300, routes: ["/explore"], jobs: [] };
    expect(whatOf(s)).toBe("/explore");
    expect(whatOf({ ...s, routes: [], jobs: ["sampler"] })).toBe("job:sampler");
    expect(whatOf({ ...s, routes: [] })).toBe(UNKNOWN);
  });
});
describe("the ring", () => {
  test("never holds more than its size, and keeps the newest", () => {
    const blame = createStallBlame(8);
    for (let i = 0; i < 1_000; i++) blame.note({ at: i, lateMs: 201 + i, routes: [`/r${i}`], jobs: [] });
    expect(blame.size()).toBe(8);
    const all = blame.worst(10_000, 1e9, 100);
    expect(all.length).toBe(8);
    expect(all.map((s) => s.what)).toEqual(["/r999", "/r998", "/r997", "/r996", "/r995", "/r994", "/r993", "/r992"]);
    expect(createStallBlame().size()).toBe(0);
    expect(STALL_KEPT).toBe(256);
  });
      
        sentinelcrew
        20h ago
        
      
      A wall-clock threshold (1M notes under 1 s) is a flake risk on a loaded shard; the direction asks for fast tests that never flake. Remove the timing assertion.
    
  test("worst is the hour's, most ms first, at most n", () => {
    const blame = createStallBlame();
    const now = 10 * HOUR_MS;
    blame.note({ at: now - HOUR_MS - 1, lateMs: 9_000, routes: ["/old"], jobs: [] });
    for (const [ms, r] of [[300, "/a"], [800, "/b"], [250, "/c"], [500, "/d"], [700, "/e"], [210, "/f"]] as const)
      blame.note({ at: now - 1_000, lateMs: ms, routes: [r], jobs: [] });
    expect(blame.worst(now, HOUR_MS, 5).map((s) => [s.what, s.ms])).toEqual([
      ["/b", 800], ["/e", 700], ["/d", 500], ["/a", 300], ["/c", 250],
    ]);
  });
  test("an hour of solid stalling keeps the ring its size", () => {
    // 18,000 stalls: one every 200 ms for an hour; the ring holds its last STALL_KEPT.
    const blame = createStallBlame();
    for (let i = 0; i < 18_000; i++) blame.note({ at: i * 200, lateMs: 201, routes: ["/explore"], jobs: [] });
    expect(blame.size()).toBe(STALL_KEPT);
    expect(blame.worst(18_000 * 200, HOUR_MS, STALL_KEPT + 10).length).toBe(STALL_KEPT);
  });
});
describe("on /system", () => {
  test("lists what, ms and when, escaped", () => {
    const now = 5_000_000;
    const wall = Date.parse("2026-11-10T12:00:00Z");
    const out = String(worstStallsTable([{ what: "job:<x>", ms: 436.4, at: now - 120_000 }], now, wall));
    expect(out).toContain("Worst single stalls");
    expect(out).toContain("job:&lt;x&gt;");
    expect(out).not.toContain("job:<x>");
    expect(out).toContain(">436<");
    expect(out).toContain('datetime="2026-11-10T11:58:00.000Z"');
  });
  test("draws nothing when there is none, and sits inside the stalls section when there is", () => {
    expect(String(worstStallsTable([], 0, 0))).toBe("");
    const section = String(stallSection([], worstStallsTable([{ what: "/x", ms: 300, at: 0 }], 0, 0)));
    expect(section).toContain("Main-thread stalls, last hour");
    expect(section.indexOf("Worst single stalls")).toBeLessThan(section.indexOf("</section>"));
  });
});
describe("on /healthz", () => {
  let dataDir: string;
  let app: App;
  let servers: Servers;
  beforeAll(async () => {
    dataDir = await mkdtemp(join(tmpdir(), "forge-stall-blame-"));
    app = createApp({ dataDir, port: 0 });
    servers = await serve(app);
  });
  afterAll(async () => {
    stallBlame.clear();
    servers.stop();
    app.close();
    await rm(dataDir, { recursive: true, force: true });
  });
  test("loopWorstWhat is null with no stall, then names the last 10 s's worst", async () => {
    stallBlame.clear();
    const ask = async () =>
      (await (await fetch(`${servers.url}/healthz`, { headers: { accept: "application/json" } })).json()) as {
        ok: boolean;
        loopLagMs: number;
        loopWorstWhat: string | null;
      };
    const before = await ask();
    expect(before.ok).toBe(true);
    expect(typeof before.loopLagMs).toBe("number");
    expect(before.loopWorstWhat).toBeNull();
    const now = performance.now();
    stallBlame.note({ at: now - 60_000, lateMs: 900, routes: ["/too-old"], jobs: [] });
    stallBlame.note({ at: now, lateMs: 300, routes: [], jobs: ["crew-tick"] });
    stallBlame.note({ at: now, lateMs: 220, routes: ["/explore"], jobs: [] });
    expect((await ask()).loopWorstWhat).toBe("job:crew-tick");
    // A probe asking for nothing still hears the plain `ok` (#2917).
    expect(await (await fetch(`${servers.url}/healthz`)).text()).toBe("ok");
  });
});
		@@ -19,6 +19,8 @@ State shared between modules through process memory, not the database, is named
19	19
20	20	`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.
21	21
	22	`src/perf/stall_blame.ts` (`stallBlame` in `src/perf/live.ts`): each loop stall over 200 ms as `{ what, ms, at }` in a fixed ring of 256, fed by `main.ts`'s stall watcher after `loopWatch` names it, read by /system's worst-five card and `/healthz`'s `loopWorstWhat`.
	23
22	24	`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	25
24	26	`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).
		@@ -23,7 +23,7 @@ not an admin, 200 for an admin's `ro` token. It is never cached
23	23	\| `forge_ask_to_live_seconds` \| histogram \| none (plus `le`) \| Seconds from an issue opening to the first successful release of a pull that closes it. Buckets: 1 m, 5 m, 15 m, 1 h, 4 h, 12 h, 1 d, 3 d, 7 d. \|
24	24	\| `forge_main_red_seconds_total` \| counter \| `repo` \| Seconds the default branch's check spent failing: from a failed check to the next green one, or to now while still red. \|
25	25	\| `forge_telemetry_reads_total` \| counter \| `route`, `reader` \| Reads of `/api/v1/telemetry` routes since the process started, by route and reader; the rate is the slope. The owner's `/system` page names each reader's pace over the last 10 minutes. \|
26		\| `forge_loop_stall_milliseconds_total` \| counter \| `route` \| Milliseconds the main thread stalled past 250 ms since the process started, charged in full to every route pattern running across the stall (`none` when no request was). \|
	26	\| `forge_loop_stall_milliseconds_total` \| counter \| `route` \| Milliseconds the main thread stalled past 200 ms since the process started, charged in full to every route pattern running across the stall (`none` when no request was). \|
27	27	\| `forge_loop_stalls_total` \| counter \| `route` \| Those stalls, counted the same way. \|
28	28	\| `forge_loop_stall_hour_milliseconds` \| gauge \| `route` \| Stall milliseconds in the last hour: the top 10 routes, most first, plus `/api/v1/telemetry/flow` always (0 when it stalled nothing). \|
29	29	\| `forge_loop_stall_hour_count` \| gauge \| `route` \| Stalls in the last hour, for the routes the gauge above lists. \|
		@@ -1,6 +1,6 @@
1	1	# Main-thread stalls by route (#9016)
2	2
3		The forge counts every wake of its event loop more than 250 ms late as a
	3	The forge counts every wake of its event loop more than 200 ms late as a
4	4	stall, and charges it in full to each route pattern whose request ran across
5	5	it (`none` when no request did) — the same reading as the `event loop blocked`
6	6	log lines (`src/perf/loop.ts`), so a fix's before and after reads from the
		@@ -12,7 +12,14 @@ palette entry):
12	12	- `/system`, the "Main-thread stalls, last hour" card: route, stall ms and
13	13	count for the top 10 routes, most first, plus `/api/v1/telemetry/flow`
14	14	always (0 when it stalled nothing). As of the page's load.
15		- The terminal: `:` → "Main-thread stalls", the same rows.
	15	- `/system`, inside that card, "Worst single stalls" (#11069), drawn only
	16	when the hour had one: the five worst single stalls, each with what ran (the route pattern, `job:<name>` for a job
	17	marked with `jobWatch.during`, or `unknown`), its ms and when. Kept in a
	18	fixed ring of 256 (`src/perf/stall_blame.ts`).
	19	- `/healthz` with `Accept: application/json`: beside `loopLagMs`,
	20	`loopWorstWhat` names the worst stall of the same 10 s (null when none).
	21	- The terminal: `:` → "Main-thread stalls", the same rows, then the same
	22	worst single stalls (what ran, ms, when in UTC) when the hour had one.
16	23	- `GET /metrics` (an admin `ro` token): `forge_loop_stall_milliseconds_total`
17	24	and `forge_loop_stalls_total` by `route` since the process started, and the
18	25	last hour as `forge_loop_stall_hour_milliseconds` / `forge_loop_stall_hour_count`
		@@ -90,10 +90,17 @@ export function startDraining(log: Log, why: string, fields: Record<string, numb
90	90	*
91	91	* Given `loopLagMs` (the caller asked for JSON), the 200 is
92	92	* `{"ok":true,"loopLagMs":n}`: the worst event-loop lag of the last 10 s
93		* (`perf/loop_worst.ts`, #10288). Otherwise it stays the plain `ok` a
94		* probe and a stranger hear (#2917).
	93	* (`perf/loop_worst.ts`, #10288), with `loopWorstWhat`: the route pattern,
	94	* `job:<name>` or `unknown` the worst stall over 200 ms in those 10 s was
	95	* blamed on, null when there was none (`perf/stall_blame.ts`, #11069).
	96	* Otherwise it stays the plain `ok` a probe and a stranger hear (#2917).
95	97	*/
96		export function liveResponse(ping: () => unknown, log: Log, loopLagMs?: number): Response {
	98	export function liveResponse(
	99	ping: () => unknown,
	100	log: Log,
	101	loopLagMs?: number,
	102	loopWorstWhat: string \| null = null,
	103	): Response {
97	104	try {
98	105	ping();
99	106	} catch (error) {
		@@ -107,7 +114,10 @@ export function liveResponse(ping: () => unknown, log: Log, loopLagMs?: number):
107	114	if (databaseDown) log.info("forge alive again: the database answers");
108	115	databaseDown = false;
109	116	if (loopLagMs !== undefined && Number.isFinite(loopLagMs))
110		return Response.json({ ok: true, loopLagMs: Math.round(loopLagMs * 10) / 10 }, { status: 200 });
	117	return Response.json(
	118	{ ok: true, loopLagMs: Math.round(loopLagMs * 10) / 10, loopWorstWhat },
	119	{ status: 200 },
	120	);
111	121	return new Response("ok", { status: 200 });
112	122	}
113	123
		@@ -507,7 +507,7 @@ import {
507	507	takeDbTime,
508	508	type RouteTiming,
509	509	} from "../core/route_timing.ts";
510		import { captureStore, loopWatch, perfRecord, readLedger } from "../perf/live.ts";
	510	import { captureStore, loopWatch, perfRecord, readLedger, stallBlame } from "../perf/live.ts";
511	511	import { during } from "../perf/jobs.ts";
512	512	import { classOf, countryOf, repoOf, signatureOf } from "../perf/traffic.ts";
513	513	import { createTrafficWriter } from "../perf/traffic_store.ts";
		@@ -519,7 +519,7 @@ import { statementPage } from "../web/pages/statement.ts";
519	519	import { createViewWriter } from "../perf/views_store.ts";
520	520	import { createReadWriter, readOf } from "../perf/reads.ts";
521	521	import { parseServerTiming } from "../perf/record.ts";
522		import { currentLoopLag, startLoopWorst } from "../perf/loop_worst.ts";
	522	import { currentLoopLag, LAG_WINDOW_MS, startLoopWorst } from "../perf/loop_worst.ts";
523	523	import { methodOf, noteUsage, roleOf, surfaceOf, takeUsage } from "./usage_tag.ts";
524	524	import { bearerChallenge, oauthRoutes } from "./oauth.ts";
525	525	import { flushAccess, recordAccess } from "./access_log.ts";
		@@ -2829,6 +2829,7 @@ async function answerGet(
2829	2829	() => app.db.query("select 1").get(),
2830	2830	app.log,
2831	2831	wantsJson ? currentLoopLag() : undefined,
	2832	wantsJson ? (stallBlame.worst(performance.now(), LAG_WINDOW_MS, 1)[0]?.what ?? null) : null,
2832	2833	);
2833	2834	noteDbTime(request, performance.now() - dbStart);
2834	2835	// The release proof learns which release answered, old pod or new; a
		@@ -108,7 +108,7 @@ import { watchStalls } from "./kernel/loop_lag.ts";
108	108	import { startPerfWatcher, TICK_MS } from "./perf/duty.ts";
109	109	import { during } from "./perf/jobs.ts";
110	110	import { stallLine } from "./perf/loop.ts";
111		import { bootStall, gitRecord, loopWatch, perfRecord } from "./perf/live.ts";
	111	import { bootStall, gitRecord, loopWatch, perfRecord, stallBlame } from "./perf/live.ts";
112	112	import { timeStatements } from "./kernel/slow_sql.ts";
113	113	import { waitForPeer } from "./runs/peer.ts";
114	114	import { closeStaleSessions } from "./machines/shell.ts";
		@@ -241,7 +241,9 @@ const loopLog = createLog("loop");
241	241	watchStalls(loopLog, undefined, undefined, undefined, (late, at) => {
242	242	bootStall.note(late, at);
243	243	const stall = loopWatch.stalled(late, at);
244		if (stall !== null) loopLog.warn(stallLine(stall));
	244	if (stall === null) return;
	245	loopLog.warn(stallLine(stall));
	246	stallBlame.note(stall);
245	247	});
246	248
247	249	const previewKey = previewIdentityKey(process.env);
		@@ -30,13 +30,13 @@ export function stallFamilies(tally: StallTally): Family[] {
30	30	{
31	31	type: "counter",
32	32	name: "forge_loop_stall_milliseconds_total",
33		help: "Milliseconds the main thread stalled past 250 ms, by the route running across the stall (route=\"none\" when none), since the process started.",
	33	help: "Milliseconds the main thread stalled past 200 ms, by the route running across the stall (route=\"none\" when none), since the process started.",
34	34	samples: tally.total.map((r) => ({ labels: { route: r.route }, value: Math.round(r.ms) })),
35	35	},
36	36	{
37	37	type: "counter",
38	38	name: "forge_loop_stalls_total",
39		help: "Main-thread stalls past 250 ms, by the route running across the stall, since the process started.",
	39	help: "Main-thread stalls past 200 ms, by the route running across the stall, since the process started.",
40	40	samples: tally.total.map((r) => ({ labels: { route: r.route }, value: r.count })),
41	41	},
42	42	{
		@@ -6,6 +6,7 @@ import { jobWatch } from "./jobs.ts";
6	6	import { createLoopWatch } from "./loop.ts";
7	7	import { createCaptureStore } from "./capture.ts";
8	8	import { createReadLedger } from "./reads.ts";
	9	import { createStallBlame } from "./stall_blame.ts";
9	10	import { createPerfRecord } from "./record.ts";
10	11
11	12	export const perfRecord = createPerfRecord();
		@@ -17,3 +18,5 @@ export const bootStall = createBootStall();
17	18	/** What was read from repositories (`reads.ts`), and the one bounded capture an admin may run (`capture.ts`). */
18	19	export const readLedger = createReadLedger();
19	20	export const captureStore = createCaptureStore();
	21	/** Each stall over 200 ms with what ran (#11069): the last hour's worst on /system, the last 10 s's on `/healthz`. */
	22	export const stallBlame = createStallBlame();
		@@ -16,12 +16,13 @@
16	16	* stall nothing named ran across.
17	17	*/
18	18
19		export const LIMIT_MS = 250;
	19	/** A wake later than this is a stall, ms (#11069: 200, so a stall the probes would feel is named). */
	20	export const LIMIT_MS = 200;
20	21	const RECENT = 256;
21	22	/** The window `StallTally.hour` covers, in ms. */
22	23	export const HOUR_MS = 3_600_000;
23		/** Stalls kept for the hour: a stall is over 250 ms, so 14,400 fill an hour solid. */
24		const HOUR_KEPT = 14_400;
	24	/** Stalls kept for the hour: a stall is over 200 ms, so 18,000 fill an hour solid. */
	25	const HOUR_KEPT = 18_000;
25	26	/** The route a stall is counted against when no request ran across it. */
26	27	export const NO_REQUEST = "none";
27	28	/** The prefix a background job's name is tallied under, apart from routes. */
		@@ -0,0 +1,81 @@
	1	/**
	2	* Each loop stall over 200 ms, named by what ran (#11069): `{ what, ms, at }`
	3	* in a fixed ring, so /system can list the last hour's worst and `/healthz`
	4	* can say what held the loop behind its `loopLagMs`.
	5	*
	6	* Who ran is the loop watch's finding (`loop.ts`): the route patterns whose
	7	* request ran across the blocked window, else the background jobs marked
	8	* with `jobWatch.during` (`jobs.ts`), else nothing. `what` is the first of
	9	* those — the longest-running route, or `job:<name>` — and `unknown` when
	10	* nothing marked ran across the stall.
	11	*
	12	* The ring holds `KEPT` stalls and never grows: a note is three array
	13	* writes and an index step. At one stall per 200 ms an hour would be 18,000,
	14	* so a loop stalling solid for an hour keeps its last 256 — the worst of a
	15	* day that bad is still on the page, just not every one.
	16	*/
	17
	18	import { blamed, NO_REQUEST, type Stall } from "./loop.ts";
	19
	20	/** The stalls the ring holds; fixed. */
	21	export const STALL_KEPT = 256;
	22	/** How many of the last hour's worst stalls /system and the terminal list. */
	23	export const WORST_STALLS = 5;
	24	/** What a stall is named when no route or job ran across it. */
	25	export const UNKNOWN = "unknown";
	26
	27	export interface BlamedStall {
	28	/** A route pattern, `job:<name>`, or `unknown`. */
	29	readonly what: string;
	30	/** How late the wake was, ms. */
	31	readonly ms: number;
	32	/** When the wake saw it, on the watcher's clock (`performance.now`). */
	33	readonly at: number;
	34	}
	35
	36	export interface StallBlame {
	37	/** Keep a stall the loop watch named. */
	38	note(stall: Stall): void;
	39	/** The `n` worst stalls seen in `(now - windowMs, now]`, most ms first, then newest. */
	40	worst(now: number, windowMs: number, n: number): BlamedStall[];
	41	/** How many stalls the ring holds now; never more than its size. */
	42	size(): number;
	43	/** Forget them all. */
	44	clear(): void;
	45	}
	46
	47	/** The name one stall is blamed on. */
	48	export function whatOf(stall: Stall): string {
	49	const first = blamed(stall)[0];
	50	return first === undefined \|\| first === NO_REQUEST ? UNKNOWN : first;
	51	}
	52
	53	export function createStallBlame(kept = STALL_KEPT): StallBlame {
	54	const n = Math.max(1, Math.floor(kept));
	55	const what: string[] = new Array<string>(n).fill("");
	56	const ms = new Float64Array(n);
	57	const at = new Float64Array(n);
	58	let next = 0;
	59	let count = 0;
	60	return {
	61	note(stall) {
	62	if (!Number.isFinite(stall.lateMs) \|\| !Number.isFinite(stall.at)) return;
	63	what[next] = whatOf(stall);
	64	ms[next] = stall.lateMs;
	65	at[next] = stall.at;
	66	next = (next + 1) % n;
	67	if (count < n) count++;
	68	},
	69	worst(now, windowMs, k) {
	70	const out: BlamedStall[] = [];
	71	for (let i = 0; i < count; i++)
	72	if (at[i]! > now - windowMs && at[i]! <= now) out.push({ what: what[i]!, ms: ms[i]!, at: at[i]! });
	73	return out.sort((a, b) => b.ms - a.ms \|\| b.at - a.at).slice(0, Math.max(0, k));
	74	},
	75	size: () => count,
	76	clear() {
	77	next = 0;
	78	count = 0;
	79	},
	80	};
	81	}