Skip to content

perf(ppr): eager tail handover — first tail byte no longer waits for the resume shell; server-side segment timings + absolute tail/match taps - #693

Merged
ivogt merged 3 commits into
mainfrom
debug/segment-render-timings
Jul 5, 2026
Merged

ivogt merged 3 commits into
mainfrom
debug/segment-render-timings

Conversation

@ivogt

@ivogt ivogt commented Jul 5, 2026

Copy link
Copy Markdown
Collaborator

Problem statement

A consumer measuring a PPR HIT saw Server-Timing: handler-total;dur=18 next to a 964ms content download and could not attribute the difference: the HIT commits headers at the prelude flush, so every millisecond of live-tail work (match, loaders, Flight, resume) happens inside the response body where Server-Timing structurally cannot report it. The existing debug logs could not attribute it either — the [segments] tree-build logs were window-gated (silent on the server), and the [Server][ppr] taps printed only relative +Nms offsets whose t0 starts when each subsystem is created, so a subsystem that started 700ms late logged an innocent-looking +8ms.

On top of the observability gap, the tail had one real plumbing defect: resumeShellHTML awaited react-dom's resume() before returning the composed stream. resume() resolves only when the resumed shell completes — gated on the live loaders — so the already-flowing Flight bytes sat parked behind the handshake that #691's eager injector had just unparked at the stream level (measured on a consumer app: injector output ready at +9ms, first tail byte on the wire at +735ms).

Changes

1. perf(ppr): eager handover (ssr/index.tsx). resumeShellHTML now constructs the eager injector up front, returns its readable immediately, and pipes the resumed fizz stream in when it materializes (pipeTo closes the writable → injector flush → trailer). A resume() rejection aborts the writable, so the error reaches the response stream instead of hanging it.

Consumer-visible effect on a HIT with slow live loaders: the hydration payload's first bytes now leave the server as soon as the Flight render produces them, instead of after the resume shell completes.

Resume outcome Before After
Success, fast loaders tail streams after resume resolves tail streams immediately (indistinguishable)
Success, slow loaders first tail byte gated on resume shell (= slowest live loader) first tail byte ≈ Flight first chunk
resume() rejects resumeShellHTML promise rejects returned stream errors on read; onError(error, { phase: "rendering" }) fires in both worlds

The one unit test that pinned the old rejection contract is updated to pin the new stream-error contract (shell-handlers.test.tsx, comment explains the handover).

2. debug(router): segment tree-build timings on both sides (segment-system.tsx). The [segments] logs now run server-side too, environment-tagged ([Server][segments] / [Browser][segments]), with new timers on the previously unmeasured awaits: per-segment build ms, action component await, forceAwait content await, decodeLoaderResults. SSR-pass stalls (blocking loader awaits during fizz) were previously invisible.

3. debug(ppr): absolute timestamps + tail/match brackets (rsc-rendering.ts, inject-rsc-eager.ts, match-handlers.ts). Every [Server][ppr] tap co-prints an absolute performance.now() stamp, and new taps bracket loader-seed build, tail match, tail stream handover, tail completion (duration + bytes), and match context-build vs pipeline-collect. Together they narrate a HIT tail from serve start to last byte.

All of it is gated on the baked INTERNAL_RANGO_DEBUG flag and DCE'd from production bundles when off — zero cost for consumers not debugging.

End-to-end consumer example

Field run on the storefront that motivated this (workerd preview, INTERNAL_RANGO_DEBUG=1, PPR homepage HIT):

[Server][ppr] shell HIT: prelude enqueued (2675649b) +0ms
[Server][ppr] shell HIT: loader seed built +1ms   (abs …755648)
[Server][ppr] shell HIT: tail match done +413ms   (abs …756061)   ← the residual latency, named
[Server][ppr] flight render: first chunk +11ms    (abs …756072)
[Server][ppr] shell HIT: tail stream handed over +425ms
[Server][ppr] shell HIT: first tail chunk on the wire +425ms
[Server][ppr] shell HIT: tail complete +493ms (1088888b)

With these brackets the app's residual tail latency decomposed to per-session upstream auth bootstrap awaited inside its chrome loaders' containers (709ms fresh session → 247ms warm) — an app-fixable pattern — while proving the router's own plumbing is ~40ms end to end. Before this PR the same page read as "964ms, unexplained, invisible to Server-Timing."

Test plan

  • Eager handover: full PPR surface green after the change — shell-cache + shell-secure + shell-cache-action + semantic-matrix (107, dev + production) and cloudflare-basic ppr-shell (38, dev + production, workerd/KV).
  • shell-handlers.test.tsx resume-error test updated red→green to the stream-error contract (19/19 in file); onError phase assertion unchanged.
  • Debug additions are log-only: internal-debug-fe + shell-cache suites green (58); the no-flag negative test still proves silence when INTERNAL_RANGO_DEBUG is off.
  • Full gate: pnpm run typecheck, pnpm run test:unit:all (0 failures, 5010 tests), pnpm run lint, pnpm run format; no *.gen.ts changes (no route changes).

Notes

  • The debug logs are deliberately permanent (consumer request): they are the only instrument that can see post-header tail work, and the flag bakes to false for everyone else.
  • Server-side [Server][segments] lines have no request correlation — segment-system is shared client code and cannot import request-context (node:async_hooks would enter the browser bundle); correlate by timestamp + segment ids.
  • Known follow-up candidates surfaced by the field run, deliberately not in this PR: server-side de-prioritization of prefetch renders while a document tail streams (prefetch renders starve the interactive tail in a busy isolate), and a docs note steering session/token acquisition inside the nested (live-shaped) promise so loader containers return instantly.

ivogt added 3 commits July 5, 2026 21:37
…lete tap

Server-Timing headers structurally cannot account for a shell HIT's real
work: the HIT commits headers at the flush (~25ms TTFB), and ALL live-tail
time — match, loaders, Flight, resume — happens inside the response body
afterward (measured: handler-total 18ms vs 964ms of content download).

The [segments] logs now run on BOTH sides, environment-tagged
([Server][segments] vs [Browser][segments]), so the SSR pass's blocking
loader awaits inside the tail become visible. New timers on the previously
unmeasured awaits: per-segment build ms, action component await, forceAwait
content await, decodeLoaderResults. serveShellHit gains a tail-complete tap
(duration + bytes) bounding the post-header window end to end.

All flag-gated (baked INTERNAL_RANGO_DEBUG; DCE'd from prod bundles when
off). internal-debug-fe + shell-cache 58 passed; units 0 failures.
…g resume()

react-dom's resume() promise resolves only when the resumed shell completes,
which waits on the live loaders — so `await resume(...).pipeThrough(injector)`
parked the already-flowing Flight bytes behind the HANDSHAKE even after the
injector fix removed the in-stream parking. Measured on a consumer HIT with
~700ms upstream latency: injector output ready at +9ms, first tail byte on
the wire at +735ms.

resumeShellHTML now constructs the injector transform up front, returns its
readable immediately, and pipes the resumed fizz stream in when it
materializes (pipeTo closes the writable → injector flush → trailer). A
resume() rejection aborts the writable so the response errors instead of
hanging. Full PPR surface green: shell-cache/shell-secure/shell-cache-action/
semantic-matrix 107 + cloudflare ppr-shell 38.
Relative-only (+Nms) taps proved misleading: each tap's t0 starts when its
own subsystem is created, so a late subsystem logs '+8ms' while sitting
hundreds of ms behind serve start. All [Server][ppr] taps now co-print an
absolute performance.now() stamp; new taps bracket loader-seed build, tail
match, tail stream handover, and match context-vs-pipeline — enough to
attribute an entire HIT tail from serve start to last byte.

Field result on the consumer app: with these brackets the residual tail
latency decomposed to per-session SFCC bootstrap awaited inside chrome
loader containers (709ms fresh session -> 247ms warm), not router plumbing.
@pkg-pr-new

pkg-pr-new Bot commented Jul 5, 2026

Copy link
Copy Markdown

Open in StackBlitz

npm i https://pkg.pr.new/@rangojs/router@693

commit: 9ff44fc

@ivogt
ivogt merged commit 55eec49 into main Jul 5, 2026
34 checks passed
@ivogt
ivogt deleted the debug/segment-render-timings branch July 5, 2026 19:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant