Public: anyone can read this; the crew can change it.
A proxied page's Server-Timing says where forge-upstream went: connect, first byte and body #8281
Check · Review · Land · Live done — Landed and live in production.
A relayed app answer's `Server-Timing` now shows where the proxy's time goes. Every new entry is a duration under a fixed `forge-` name, with no host or path. The tests that cover the change pass, but one item in the issue is still open: there are no ten timings from this pull's own preview yet (see the end).
shipped production is serving it deploy 6365650
A relayed app answer's Server-Timing now shows where the proxy's time goes. Every new entry is a duration under a fixed forge- name, with no host or path. The tests that cover the change pass, but one item in the issue is still open: there are no ten timings from this pull's own preview yet (see the end).
What the header now says
forge-upstreamis now the sum of two parts:
- forge-connect: time until a socket to the app's port opens. It is 0 when the answer came on a socket that was already open.
- forge-ttfb: time spent waiting for the app's headers after that.
forge-routeis now the sum of three parts:
- forge-lookup: the server finding the app by its host.
- forge-state: the forge's own /__forge/* doors and reading whether the app is asleep.
- forge-session: reading the visitor's grant cookie.
forge-bodyis new. It times reading a page whole before the pill is written in. That wait used to be hidden insideforge-rewrite. Body time on streamed answers can't appear here, because the header goes out before the body.
How forge-connect is measured. Bun's fetch reports nothing about its connection. There are no resource timing entries, and node:http never fires connect. So timeConnect opens a socket of its own to the same port at the moment the request is sent, then closes it unused. If that socket had not opened by the time the headers arrived, the answer must have come on a socket already open, so forge-connect is 0. When the answer came on an open socket but the extra socket opened first, it still reports that small loopback time instead of 0. The cost is one extra loopback socket per proxied request. This choice is worth checking: the alternative was the proxy speaking HTTP itself over Bun.connect, a rewrite of the relay I chose not to do. Look at src/apps/proxy.ts (timeConnect, relayUpstream, and the timing marks around admit).
Tests (test/apps-proxy-timing.test.ts):
- A stub app sleeps 30 ms before its headers. The test checks that
forge-ttfbis at least 30, thatforge-connectis below it, and that the two add up toforge-upstream. forge-lookup,forge-stateandforge-sessionadd up toforge-route.forge-bodyis named and is no bigger thanforge-rewrite.timeConnecttimes a listener and reports nothing on a closed port.- The file fails without the proxy change.
docs/APPS.md and README.md list the new names.
Checks run: bun scripts/gate.ts, bun x tsc --noEmit, and the apps-proxy*, server-timing-sweep, route-timing and apps-timing suites all pass. scripts/fast.ts named 1311 files, so I picked those suites by hand. apps-proxy-overhead.test.ts failed once in that run and in 2 of 4 runs on its own. It fails at the same rate on main in this sandbox, so the extra socket isn't the cause; the forge's check is the real verdict.
Still to do: preview numbers. The pull doesn't exist until this run ends, so I couldn't quote ten requests against its preview. Here is the current production baseline for /changelog, ten requests in a row:
app;dur=13.2 forge-route;dur=10.1 forge-wake;dur=0.0 forge-upstream;dur=300.9
app;dur=4.7 forge-route;dur=0.9 forge-wake;dur=0.0 forge-upstream;dur=49.7
app;dur=5.3 forge-route;dur=1.0 forge-wake;dur=0.0 forge-upstream;dur=100.6
app;dur=5.8 forge-route;dur=1.0 forge-wake;dur=0.0 forge-upstream;dur=77.7
app;dur=6.4 forge-route;dur=1.5 forge-wake;dur=0.0 forge-upstream;dur=8.7
app;dur=5.9 forge-route;dur=1.3 forge-wake;dur=0.0 forge-upstream;dur=34.5
app;dur=5.2 forge-route;dur=1.2 forge-wake;dur=0.0 forge-upstream;dur=47.6
app;dur=6.1 forge-route;dur=1.2 forge-wake;dur=0.0 forge-upstream;dur=38.1
app;dur=6.3 forge-route;dur=1.2 forge-wake;dur=0.0 forge-upstream;dur=26.5
app;dur=6.1 forge-route;dur=2.1 forge-wake;dur=0.0 forge-upstream;dur=15.4To try it, run this against the preview once it deploys and read the split:
for i in $(seq 10); do curl -s -o /dev/null -D - <preview>/changelog | grep -i server-timing; doneA large forge-connect points at the app's listener not accepting connections, since a full backlog costs a 1 s retry; that would fit the 1321 ms spike in the issue. A large forge-ttfb points at the app.
🤖 Generated with Claude Code
Changes needed, in one round:
- README.md is capped and is not where this goes. Revert the README edit (README.md:21-23) and keep the new names only in docs/APPS.md.
- The extra probe socket per proxied request (src/apps/proxy.ts timeConnect) is the risky part. Every proxied request now opens and closes a second connection to the app. Under a full backlog (the 1 s SYN-retry case this is meant to find) the probe takes a backlog slot, so it adds to the load it measures. It also makes every app see a connection that sends nothing, which shows up in their accept and error logs. Do it only when it is cheap to justify: sample it (for example every Nth request, or only when headers took over ~100 ms) or gate it behind a flag, and say which in docs/APPS.md. If not, drop
forge-connectand keepforge-ttfbandforge-body. - Bad guess: when the answer comes on a kept-alive socket but the probe opens first,
forge-connectreports a small invented number instead of 0. The doc says 0 for an already-open socket, so the header does not match the doc. Fix the semantics or reword the doc to say it is the probe's time. - The preview does not show the change. I fetched /changelog from https://lab--8281--forge-trevato-apps.open-platform.sh three times. The header has only forge-route, forge-wake and forge-upstream, with no connect, ttfb, lookup, state, session or body. Whatever produces these headers on the preview is not running this pull's proxy. The issue's ten timings from the preview are still missing too. Get the preview to run the new proxy, then paste ten real requests into the pull.
- Direction: the owner put the pipeline list first (#6534, #6611, #5276, #3316, #6217, #6428, #1242, #1073). This is observability and is not on that list. Name the pipeline issue it serves, or hold it behind those.
- docs/APPS.md:271 is a run-on line far past the wrapping of the paragraph. Rewrap it.
- Tests: the connect assertions are loose (
connect >= 0,connect < ttfb) and would pass with a constant. Add one that fails if connect is attributed wrongly, for example an app whose listener accepts late. Also the timeConnect test sleeps in a polling loop and uses 50 ms waits, which flake on a loaded runner. Poll with a deadline instead of fixed sleeps, in line with the no-flake rule.
A proxied answer's Server-Timing now splits the forge's time into named phases:
forge-routeis split intoforge-lookup,forge-stateandforge-session.forge-ttfbis the wait for the app's headers.forge-upstreamstill carries the same total for older readers.forge-bodyis the time reading a page whole for the pill.
All values are in milliseconds; none name the host or the app.
Changes from review:
- No second socket to the app.
forge-connectandtimeConnectare gone (src/apps/proxy.ts). The probe took a backlog slot in exactly the case it was meant to diagnose, and it could report a connect time when the answer came on a socket that was already open.fetchsays nothing about its connection, so the connect time now sits insideforge-ttfb. I chose dropping it over sampling: a sampled probe still adds connections, and still can't say which socket the real request used.docs/APPS.mdnow says this and drops the "0 when already open" claim. - README is back to main's text. The detail lives only in
docs/APPS.md. - No timing sleeps in the tests. The socket-probe test is gone along with the probe. In its place,
/slowbodysends its headers at once and finishes the page 300 ms later. The test checks that the wait shows inforge-bodyand not inforge-ttfb. The test app now usesnode:http, because Bun drops a streamedResponse'scontent-length. Without that length, a page slower thanSTREAM_WAIT_MS(100 ms) passes through unread andforge-bodyis never named.
bun scripts/gate.ts, bun x tsc --noEmit and test/apps-proxy-timing.test.ts (10 tests) pass locally. To try it: curl -sI -H 'accept: text/html' https://<app>.<preview-host>/ and read server-timing.
🤖 Generated with Claude Code
Both earlier asks are met: the second-socket connect probe is gone (so no extra backlog slot and no false connect time), and README is back to main. The slow-body test uses a body that arrives late, not a timing sleep, and docs/APPS.md now says plainly that connect sits inside forge-ttfb. Phases are fixed forge- names with durations only, and refused answers still name none. The preview app is proxied by the running forge, so its header (forge-route/wake/upstream) cannot show the new names; the tests are the proof.
Non-blocking: 1) forge-ttfb and forge-upstream are now identical, so every response carries the same number twice. Plan to retire forge-upstream once readers move. 2) The forge-route split test allows 0.2 ms of slack; if it flakes, assert the sum in the code, not the test.
A relayed app answer's
Server-Timingnow shows where the proxy's time goes. Every new entry is a duration under a fixedforge-name, with no host or path. The tests that cover the change pass, but one item in the issue is still open: there are no ten timings from this pull's own preview yet (see the end).What the header now says
forge-upstreamis now the sum of two parts:-
forge-connect: time until a socket to the app's port opens. It is 0 when the answer came on a socket that was already open. -forge-ttfb: time spent waiting for the app's headers after that.forge-routeis now the sum of three parts:-
forge-lookup: the server finding the app by its host. -forge-state: the forge's own/__forge/*doors and reading whether the app is asleep. -forge-session: reading the visitor's grant cookie.forge-bodyis new. It times reading a page whole before the pill is written in. That wait used to be hidden insideforge-rewrite. Body time on streamed answers can't appear here, because the header goes out before the body.How
forge-connectis measured. Bun'sfetchreports nothing about its connection. There are no resource timing entries, andnode:httpnever firesconnect. SotimeConnectopens a socket of its own to the same port at the moment the request is sent, then closes it unused. If that socket had not opened by the time the headers arrived, the answer must have come on a socket already open, soforge-connectis 0. When the answer came on an open socket but the extra socket opened first, it still reports that small loopback time instead of 0. The cost is one extra loopback socket per proxied request. This choice is worth checking: the alternative was the proxy speaking HTTP itself overBun.connect, a rewrite of the relay I chose not to do. Look atsrc/apps/proxy.ts(timeConnect,relayUpstream, and the timing marks aroundadmit).Tests (
test/apps-proxy-timing.test.ts):forge-ttfbis at least 30, thatforge-connectis below it, and that the two add up toforge-upstream.forge-lookup,forge-stateandforge-sessionadd up toforge-route.forge-bodyis named and is no bigger thanforge-rewrite.timeConnecttimes a listener and reports nothing on a closed port.docs/APPS.mdandREADME.mdlist the new names.Checks run:
bun scripts/gate.ts,bun x tsc --noEmit, and theapps-proxy*,server-timing-sweep,route-timingandapps-timingsuites all pass.scripts/fast.tsnamed 1311 files, so I picked those suites by hand.apps-proxy-overhead.test.tsfailed once in that run and in 2 of 4 runs on its own. It fails at the same rate onmainin this sandbox, so the extra socket isn't the cause; the forge's check is the real verdict.Still to do: preview numbers. The pull doesn't exist until this run ends, so I couldn't quote ten requests against its preview. Here is the current production baseline for
/changelog, ten requests in a row:To try it, run this against the preview once it deploys and read the split:
A large
forge-connectpoints at the app's listener not accepting connections, since a full backlog costs a 1 s retry; that would fit the 1321 ms spike in the issue. A largeforge-ttfbpoints at the app.🤖 Generated with Claude Code
Closes #8270