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

Every response's Server-Timing names the worst event-loop lag of the last 10 s, so a stall outside the handler shows #10292

Merged opened this

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

Merged

I added `lag;dur=<ms>` to every forge response's `Server-Timing`: the worst event-loop lag seen in the last 10 s. The issue's last item is not done: this pull's preview doesn't exist until the forge opens the pull, so I couldn't quote its `lag` across 30 requests. As a baseline, 30 requests to production `/nope` gave `app;dur` 1.8–6.1 ms each, but `forge-ttfb` was 59–1147 ms on 9 of them (59.5, 97…

shipped production is serving it deploy f21b126

opened this

I added lag;dur=<ms> to every forge response's Server-Timing: the worst event-loop lag seen in the last 10 s. The issue's last item is not done: this pull's preview doesn't exist until the forge opens the pull, so I couldn't quote its lag across 30 requests. As a baseline, 30 requests to production /nope gave app;dur 1.8–6.1 ms each, but forge-ttfb was 59–1147 ms on 9 of them (59.5, 97.3, 103.1, 137.6, 158.0, 224.2, 286.3, 663.9 and 1147.3 ms). The same 30 requests against the preview should show lag rising on exactly those.

What changed

  • src/perf/loop_worst.ts (new): keeps the worst lag of the last 10 s in ten one-second slots.

- It is fed by the existing startLoopLag sampler in kernel/loop_lag.ts: one unref'd 50 ms timer, started once by the first serve. - Recording a sample takes constant time and reading the window looks at ten numbers, so a tick costs well under 0.1 ms. I didn't time it, because the repo's rule is to count work rather than time it. - A stall stays visible for 9–10 s after it, because the window moves a second at a time. - With a 50 ms timer, a block can read up to 50 ms short (a 150 ms block reads 100–150).

  • src/http/server.ts: counted() adds the token through withLag() in src/core/route_timing.ts. The token goes on the response only. The perf record's phases leave it out, so per-route phase stats aren't polluted by a number that belongs to the loop, not the request.
  • /healthz: still answers plain ok to probes and strangers; I kept that body unchanged because the #2917 test pins it. Only Accept: application/json gets {"ok":true,"loopLagMs":n}.

Tests

  • test/loop-worst.test.ts checks the window by hand: slot rollover, reuse of a slot a lap later, and bad input.
  • End to end, it starts a real server, blocks the loop for 150 ms with a busy wait, and sees lag;dur ≥ 140 on the next /nope and loopLagMs ≥ 140 on /healthz.

- The test runs the sampler every 5 ms rather than 50, so the reading can be compared against 140 exactly. - It then stops the sampler and moves the window's clock forward 10 s; the next response reads lag;dur=0.0. - The window's clock is separate from the clock that measures lateness, so moving it forward doesn't look like a 10 s stall.

  • About 73 existing *-timing tests compared exact phase lists, so the extra token broke them. They now read requestTiming(res) from the new test/helpers/request-timing.ts, which drops lag. test/route-timing.test.ts's exact-format regexes now expect the trailing lag. The tests were too strict for an added token; the code was right.
  • These tests in particular showed lags of around 160 ms inside the test process, so the stalls are real.

Checks

  • bun scripts/gate.ts and bun x tsc --noEmit are clean.
  • I ran every test file that mentions Server-Timing or /healthz (272 files), plus flake, principles and the tests that read AGENTS.md.
  • The only failure is test/scaffold.test.ts "typechecks under strict settings". It needs bun x to write to a tempdir that is read-only in my sandbox, and it fails the same way on main.

Not done

  • The keep_plan tool wasn't available in this session, so the issue has no plan.
  • The apps proxy's own forge-* Server-Timing doesn't get lag. The lag on the forge's own responses is what names the stall.

AGENTS.md now names loopWorst as state shared through process memory, as it asks.

Try it

  • curl -sI <preview>/nope | grep -i server-timing shows the new lag;dur token.
  • curl -s -H 'accept: application/json' <preview>/healthz returns loopLagMs.

🤖 Generated with Claude Code

Closes #10288

commented

I added lag;dur=<ms> to every forge response's Server-Timing: the worst event-loop lag seen in the last 10 s. The issue's last item is not done: this pull's preview doesn't exist until the forge opens the pull, so I couldn't quote its lag across 30 requests. As a baseline, 30 requests to production /nope gave app;dur 1.8–6.1 ms each, but forge-ttfb was 59–1147 ms on 9 of them (59.5, 97.3, 103.1, 137.6, 158.0, 224.2, 286.3, 663.9 and 1147.3 ms). The same 30 requests against the preview should show lag rising on exactly those.

What changed

  • src/perf/loop_worst.ts (new): keeps the worst lag of the last 10 s in ten one-second slots.

- It is fed by the existing startLoopLag sampler in kernel/loop_lag.ts: one unref'd 50 ms timer, started once by the first serve. - Recording a sample takes constant time and reading the window looks at ten numbers, so a tick costs well under 0.1 ms. I didn't time it, because the repo's rule is to count work rather than time it. - A stall stays visible for 9–10 s after it, because the window moves a second at a time. - With a 50 ms timer, a block can read up to 50 ms short (a 150 ms block reads 100–150).

  • src/http/server.ts: counted() adds the token through withLag() in src/core/route_timing.ts. The token goes on the response only. The perf record's phases leave it out, so per-route phase stats aren't polluted by a number that belongs to the loop, not the request.
  • /healthz: still answers plain ok to probes and strangers; I kept that body unchanged because the #2917 test pins it. Only Accept: application/json gets {"ok":true,"loopLagMs":n}.

Tests

  • test/loop-worst.test.ts checks the window by hand: slot rollover, reuse of a slot a lap later, and bad input.
  • End to end, it starts a real server, blocks the loop for 150 ms with a busy wait, and sees lag;dur ≥ 140 on the next /nope and loopLagMs ≥ 140 on /healthz.

- The test runs the sampler every 5 ms rather than 50, so the reading can be compared against 140 exactly. - It then stops the sampler and moves the window's clock forward 10 s; the next response reads lag;dur=0.0. - The window's clock is separate from the clock that measures lateness, so moving it forward doesn't look like a 10 s stall.

  • About 73 existing *-timing tests compared exact phase lists, so the extra token broke them. They now read requestTiming(res) from the new test/helpers/request-timing.ts, which drops lag. test/route-timing.test.ts's exact-format regexes now expect the trailing lag. The tests were too strict for an added token; the code was right.
  • These tests in particular showed lags of around 160 ms inside the test process, so the stalls are real.

Checks

  • bun scripts/gate.ts and bun x tsc --noEmit are clean.
  • I ran every test file that mentions Server-Timing or /healthz (272 files), plus flake, principles and the tests that read AGENTS.md.
  • The only failure is test/scaffold.test.ts "typechecks under strict settings". It needs bun x to write to a tempdir that is read-only in my sandbox, and it fails the same way on main.

Not done

  • The keep_plan tool wasn't available in this session, so the issue has no plan.
  • The apps proxy's own forge-* Server-Timing doesn't get lag. The lag on the forge's own responses is what names the stall.

AGENTS.md now names loopWorst as state shared through process memory, as it asks.

Try it

  • curl -sI <preview>/nope | grep -i server-timing shows the new lag;dur token.
  • curl -s -H 'accept: application/json' <preview>/healthz returns loopLagMs.

🤖 Generated with Claude Code

commented

I added lag;dur=<ms> to every forge response's Server-Timing: the worst event-loop lag seen in the last 10 s. The issue's last item is not done: I couldn't quote the preview's lag across 30 requests, because I had no preview address for this pull. As a baseline, 30 requests to production /nope gave app;dur 1.8–6.1 ms each, but forge-ttfb was 59–1147 ms on 9 of them (59.5, 97.3, 103.1, 137.6, 158.0, 224.2, 286.3, 663.9 and 1147.3 ms). The same 30 requests against the preview should show lag rising on exactly those.

What changed

  • src/perf/loop_worst.ts (new): keeps the worst lag of the last 10 s in ten one-second slots.

- It is fed by the existing startLoopLag sampler in kernel/loop_lag.ts: one unref'd 50 ms timer, started once by the first serve. - Recording a sample takes constant time and reading the window looks at ten numbers, so a tick costs well under 0.1 ms. I didn't time it, because the repo's rule is to count work rather than time it. - A stall stays visible for 9–10 s after it, because the window moves a second at a time. - With a 50 ms timer, a block can read up to 50 ms short (a 150 ms block reads 100–150).

  • src/http/server.ts: counted() adds the token through withLag() in src/core/route_timing.ts. The token goes on the response only. The perf record's phases leave it out, so per-route phase stats aren't polluted by a number that belongs to the loop, not the request.
  • /healthz: still answers plain ok to probes and strangers; I kept that body unchanged because the #2917 test pins it. Only Accept: application/json gets {"ok":true,"loopLagMs":n}.
  • Commit messages: the check failed because no commit had a Try: line. Rather than force-push, I added an empty commit with one.

Tests

  • test/loop-worst.test.ts checks the window by hand: slot rollover, reuse of a slot a lap later, and bad input.
  • End to end, it starts a real server, blocks the loop for 150 ms with a busy wait, and sees lag;dur ≥ 140 on the next /nope and loopLagMs ≥ 140 on /healthz.

- The test runs the sampler every 5 ms rather than 50, so the reading can be compared against 140 exactly. - It then stops the sampler and moves the window's clock forward 10 s; the next response reads lag;dur=0.0. - The window's clock is separate from the clock that measures lateness, so moving it forward doesn't look like a 10 s stall.

  • About 73 existing *-timing tests compared exact phase lists, so the extra token broke them. They now read requestTiming(res) from the new test/helpers/request-timing.ts, which drops lag. test/route-timing.test.ts's exact-format regexes now expect the trailing lag. The tests were too strict for an added token; the code was right.
  • These tests in particular showed lags of around 160 ms inside the test process, so the stalls are real.

Checks

  • bun scripts/gate.ts and bun x tsc --noEmit are clean.
  • On the first push I ran every test file that mentions Server-Timing or /healthz (272 files), plus flake, principles and the tests that read AGENTS.md. The only failure was test/scaffold.test.ts "typechecks under strict settings". It needs bun x to write to a tempdir that is read-only in my sandbox, and it fails the same way on main.
  • After the Try: commit I re-ran loop-worst, health, route-timing and map-cache, and all pass.
  • The Try: rule isn't in scripts/gate.ts, so I couldn't check it locally; the forge's next check will tell.

Not done

  • The keep_plan tool wasn't available in this session, so the issue has no plan.
  • The apps proxy's own forge-* Server-Timing doesn't get lag. The lag on the forge's own responses is what names the stall.

AGENTS.md now names loopWorst as state shared through process memory, as it asks.

Try it

  • curl -sI <preview>/nope | grep -i server-timing shows the new lag;dur token.
  • curl -s -H 'accept: application/json' <preview>/healthz returns loopLagMs.

🤖 Generated with Claude Code

Changes requested — before the latest push

The preview works: 30 requests to /nope gave lag;dur 4.9 to 65.8 ms (1x4.9, 7x5.1, 10x5.7, 12x65.8), and /healthz with Accept: application/json returned loopLagMs. No security finding: the lag value is server-computed, JSON is only served on an Accept opt-in, and nothing is injected. Two things to fix in one round:

  1. Box 4 is not met. The pull description says the 30-request lag was not quoted. The preview exists now, so quote it in the description. The numbers above are a start. Rerun them yourself and name which requests were slow.
  2. Box 1 says the tick costs under 0.1 ms. The description says it was not measured. Add a test that runs note and worst about 100k times and asserts the mean is under 0.1 ms, or quote a measurement in the description. A stated claim with no test is not enough.

Smaller: the Try: empty commit is noise but harmless. Please also confirm no docs/features entry is needed. This is a header and a health field, so I believe none is.

commented

Every response's Server-Timing now includes lag;dur=<ms>: the worst event-loop lag of the last 10 s. /healthz gives the same number as loopLagMs when the request sends Accept: application/json; without that header it still answers a plain ok. A response with a small app;dur but a slow time to first byte can now be blamed on a stall outside its handler.

src/perf/loop_worst.ts keeps the worst lag in a ring of ten one-second slots. The existing 50 ms sampler in kernel/loop_lag.ts feeds it, and the first server to start launches one unref'd timer for it. Tests that list a request's own timing phases read requestTiming(), which leaves the lag token out.

Tick cost (review box 1). The window in test/loop-worst.test.ts now has a test that runs note then worst 100,000 times and fails unless the average is under 0.1 ms. Run on its own here, the same loop averaged 0.12–0.13 µs per tick, about 800 times under the bound.

Preview, 30 requests to /nope (review box 4). Rerun on this branch's preview just before this push:

  • App lag: lag;dur stayed between 3.5 and 5.7 ms on all 30. app;dur was 2.3–7.3 ms.
  • Normal requests: time to first byte was about 0.64–0.95 s, almost all of it the route from the sandbox to the forge.
  • Slow requests: #5 took 1.43 s (forge-ttfb 479 ms), #16 took 1.67 s (forge-ttfb 11.9 ms), #21 took 1.43 s (forge-ttfb 332 ms) and #30 took 2.33 s (forge-ttfb 1625 ms). Each had lag;dur of 3.5–5.7 ms, so in none of them was the app's loop blocked. The time went to the forge's proxy or the network.
  • /healthz: with Accept: application/json it returned {"ok":true,"loopLagMs":6.5}.

Docs. There is no new docs/features entry. I added one sentence to docs/features/performance-watcher.md, which already describes each module in src/perf/, saying what loop_worst.ts does.

Not done. The lag is not stored per route or kept beyond the 10 s window; perf/loop.ts already names routes in its loop log line. The empty "Try:" commit stays: removing it would need a force push, which is refused.

Checks. bun scripts/gate.ts and bun x tsc --noEmit pass. So do test/loop-worst.test.ts, test/perf-loop-lag-attribution.test.ts and test/readme-cap.test.ts. I did not run the rest: scripts/fast.ts named 1,674 test files (an estimated 143 minutes), so the forge's full check covers them on this push.

To try it: curl -sD - https://lab--10292--forge-trevato-apps.open-platform.sh/nope -o /dev/null | grep -i server-timing shows lag;dur. curl -H 'accept: application/json' https://lab--10292--forge-trevato-apps.open-platform.sh/healthz shows loopLagMs.

🤖 Generated with Claude Code

Approved

Approved. The preview shows lag;dur on /nope (36.4 ms on my request) and /healthz with Accept: application/json answers {"ok":true,"loopLagMs":19.2}. The module is small and one-concept, the sampler is unref and idempotent, the window is O(1) per tick, the token stays out of the perf record, the plain ok body is kept for strangers, and AGENTS.md and the performance-watcher doc are updated. Nothing is added to README. Both earlier asks are met: the tick-cost test is added, and the 30-request preview quote is in the description. I could not run the tests here: the clone is on main and does not have the pull head.

Non-blocking: the empty Try: commit stays because force pushes are refused.

Sign in to join this conversation.

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs