Repository navigation
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
Conversation
…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.
commit: |
9 tasks done
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem statement
A consumer measuring a PPR HIT saw
Server-Timing: handler-total;dur=18next 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+Nmsoffsets whoset0starts 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:
resumeShellHTMLawaited react-dom'sresume()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).resumeShellHTMLnow constructs the eager injector up front, returns its readable immediately, and pipes the resumed fizz stream in when it materializes (pipeTocloses the writable → injector flush → trailer). Aresume()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()rejectsresumeShellHTMLpromise rejectsonError(error, { phase: "rendering" })fires in both worldsThe 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 absoluteperformance.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_DEBUGflag 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):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
shell-handlers.test.tsxresume-error test updated red→green to the stream-error contract (19/19 in file);onErrorphase assertion unchanged.INTERNAL_RANGO_DEBUGis off.pnpm run typecheck,pnpm run test:unit:all(0 failures, 5010 tests),pnpm run lint,pnpm run format; no*.gen.tschanges (no route changes).Notes
falsefor everyone else.[Server][segments]lines have no request correlation — segment-system is shared client code and cannot importrequest-context(node:async_hookswould enter the browser bundle); correlate by timestamp + segment ids.