mirror of
https://github.com/hanzoai/next.js.git
synced 2026-09-24 17:00:51 +00:00
[Bench] Add client-trace attribution pass and document metrics to render-pipeline (#95828)
Added a bunch of stuff to the bench. --- **New metrics in the HTTP benchmark** - Report TTFB per route (time to first body byte), next to total latency. - Report each route's document size, how many bytes are inline Flight payload, and the Flight share. **New script: `pnpm bench:render-pipeline:client`** - Loads each route in Chrome with tracing and 4x CPU throttling, and breaks down where client time goes: evaluating chunks, evaluating inline Flight scripts, compiling, background parsing, GC, time to hydration, and blocking time before hydration. - Also prints FCP/LCP/DOMContentLoaded/load from the same trace, and JS transferred vs parsed. - Off by default, separate from the timing benchmark, since tracing perturbs timing. - Hydration time comes from a small client component added to the fixture root layout that calls `performance.mark`. **Bug fixes** - The benchmark was replacing the fixture's `next.config.js` with an empty one during runs. - If the port was already taken, the benchmark could silently measure whatever server was already running there. Both scripts now refuse to start if something is already on the port. - A server that died on startup used to look like a slow server; now it errors immediately. - One failed request used to abort the whole run and throw away all results. Now it costs one sample and gets counted in `errors`. - Killing an already-dead server used to hang the script. - Bad flags now error upfront instead of crashing at the end. --------- Co-authored-by: Claude Fable 5 <[email protected]>
This commit is contained in:
@@ -98,6 +98,20 @@ Artifacts are written under:
|
||||
- `bench/render-pipeline/artifacts/<run>/node/next-runtime-trace.log`
|
||||
- `bench/render-pipeline/artifacts/<run>/results.json`
|
||||
|
||||
## 5b. Client-side attribution (opt-in)
|
||||
|
||||
When a change can affect client cost (payload shape, chunk layout, hydration),
|
||||
run the traced client pass after the server benchmark (it reuses the build):
|
||||
|
||||
```bash
|
||||
pnpm bench:render-pipeline:client
|
||||
```
|
||||
|
||||
This reports main-thread buckets per route (chunk eval/compile, inline script
|
||||
eval, hydration mark, blocking time, GC) plus FCP/LCP/DCL/load as secondary
|
||||
rows. Compare bucket medians across A/B runs; document bytes and Flight share
|
||||
from the HTTP benchmark are the deterministic cross-check.
|
||||
|
||||
## 6. Analyze hotspots
|
||||
|
||||
```bash
|
||||
|
||||
@@ -1,4 +1,5 @@
|
||||
import React from 'react'
|
||||
import HydrationMark from './ui/hydration-mark'
|
||||
|
||||
export default function Layout({ children }) {
|
||||
return (
|
||||
@@ -6,7 +7,10 @@ export default function Layout({ children }) {
|
||||
<head>
|
||||
<title>My App</title>
|
||||
</head>
|
||||
<body>{children}</body>
|
||||
<body>
|
||||
{children}
|
||||
<HydrationMark />
|
||||
</body>
|
||||
</html>
|
||||
)
|
||||
}
|
||||
|
||||
@@ -0,0 +1,12 @@
|
||||
'use client'
|
||||
import { useEffect } from 'react'
|
||||
|
||||
// Marks shell hydration for the client-trace harness. Effects flush after
|
||||
// the initial hydration commit, so this measures the shell, not streamed
|
||||
// Suspense content that hydrates later.
|
||||
export default function HydrationMark() {
|
||||
useEffect(() => {
|
||||
performance.mark('bench:hydrated')
|
||||
}, [])
|
||||
return null
|
||||
}
|
||||
@@ -109,19 +109,10 @@ echo "======================="
|
||||
echo "Duration: ${DURATION}s per phase | Warmup: ${WARMUP_REQS} reqs"
|
||||
echo "Server: minimal-server (minimalMode: true)"
|
||||
|
||||
cat > next.config.js <<'CONF'
|
||||
module.exports = {}
|
||||
CONF
|
||||
|
||||
echo ""
|
||||
echo "Building..."
|
||||
node "$NEXT_BIN" build &>/dev/null
|
||||
run_benchmark "Node Streams (default)"
|
||||
|
||||
# Restore config
|
||||
cat > next.config.js <<'CONF'
|
||||
module.exports = {}
|
||||
CONF
|
||||
|
||||
echo ""
|
||||
echo "Done."
|
||||
|
||||
@@ -126,6 +126,61 @@ Override with:
|
||||
pnpm bench:render-pipeline --scenario=e2e --routes=/,/streaming/heavy
|
||||
```
|
||||
|
||||
## Per-route document metrics
|
||||
|
||||
Each run reports, per route, alongside latency:
|
||||
|
||||
- **ttfb** — time to first body byte, from stream reading. Catches shell-flush
|
||||
regressions that total latency hides on streaming routes.
|
||||
- **document bytes** — decompressed body size, plus the share of bytes inside
|
||||
inline `self.__next_f.push(...)` Flight scripts and the inline script count.
|
||||
Byte totals are deterministic per build (fixture data is seeded), so any
|
||||
delta in an A/B comparison is a real payload change — no repeat runs needed.
|
||||
They also double as a check that both sides of a comparison rendered the
|
||||
same output. The script *count* is not stable: Fizz wraps whatever Flight
|
||||
rows are pending into one script per flush, so the count varies with write
|
||||
timing. Compare bytes, not counts.
|
||||
|
||||
## Client trace pass (opt-in)
|
||||
|
||||
```bash
|
||||
pnpm bench:render-pipeline:client --build=true
|
||||
```
|
||||
|
||||
Drives Chromium over the production server with CDP tracing and CPU throttling
|
||||
(default 4x) and reports main-thread attribution buckets per route:
|
||||
|
||||
- per-chunk script eval and compile time (with file counts)
|
||||
- inline script eval time (Flight `__next_f.push` scripts plus Fizz's tiny
|
||||
`$RS`/`$RC` boundary-reveal scripts; Flight dominates duration)
|
||||
- off-main-thread streaming parse CPU (`v8.parseOnBackgroundParsing`) —
|
||||
most parse cost for large external chunks lands here, not in the
|
||||
main-thread compile bucket
|
||||
- time to the `bench:hydrated` mark (shell hydration commit)
|
||||
- long tasks / total blocking time before hydration, clipped to the
|
||||
pre-hydration portion of each task (null when the mark is not
|
||||
observed — there is no well-defined window without it)
|
||||
- GC time (top-level `MinorGC`/`MajorGC` pauses only; GC can fire inside
|
||||
eval, so buckets overlap and are not meant to sum to wall time)
|
||||
- JS transferred vs parsed bytes
|
||||
|
||||
The `bench:hydrated` mark comes from a small client component in the
|
||||
fixture root layout (`app/ui/hydration-mark.js`, the shape of an
|
||||
analytics provider). It is part of the measured payload on every route,
|
||||
so byte totals from builds before it was added are not comparable.
|
||||
|
||||
FCP/LCP/DOMContentLoaded/load are extracted from the same trace as secondary
|
||||
rows — sanity anchors, not comparison metrics. Attribution buckets are stable
|
||||
at low sample counts (default 3 per route, cold visit each), so this pass adds
|
||||
minutes, not tens of minutes. Tracing perturbs timing: never use this pass for
|
||||
latency/throughput numbers, and never run it concurrently with the HTTP
|
||||
benchmark. Raw traces land in the artifact dir (`client-trace-<route>.json`,
|
||||
loadable in Chrome DevTools Performance panel or https://ui.perfetto.dev).
|
||||
|
||||
Reuse a server started elsewhere with `--start-server=false --port=<port>`.
|
||||
Chromium comes from the repo's `playwright` dependency; if launch fails, run
|
||||
`pnpm exec playwright install chromium`.
|
||||
|
||||
## Measurement model
|
||||
|
||||
The benchmark uses a **closed-loop** load generator: each concurrent worker
|
||||
|
||||
+299
-115
@@ -3,11 +3,12 @@
|
||||
import { spawn } from 'node:child_process'
|
||||
import { once } from 'node:events'
|
||||
import { existsSync } from 'node:fs'
|
||||
import { access, copyFile, mkdir, readFile, writeFile } from 'node:fs/promises'
|
||||
import { access, copyFile, mkdir, writeFile } from 'node:fs/promises'
|
||||
import { resolve } from 'node:path'
|
||||
import { performance } from 'node:perf_hooks'
|
||||
import { setTimeout as sleep } from 'node:timers/promises'
|
||||
import { fileURLToPath } from 'node:url'
|
||||
import zlib from 'node:zlib'
|
||||
|
||||
const REPO_ROOT = fileURLToPath(new URL('../..', import.meta.url))
|
||||
const NEXT_BIN = resolve(REPO_ROOT, 'packages/next/dist/bin/next')
|
||||
@@ -54,6 +55,11 @@ type BenchStats = {
|
||||
max: number
|
||||
}
|
||||
|
||||
type RequestSample = {
|
||||
totalMs: number
|
||||
ttfbMs: number
|
||||
}
|
||||
|
||||
type FullRoutePhaseResult = {
|
||||
mode: StreamMode
|
||||
route: string
|
||||
@@ -62,12 +68,27 @@ type FullRoutePhaseResult = {
|
||||
errors: number
|
||||
concurrency: number
|
||||
throughputRps: number
|
||||
latency: BenchStats
|
||||
// Null when every request in the phase failed.
|
||||
latency: BenchStats | null
|
||||
ttfb: BenchStats | null
|
||||
}
|
||||
|
||||
// Byte composition of one route's HTML document. Bytes are uncompressed
|
||||
// (undici decompresses before we see the body). Flight bytes are the
|
||||
// contents of inline `self.__next_f.push(...)` scripts.
|
||||
type RouteDocumentInfo = {
|
||||
route: string
|
||||
bytes: number
|
||||
gzipBytes: number
|
||||
inlineFlightBytes: number
|
||||
inlineFlightShare: number
|
||||
inlineFlightScripts: number
|
||||
}
|
||||
|
||||
type FullRunResult = {
|
||||
mode: StreamMode
|
||||
routeResults: FullRoutePhaseResult[]
|
||||
routeDocuments: RouteDocumentInfo[]
|
||||
}
|
||||
|
||||
function parseBoolean(value: string): boolean {
|
||||
@@ -172,8 +193,12 @@ function parseCli(): CliOptions {
|
||||
const args = new Map<string, string>()
|
||||
for (const rawArg of rawArgs) {
|
||||
if (!rawArg.startsWith('--')) continue
|
||||
const [rawKey, rawValue] = rawArg.slice(2).split('=')
|
||||
args.set(rawKey, rawValue ?? 'true')
|
||||
const eq = rawArg.indexOf('=')
|
||||
if (eq === -1) {
|
||||
args.set(rawArg.slice(2), 'true')
|
||||
} else {
|
||||
args.set(rawArg.slice(2, eq), rawArg.slice(eq + 1))
|
||||
}
|
||||
}
|
||||
|
||||
const scenarioRaw = args.get('scenario') ?? 'e2e'
|
||||
@@ -224,7 +249,8 @@ function parseCli(): CliOptions {
|
||||
}
|
||||
}
|
||||
|
||||
function computeStats(samples: number[]): BenchStats {
|
||||
function computeStats(samples: number[]): BenchStats | null {
|
||||
if (samples.length === 0) return null
|
||||
const sorted = [...samples].sort((a, b) => a - b)
|
||||
const min = sorted[0]
|
||||
const max = sorted[sorted.length - 1]
|
||||
@@ -267,16 +293,22 @@ async function ensureNextBuilt() {
|
||||
}
|
||||
}
|
||||
|
||||
function defaultConfig(): string {
|
||||
return 'module.exports = {}\n'
|
||||
}
|
||||
|
||||
async function waitForServerReady(
|
||||
url: string,
|
||||
timeoutMs: number
|
||||
timeoutMs: number,
|
||||
serverDied?: () => boolean
|
||||
): Promise<void> {
|
||||
const start = performance.now()
|
||||
while (performance.now() - start < timeoutMs) {
|
||||
// Without this check, a server that dies on startup (e.g. EADDRINUSE
|
||||
// against a stale server on the same port) is indistinguishable from
|
||||
// a slow one — worse, a 200 from whatever else owns the port would
|
||||
// pass, and the run would silently measure the wrong server.
|
||||
if (serverDied?.()) {
|
||||
throw new Error(
|
||||
`Server process exited before becoming ready (is port already in use?)`
|
||||
)
|
||||
}
|
||||
try {
|
||||
const response = await fetch(url, { cache: 'no-store' })
|
||||
await response.arrayBuffer()
|
||||
@@ -289,10 +321,38 @@ async function waitForServerReady(
|
||||
throw new Error(`Server did not become ready within ${timeoutMs}ms`)
|
||||
}
|
||||
|
||||
async function requestLatencyMs(
|
||||
function spawnedServerDied(server: ReturnType<typeof spawn>): () => boolean {
|
||||
return () => server.exitCode !== null || server.signalCode !== null
|
||||
}
|
||||
|
||||
// The death check alone is racy on a contested port: a stale server can
|
||||
// answer the readiness probe before our child fails to bind, and the run
|
||||
// would silently measure the wrong server.
|
||||
async function assertPortFree(port: number): Promise<void> {
|
||||
const controller = new AbortController()
|
||||
const timeout = setTimeout(() => controller.abort(), 1000)
|
||||
try {
|
||||
await fetch(`http://127.0.0.1:${port}/`, {
|
||||
cache: 'no-store',
|
||||
signal: controller.signal,
|
||||
})
|
||||
} catch {
|
||||
return
|
||||
} finally {
|
||||
clearTimeout(timeout)
|
||||
}
|
||||
throw new Error(
|
||||
`Port ${port} is already serving responses — another server is running. ` +
|
||||
`Stop it or pass a different --port.`
|
||||
)
|
||||
}
|
||||
|
||||
// Reads the body as a stream so TTFB (first body chunk) can be observed
|
||||
// separately from total latency. Byte counts are of the decompressed body.
|
||||
async function measureRequest(
|
||||
url: string,
|
||||
timeoutMs: number
|
||||
): Promise<number> {
|
||||
): Promise<RequestSample> {
|
||||
const controller = new AbortController()
|
||||
const timeout = setTimeout(() => controller.abort(), timeoutMs)
|
||||
|
||||
@@ -302,26 +362,96 @@ async function requestLatencyMs(
|
||||
cache: 'no-store',
|
||||
signal: controller.signal,
|
||||
})
|
||||
await response.arrayBuffer()
|
||||
if (!response.ok) {
|
||||
await response.arrayBuffer().catch(() => undefined)
|
||||
throw new Error(`Request failed (${response.status}) for ${url}`)
|
||||
}
|
||||
return performance.now() - start
|
||||
let ttfbMs = -1
|
||||
if (response.body) {
|
||||
const reader = response.body.getReader()
|
||||
while (true) {
|
||||
const { done } = await reader.read()
|
||||
if (done) break
|
||||
if (ttfbMs < 0) ttfbMs = performance.now() - start
|
||||
}
|
||||
}
|
||||
const totalMs = performance.now() - start
|
||||
if (ttfbMs < 0) ttfbMs = totalMs
|
||||
return { totalMs, ttfbMs }
|
||||
} finally {
|
||||
clearTimeout(timeout)
|
||||
}
|
||||
}
|
||||
|
||||
// Tolerates individual request failures (like the load phase) so one
|
||||
// transient error costs one sample, not the whole run's results.
|
||||
async function runSerialRequests(
|
||||
url: string,
|
||||
count: number,
|
||||
timeoutMs: number
|
||||
): Promise<number[]> {
|
||||
const latencies: number[] = []
|
||||
): Promise<{ samples: RequestSample[]; errors: number }> {
|
||||
const samples: RequestSample[] = []
|
||||
let errors = 0
|
||||
for (let i = 0; i < count; i++) {
|
||||
latencies.push(await requestLatencyMs(url, timeoutMs))
|
||||
try {
|
||||
samples.push(await measureRequest(url, timeoutMs))
|
||||
} catch {
|
||||
errors++
|
||||
}
|
||||
}
|
||||
return { samples, errors }
|
||||
}
|
||||
|
||||
async function inspectRouteDocument(
|
||||
url: string,
|
||||
route: string,
|
||||
timeoutMs: number
|
||||
): Promise<RouteDocumentInfo> {
|
||||
const controller = new AbortController()
|
||||
const timeout = setTimeout(() => controller.abort(), timeoutMs)
|
||||
try {
|
||||
const response = await fetch(url, {
|
||||
cache: 'no-store',
|
||||
signal: controller.signal,
|
||||
})
|
||||
const text = await response.text()
|
||||
if (!response.ok) {
|
||||
throw new Error(`Request failed (${response.status}) for ${url}`)
|
||||
}
|
||||
const bytes = Buffer.byteLength(text)
|
||||
const gzipBytes = zlib.gzipSync(text).byteLength
|
||||
let inlineFlightBytes = 0
|
||||
let inlineFlightScripts = 0
|
||||
// Inline Flight scripts can carry attributes (e.g. a CSP nonce), so
|
||||
// match any <script ...> tag; the content anchor identifies them.
|
||||
const flightScript = /<script[^>]*>(self\.__next_f\.push\(.*?)<\/script>/gs
|
||||
for (const match of text.matchAll(flightScript)) {
|
||||
inlineFlightBytes += Buffer.byteLength(match[1])
|
||||
inlineFlightScripts++
|
||||
}
|
||||
if (inlineFlightScripts === 0) {
|
||||
// Every App Router document carries inline Flight scripts; a
|
||||
// silent zero would corrupt the flight-share metric.
|
||||
if (text.includes('__next_f')) {
|
||||
throw new Error(
|
||||
`[inspect] ${route}: document contains __next_f but the extraction regex matched no inline Flight scripts — the markup shape changed, update the regex in inspectRouteDocument`
|
||||
)
|
||||
}
|
||||
throw new Error(
|
||||
`[inspect] ${route}: not an App Router document (no __next_f) — this benchmark only measures App Router routes`
|
||||
)
|
||||
}
|
||||
return {
|
||||
route,
|
||||
bytes,
|
||||
gzipBytes,
|
||||
inlineFlightBytes,
|
||||
inlineFlightShare: bytes > 0 ? inlineFlightBytes / bytes : 0,
|
||||
inlineFlightScripts,
|
||||
}
|
||||
} finally {
|
||||
clearTimeout(timeout)
|
||||
}
|
||||
return latencies
|
||||
}
|
||||
|
||||
// Closed-loop load generator: each worker issues the next request only after
|
||||
@@ -334,8 +464,8 @@ async function runConcurrentRequests(
|
||||
totalRequests: number,
|
||||
concurrency: number,
|
||||
timeoutMs: number
|
||||
): Promise<{ latencies: number[]; errors: number }> {
|
||||
const latencies: number[] = []
|
||||
): Promise<{ samples: RequestSample[]; errors: number }> {
|
||||
const samples: RequestSample[] = []
|
||||
let errors = 0
|
||||
let index = 0
|
||||
|
||||
@@ -345,7 +475,7 @@ async function runConcurrentRequests(
|
||||
index++
|
||||
if (current >= totalRequests) return
|
||||
try {
|
||||
latencies.push(await requestLatencyMs(url, timeoutMs))
|
||||
samples.push(await measureRequest(url, timeoutMs))
|
||||
} catch {
|
||||
errors++
|
||||
}
|
||||
@@ -353,7 +483,7 @@ async function runConcurrentRequests(
|
||||
})
|
||||
|
||||
await Promise.all(workers)
|
||||
return { latencies, errors }
|
||||
return { samples, errors }
|
||||
}
|
||||
|
||||
async function copyIfExists(fromPath: string, toPath: string) {
|
||||
@@ -365,6 +495,10 @@ async function copyIfExists(fromPath: string, toPath: string) {
|
||||
}
|
||||
}
|
||||
|
||||
function formatKb(bytes: number): string {
|
||||
return `${(bytes / 1024).toFixed(1)}KB`
|
||||
}
|
||||
|
||||
function printFullResults(label: string, results: FullRunResult[]) {
|
||||
console.log(`\n${label}`)
|
||||
|
||||
@@ -375,6 +509,14 @@ function printFullResults(label: string, results: FullRunResult[]) {
|
||||
result.routeResults.map((entry) => entry.route)
|
||||
)) {
|
||||
console.log(` Route: ${route}`)
|
||||
const document = result.routeDocuments.find(
|
||||
(entry) => entry.route === route
|
||||
)
|
||||
if (document) {
|
||||
console.log(
|
||||
` document ${formatKb(document.bytes)} gzip=${formatKb(document.gzipBytes)} flight=${formatKb(document.inlineFlightBytes)} (${(document.inlineFlightShare * 100).toFixed(1)}%, ${document.inlineFlightScripts} inline scripts)`
|
||||
)
|
||||
}
|
||||
const routeEntries = result.routeResults.filter(
|
||||
(entry) => entry.route === route
|
||||
)
|
||||
@@ -383,9 +525,16 @@ function printFullResults(label: string, results: FullRunResult[]) {
|
||||
console.log(
|
||||
` ${entry.phase} requests=${entry.requests} concurrency=${entry.concurrency}${errorSuffix}`
|
||||
)
|
||||
if (entry.latency === null || entry.ttfb === null) {
|
||||
console.log(` all requests failed`)
|
||||
continue
|
||||
}
|
||||
console.log(
|
||||
` throughput=${entry.throughputRps.toFixed(2)} req/s median=${entry.latency.median.toFixed(2)}ms p95=${entry.latency.p95.toFixed(2)}ms stddev=${entry.latency.stddev.toFixed(2)}ms`
|
||||
)
|
||||
console.log(
|
||||
` ttfb median=${entry.ttfb.median.toFixed(2)}ms p95=${entry.ttfb.p95.toFixed(2)}ms`
|
||||
)
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -422,6 +571,8 @@ function buildNodeArgs(
|
||||
}
|
||||
|
||||
async function gracefulKill(server: ReturnType<typeof spawn>) {
|
||||
// once('exit') never resolves for a child that already exited.
|
||||
if (server.exitCode !== null || server.signalCode !== null) return
|
||||
const tryKill = async (signal: NodeJS.Signals, timeoutMs: number) => {
|
||||
server.kill(signal)
|
||||
const didExit = await Promise.race([
|
||||
@@ -454,9 +605,21 @@ async function runWarmup(
|
||||
let prevMean = Infinity
|
||||
|
||||
for (let batch = 0; batch < (untilStable ? maxBatches : 1); batch++) {
|
||||
const latencies = await runSerialRequests(url, batchSize, timeoutMs)
|
||||
const { samples, errors } = await runSerialRequests(
|
||||
url,
|
||||
batchSize,
|
||||
timeoutMs
|
||||
)
|
||||
totalRequests += batchSize
|
||||
const mean = latencies.reduce((s, v) => s + v, 0) / latencies.length
|
||||
if (samples.length === 0) {
|
||||
throw new Error(
|
||||
`[${label}] warmup: all ${batchSize} requests failed — server is not serving this route`
|
||||
)
|
||||
}
|
||||
if (errors > 0) {
|
||||
console.warn(`[${label}] warmup: ${errors}/${batchSize} requests failed`)
|
||||
}
|
||||
const mean = samples.reduce((s, v) => s + v.totalMs, 0) / samples.length
|
||||
|
||||
if (untilStable && batch > 0) {
|
||||
const delta = Math.abs(mean - prevMean) / prevMean
|
||||
@@ -483,8 +646,12 @@ async function runRoutePhases(
|
||||
options: CliOptions,
|
||||
mode: StreamMode,
|
||||
label: string
|
||||
): Promise<FullRoutePhaseResult[]> {
|
||||
): Promise<{
|
||||
routeResults: FullRoutePhaseResult[]
|
||||
routeDocuments: RouteDocumentInfo[]
|
||||
}> {
|
||||
const routeResults: FullRoutePhaseResult[] = []
|
||||
const routeDocuments: RouteDocumentInfo[] = []
|
||||
|
||||
for (const route of options.routes) {
|
||||
const url = `http://127.0.0.1:${options.port}${route}`
|
||||
@@ -501,23 +668,36 @@ async function runRoutePhases(
|
||||
warmupLabel
|
||||
)
|
||||
|
||||
// One inspection request outside the timed phases: byte composition is
|
||||
// deterministic per build, so a single sample suffices and the text
|
||||
// scan never contaminates latency measurements.
|
||||
routeDocuments.push(
|
||||
await inspectRouteDocument(url, route, options.timeoutMs)
|
||||
)
|
||||
|
||||
console.log(`[${label}/${mode}] route ${route}: single-client phase`)
|
||||
const serialStart = performance.now()
|
||||
const serialLatencies = await runSerialRequests(
|
||||
const serialResult = await runSerialRequests(
|
||||
url,
|
||||
options.serialRequests,
|
||||
options.timeoutMs
|
||||
)
|
||||
const serialDurationMs = performance.now() - serialStart
|
||||
if (serialResult.errors > 0) {
|
||||
console.warn(
|
||||
`[${label}/${mode}] route ${route}: ${serialResult.errors}/${options.serialRequests} serial requests failed`
|
||||
)
|
||||
}
|
||||
routeResults.push({
|
||||
mode,
|
||||
route,
|
||||
phase: 'single-client',
|
||||
requests: options.serialRequests,
|
||||
errors: 0,
|
||||
errors: serialResult.errors,
|
||||
concurrency: 1,
|
||||
throughputRps: options.serialRequests / (serialDurationMs / 1000),
|
||||
latency: computeStats(serialLatencies),
|
||||
latency: computeStats(serialResult.samples.map((s) => s.totalMs)),
|
||||
ttfb: computeStats(serialResult.samples.map((s) => s.ttfbMs)),
|
||||
})
|
||||
|
||||
console.log(`[${label}/${mode}] route ${route}: under-load phase`)
|
||||
@@ -542,11 +722,12 @@ async function runRoutePhases(
|
||||
errors: loadResult.errors,
|
||||
concurrency: options.loadConcurrency,
|
||||
throughputRps: options.loadRequests / (loadDurationMs / 1000),
|
||||
latency: computeStats(loadResult.latencies),
|
||||
latency: computeStats(loadResult.samples.map((s) => s.totalMs)),
|
||||
ttfb: computeStats(loadResult.samples.map((s) => s.ttfbMs)),
|
||||
})
|
||||
}
|
||||
|
||||
return routeResults
|
||||
return { routeResults, routeDocuments }
|
||||
}
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
@@ -558,10 +739,14 @@ async function runMinimalServerSession(
|
||||
mode: StreamMode,
|
||||
modeArtifactDir: string,
|
||||
routeSubset: CliOptions
|
||||
): Promise<FullRoutePhaseResult[]> {
|
||||
): Promise<{
|
||||
routeResults: FullRoutePhaseResult[]
|
||||
routeDocuments: RouteDocumentInfo[]
|
||||
}> {
|
||||
let server: ReturnType<typeof spawn> | null = null
|
||||
try {
|
||||
console.log(`[minimal-server/${mode}] starting server...`)
|
||||
await assertPortFree(options.port)
|
||||
|
||||
const serverArgs = buildNodeArgs(options, modeArtifactDir, mode)
|
||||
serverArgs.push(MINIMAL_SERVER)
|
||||
@@ -579,7 +764,8 @@ async function runMinimalServerSession(
|
||||
|
||||
await waitForServerReady(
|
||||
`http://127.0.0.1:${options.port}${routeSubset.routes[0]}`,
|
||||
options.timeoutMs
|
||||
options.timeoutMs,
|
||||
spawnedServerDied(server)
|
||||
)
|
||||
|
||||
return await runRoutePhases(routeSubset, mode, 'minimal-server')
|
||||
@@ -601,62 +787,56 @@ async function runMinimalServerModeBenchmark(
|
||||
options: CliOptions,
|
||||
mode: StreamMode
|
||||
): Promise<FullRunResult> {
|
||||
const nextConfigPath = resolve(options.appDir, 'next.config.js')
|
||||
const originalConfig = await readFile(nextConfigPath, 'utf8')
|
||||
const modeArtifactDir = resolve(options.artifactDir, mode)
|
||||
|
||||
await mkdir(modeArtifactDir, { recursive: true })
|
||||
|
||||
try {
|
||||
await writeFile(nextConfigPath, defaultConfig())
|
||||
|
||||
if (options.build) {
|
||||
await ensureGeneratedClientGraph(options)
|
||||
console.log(`\n[minimal-server/${mode}] building app fixture...`)
|
||||
await runCommand('node', [NEXT_BIN, 'build'], options.appDir, {
|
||||
...process.env,
|
||||
NEXT_TELEMETRY_DISABLED: '1',
|
||||
})
|
||||
if (options.captureNextTrace) {
|
||||
await copyIfExists(
|
||||
resolve(options.appDir, '.next/trace-build'),
|
||||
resolve(modeArtifactDir, 'next-trace-build.log')
|
||||
)
|
||||
}
|
||||
if (options.build) {
|
||||
await ensureGeneratedClientGraph(options)
|
||||
console.log(`\n[minimal-server/${mode}] building app fixture...`)
|
||||
await runCommand('node', [NEXT_BIN, 'build'], options.appDir, {
|
||||
...process.env,
|
||||
NEXT_TELEMETRY_DISABLED: '1',
|
||||
})
|
||||
if (options.captureNextTrace) {
|
||||
await copyIfExists(
|
||||
resolve(options.appDir, '.next/trace-build'),
|
||||
resolve(modeArtifactDir, 'next-trace-build.log')
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
let routeResults: FullRoutePhaseResult[]
|
||||
const routeResults: FullRoutePhaseResult[] = []
|
||||
const routeDocuments: RouteDocumentInfo[] = []
|
||||
|
||||
if (options.isolateRoutes) {
|
||||
routeResults = []
|
||||
for (let i = 0; i < options.routes.length; i++) {
|
||||
if (i > 0) await sleep(1000)
|
||||
const subset = { ...options, routes: [options.routes[i]] }
|
||||
console.log(
|
||||
`[minimal-server/${mode}] isolate-routes: restarting server for ${options.routes[i]}`
|
||||
)
|
||||
routeResults.push(
|
||||
...(await runMinimalServerSession(
|
||||
options,
|
||||
mode,
|
||||
modeArtifactDir,
|
||||
subset
|
||||
))
|
||||
)
|
||||
}
|
||||
} else {
|
||||
routeResults = await runMinimalServerSession(
|
||||
if (options.isolateRoutes) {
|
||||
for (let i = 0; i < options.routes.length; i++) {
|
||||
if (i > 0) await sleep(1000)
|
||||
const subset = { ...options, routes: [options.routes[i]] }
|
||||
console.log(
|
||||
`[minimal-server/${mode}] isolate-routes: restarting server for ${options.routes[i]}`
|
||||
)
|
||||
const session = await runMinimalServerSession(
|
||||
options,
|
||||
mode,
|
||||
modeArtifactDir,
|
||||
options
|
||||
subset
|
||||
)
|
||||
routeResults.push(...session.routeResults)
|
||||
routeDocuments.push(...session.routeDocuments)
|
||||
}
|
||||
|
||||
return { mode, routeResults }
|
||||
} finally {
|
||||
await writeFile(nextConfigPath, originalConfig)
|
||||
} else {
|
||||
const session = await runMinimalServerSession(
|
||||
options,
|
||||
mode,
|
||||
modeArtifactDir,
|
||||
options
|
||||
)
|
||||
routeResults.push(...session.routeResults)
|
||||
routeDocuments.push(...session.routeDocuments)
|
||||
}
|
||||
|
||||
return { mode, routeResults, routeDocuments }
|
||||
}
|
||||
|
||||
async function runMinimalServerBenchmarks(
|
||||
@@ -687,10 +867,14 @@ async function runE2EServerSession(
|
||||
mode: StreamMode,
|
||||
modeArtifactDir: string,
|
||||
routeSubset: CliOptions
|
||||
): Promise<FullRoutePhaseResult[]> {
|
||||
): Promise<{
|
||||
routeResults: FullRoutePhaseResult[]
|
||||
routeDocuments: RouteDocumentInfo[]
|
||||
}> {
|
||||
let server: ReturnType<typeof spawn> | null = null
|
||||
try {
|
||||
console.log(`[e2e/${mode}] starting production server (next start)...`)
|
||||
await assertPortFree(options.port)
|
||||
|
||||
const serverArgs = buildNodeArgs(options, modeArtifactDir, mode)
|
||||
serverArgs.push(NEXT_BIN, 'start', '--port', String(options.port))
|
||||
@@ -707,7 +891,8 @@ async function runE2EServerSession(
|
||||
|
||||
await waitForServerReady(
|
||||
`http://127.0.0.1:${options.port}${routeSubset.routes[0]}`,
|
||||
options.timeoutMs
|
||||
options.timeoutMs,
|
||||
spawnedServerDied(server)
|
||||
)
|
||||
|
||||
return await runRoutePhases(routeSubset, mode, 'e2e')
|
||||
@@ -729,57 +914,56 @@ async function runE2EModeBenchmark(
|
||||
options: CliOptions,
|
||||
mode: StreamMode
|
||||
): Promise<FullRunResult> {
|
||||
const nextConfigPath = resolve(options.appDir, 'next.config.js')
|
||||
const originalConfig = await readFile(nextConfigPath, 'utf8')
|
||||
const modeArtifactDir = resolve(options.artifactDir, mode)
|
||||
|
||||
await mkdir(modeArtifactDir, { recursive: true })
|
||||
|
||||
try {
|
||||
await writeFile(nextConfigPath, defaultConfig())
|
||||
|
||||
if (options.build) {
|
||||
await ensureGeneratedClientGraph(options)
|
||||
console.log(`\n[e2e/${mode}] building app fixture...`)
|
||||
await runCommand('node', [NEXT_BIN, 'build'], options.appDir, {
|
||||
...process.env,
|
||||
NEXT_TELEMETRY_DISABLED: '1',
|
||||
})
|
||||
if (options.captureNextTrace) {
|
||||
await copyIfExists(
|
||||
resolve(options.appDir, '.next/trace-build'),
|
||||
resolve(modeArtifactDir, 'next-trace-build.log')
|
||||
)
|
||||
}
|
||||
if (options.build) {
|
||||
await ensureGeneratedClientGraph(options)
|
||||
console.log(`\n[e2e/${mode}] building app fixture...`)
|
||||
await runCommand('node', [NEXT_BIN, 'build'], options.appDir, {
|
||||
...process.env,
|
||||
NEXT_TELEMETRY_DISABLED: '1',
|
||||
})
|
||||
if (options.captureNextTrace) {
|
||||
await copyIfExists(
|
||||
resolve(options.appDir, '.next/trace-build'),
|
||||
resolve(modeArtifactDir, 'next-trace-build.log')
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
let routeResults: FullRoutePhaseResult[]
|
||||
const routeResults: FullRoutePhaseResult[] = []
|
||||
const routeDocuments: RouteDocumentInfo[] = []
|
||||
|
||||
if (options.isolateRoutes) {
|
||||
routeResults = []
|
||||
for (let i = 0; i < options.routes.length; i++) {
|
||||
if (i > 0) await sleep(1000)
|
||||
const subset = { ...options, routes: [options.routes[i]] }
|
||||
console.log(
|
||||
`[e2e/${mode}] isolate-routes: restarting server for ${options.routes[i]}`
|
||||
)
|
||||
routeResults.push(
|
||||
...(await runE2EServerSession(options, mode, modeArtifactDir, subset))
|
||||
)
|
||||
}
|
||||
} else {
|
||||
routeResults = await runE2EServerSession(
|
||||
if (options.isolateRoutes) {
|
||||
for (let i = 0; i < options.routes.length; i++) {
|
||||
if (i > 0) await sleep(1000)
|
||||
const subset = { ...options, routes: [options.routes[i]] }
|
||||
console.log(
|
||||
`[e2e/${mode}] isolate-routes: restarting server for ${options.routes[i]}`
|
||||
)
|
||||
const session = await runE2EServerSession(
|
||||
options,
|
||||
mode,
|
||||
modeArtifactDir,
|
||||
options
|
||||
subset
|
||||
)
|
||||
routeResults.push(...session.routeResults)
|
||||
routeDocuments.push(...session.routeDocuments)
|
||||
}
|
||||
|
||||
return { mode, routeResults }
|
||||
} finally {
|
||||
await writeFile(nextConfigPath, originalConfig)
|
||||
} else {
|
||||
const session = await runE2EServerSession(
|
||||
options,
|
||||
mode,
|
||||
modeArtifactDir,
|
||||
options
|
||||
)
|
||||
routeResults.push(...session.routeResults)
|
||||
routeDocuments.push(...session.routeDocuments)
|
||||
}
|
||||
|
||||
return { mode, routeResults, routeDocuments }
|
||||
}
|
||||
|
||||
async function runE2EBenchmarks(options: CliOptions): Promise<FullRunResult[]> {
|
||||
|
||||
@@ -0,0 +1,685 @@
|
||||
// This script must be run with tsx
|
||||
//
|
||||
// Client-side attribution pass for the render-pipeline fixtures. Drives
|
||||
// Chromium over the production server with CDP tracing enabled and
|
||||
// decomposes main-thread time into framework-attributable buckets
|
||||
// (per-chunk script compile/eval, inline Flight script cost, hydration,
|
||||
// GC, long tasks). Paint milestones (FCP/LCP/DCL/load) are extracted from
|
||||
// the same trace as free secondary rows — the buckets are the numbers to
|
||||
// compare, milestones are sanity anchors.
|
||||
//
|
||||
// Tracing perturbs timing, so this is a separate opt-in pass (like
|
||||
// --capture-cpu in benchmark.ts), not part of the default benchmark run.
|
||||
// Attribution buckets are meaningful at low sample counts; the default is
|
||||
// 3 samples per route.
|
||||
|
||||
import { spawn } from 'node:child_process'
|
||||
import { once } from 'node:events'
|
||||
import { existsSync } from 'node:fs'
|
||||
import { access, mkdir, writeFile } from 'node:fs/promises'
|
||||
import { resolve } from 'node:path'
|
||||
import { setTimeout as sleep } from 'node:timers/promises'
|
||||
import { fileURLToPath } from 'node:url'
|
||||
|
||||
import { chromium } from 'playwright'
|
||||
import type { Browser, Page } from 'playwright'
|
||||
|
||||
const REPO_ROOT = fileURLToPath(new URL('../..', import.meta.url))
|
||||
const NEXT_BIN = resolve(REPO_ROOT, 'packages/next/dist/bin/next')
|
||||
|
||||
const TRACE_CATEGORIES = [
|
||||
'devtools.timeline',
|
||||
'disabled-by-default-devtools.timeline',
|
||||
'blink.user_timing',
|
||||
'loading',
|
||||
'v8',
|
||||
]
|
||||
|
||||
type CliOptions = {
|
||||
appDir: string
|
||||
routes: string[]
|
||||
samples: number
|
||||
cpuThrottle: number
|
||||
build: boolean
|
||||
startServer: boolean
|
||||
port: number
|
||||
timeoutMs: number
|
||||
settleMs: number
|
||||
artifactDir: string
|
||||
jsonOut?: string
|
||||
}
|
||||
|
||||
// All times are ms relative to navigationStart. Buckets are sums of
|
||||
// main-thread trace event durations, except parseBackgroundMs which sums
|
||||
// v8.parseOnBackgroundParsing across the renderer's script-streamer
|
||||
// threads — actual off-main-thread parse CPU, not the enclosing
|
||||
// v8.parseOnBackground wall time, which is dominated by waiting for
|
||||
// network bytes. Buckets overlap: compile events nest inside eval
|
||||
// events, and GC pauses can fire inside eval too. They are reported
|
||||
// separately for attribution, not meant to sum to wall time. The
|
||||
// blocking-time fields are null when the bench:hydrated mark was not
|
||||
// observed — without it there is no well-defined pre-hydration window.
|
||||
type TraceSample = {
|
||||
fcpMs: number | null
|
||||
lcpMs: number | null
|
||||
domContentLoadedMs: number | null
|
||||
loadMs: number | null
|
||||
hydratedMs: number | null
|
||||
evalChunksMs: number
|
||||
evalChunkCount: number
|
||||
evalInlineMs: number
|
||||
evalInlineCount: number
|
||||
compileMs: number
|
||||
parseBackgroundMs: number
|
||||
gcMs: number
|
||||
longTasksToHydrated: number | null
|
||||
blockingTimeToHydratedMs: number | null
|
||||
jsTransferBytes: number
|
||||
jsParsedBytes: number
|
||||
jsFileCount: number
|
||||
}
|
||||
|
||||
type RouteTraceResult = {
|
||||
route: string
|
||||
samples: TraceSample[]
|
||||
median: TraceSample
|
||||
}
|
||||
|
||||
type TraceEvent = {
|
||||
name: string
|
||||
cat: string
|
||||
ph: string
|
||||
ts: number
|
||||
dur?: number
|
||||
pid: number
|
||||
tid: number
|
||||
args?: {
|
||||
data?: {
|
||||
url?: string
|
||||
documentLoaderURL?: string
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function parseBoolean(value: string): boolean {
|
||||
return value === '1' || value === 'true' || value === 'yes'
|
||||
}
|
||||
|
||||
function parseNumberArg(
|
||||
args: Map<string, string>,
|
||||
key: string,
|
||||
fallback: number
|
||||
): number {
|
||||
const value = args.get(key)
|
||||
if (value === undefined) return fallback
|
||||
const parsed = Number(value)
|
||||
if (!Number.isFinite(parsed)) {
|
||||
throw new Error(`Invalid numeric value for --${key}: ${value}`)
|
||||
}
|
||||
return parsed
|
||||
}
|
||||
|
||||
function usage() {
|
||||
console.log(`Usage: pnpm bench:render-pipeline:client [options]
|
||||
|
||||
Options:
|
||||
--app-dir=<path> (default: bench/basic-app)
|
||||
--routes=/,/dashboard,... (default: /,/dashboard,/docs,/blog,/tailwind)
|
||||
--samples=<number> (default: 3)
|
||||
--cpu-throttle=<number> (default: 4) CDP CPU throttling rate
|
||||
--build=true|false (default: false) build the fixture first
|
||||
--start-server=true|false (default: true) set false to attach to a
|
||||
server already running on --port
|
||||
--port=<number> (default: 3199)
|
||||
--timeout-ms=<number> (default: 30000)
|
||||
--settle-ms=<number> (default: 750) post-hydration wait so
|
||||
prefetch processing lands in the trace
|
||||
--artifact-dir=<path> (default: bench/render-pipeline/artifacts/<timestamp>-client)
|
||||
--json-out=<path>
|
||||
`)
|
||||
}
|
||||
|
||||
function parseCli(): CliOptions {
|
||||
const rawArgs = process.argv.slice(2)
|
||||
if (rawArgs.includes('--help')) {
|
||||
usage()
|
||||
process.exit(0)
|
||||
}
|
||||
|
||||
const args = new Map<string, string>()
|
||||
for (const rawArg of rawArgs) {
|
||||
if (!rawArg.startsWith('--')) continue
|
||||
const eq = rawArg.indexOf('=')
|
||||
if (eq === -1) {
|
||||
args.set(rawArg.slice(2), 'true')
|
||||
} else {
|
||||
args.set(rawArg.slice(2, eq), rawArg.slice(eq + 1))
|
||||
}
|
||||
}
|
||||
|
||||
const routes = (args.get('routes') ?? '/,/dashboard,/docs,/blog,/tailwind')
|
||||
.split(',')
|
||||
.map((route) => route.trim())
|
||||
.filter(Boolean)
|
||||
if (routes.length === 0) {
|
||||
throw new Error('--routes cannot be empty')
|
||||
}
|
||||
for (const route of routes) {
|
||||
if (!route.startsWith('/')) {
|
||||
throw new Error(`Each route must start with '/': ${route}`)
|
||||
}
|
||||
}
|
||||
|
||||
const samples = parseNumberArg(args, 'samples', 3)
|
||||
if (samples < 1) {
|
||||
throw new Error(`--samples must be at least 1, got ${samples}`)
|
||||
}
|
||||
// CDP rejects rates below 1 (1 = no throttling).
|
||||
const cpuThrottle = parseNumberArg(args, 'cpu-throttle', 4)
|
||||
if (cpuThrottle < 1) {
|
||||
throw new Error(`--cpu-throttle must be at least 1, got ${cpuThrottle}`)
|
||||
}
|
||||
|
||||
const timestamp = new Date().toISOString().replace(/[:.]/g, '-')
|
||||
|
||||
return {
|
||||
appDir: resolve(REPO_ROOT, args.get('app-dir') ?? 'bench/basic-app'),
|
||||
routes,
|
||||
samples,
|
||||
cpuThrottle,
|
||||
build: parseBoolean(args.get('build') ?? 'false'),
|
||||
startServer: parseBoolean(args.get('start-server') ?? 'true'),
|
||||
port: parseNumberArg(args, 'port', 3199),
|
||||
timeoutMs: parseNumberArg(args, 'timeout-ms', 30_000),
|
||||
settleMs: parseNumberArg(args, 'settle-ms', 750),
|
||||
artifactDir: resolve(
|
||||
REPO_ROOT,
|
||||
args.get('artifact-dir') ??
|
||||
`bench/render-pipeline/artifacts/${timestamp}-client`
|
||||
),
|
||||
jsonOut: args.get('json-out'),
|
||||
}
|
||||
}
|
||||
|
||||
async function runCommand(
|
||||
command: string,
|
||||
args: string[],
|
||||
cwd: string
|
||||
): Promise<void> {
|
||||
const child = spawn(command, args, {
|
||||
cwd,
|
||||
env: { ...process.env, NEXT_TELEMETRY_DISABLED: '1' },
|
||||
stdio: 'inherit',
|
||||
})
|
||||
const [code] = (await once(child, 'exit')) as [number | null]
|
||||
if (code !== 0) {
|
||||
throw new Error(
|
||||
`Command failed: ${command} ${args.join(' ')} (exit ${code})`
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
async function waitForServerReady(
|
||||
url: string,
|
||||
timeoutMs: number,
|
||||
serverDied?: () => boolean
|
||||
): Promise<void> {
|
||||
const start = performance.now()
|
||||
while (performance.now() - start < timeoutMs) {
|
||||
// Without this check, a server that dies on startup (e.g. EADDRINUSE
|
||||
// against a stale server on the same port) is indistinguishable from
|
||||
// a slow one — worse, a 200 from whatever else owns the port would
|
||||
// pass, and the run would silently measure the wrong server.
|
||||
if (serverDied?.()) {
|
||||
throw new Error(
|
||||
`Server process exited before becoming ready (is port already in use?)`
|
||||
)
|
||||
}
|
||||
try {
|
||||
const response = await fetch(url, { cache: 'no-store' })
|
||||
await response.arrayBuffer()
|
||||
if (response.ok) return
|
||||
} catch {
|
||||
// server not ready yet
|
||||
}
|
||||
await sleep(200)
|
||||
}
|
||||
throw new Error(`Server did not become ready within ${timeoutMs}ms`)
|
||||
}
|
||||
|
||||
// The death check alone is racy on a contested port: a stale server can
|
||||
// answer the readiness probe before our child fails to bind, and the run
|
||||
// would silently measure the wrong server.
|
||||
async function assertPortFree(port: number): Promise<void> {
|
||||
const controller = new AbortController()
|
||||
const timeout = setTimeout(() => controller.abort(), 1000)
|
||||
try {
|
||||
await fetch(`http://127.0.0.1:${port}/`, {
|
||||
cache: 'no-store',
|
||||
signal: controller.signal,
|
||||
})
|
||||
} catch {
|
||||
return
|
||||
} finally {
|
||||
clearTimeout(timeout)
|
||||
}
|
||||
throw new Error(
|
||||
`Port ${port} is already serving responses — another server is running. ` +
|
||||
`Stop it, pass a different --port, or use --start-server=false to ` +
|
||||
`trace against it deliberately.`
|
||||
)
|
||||
}
|
||||
|
||||
async function gracefulKill(server: ReturnType<typeof spawn>) {
|
||||
// once('exit') never resolves for a child that already exited.
|
||||
if (server.exitCode !== null || server.signalCode !== null) return
|
||||
const tryKill = async (signal: NodeJS.Signals, timeoutMs: number) => {
|
||||
server.kill(signal)
|
||||
const didExit = await Promise.race([
|
||||
once(server, 'exit')
|
||||
.then(() => true)
|
||||
.catch(() => true),
|
||||
sleep(timeoutMs).then(() => false),
|
||||
])
|
||||
return didExit
|
||||
}
|
||||
|
||||
if (!(await tryKill('SIGINT', 3000))) {
|
||||
if (!(await tryKill('SIGTERM', 3000))) {
|
||||
server.kill('SIGKILL')
|
||||
await once(server, 'exit').catch(() => undefined)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function median(values: number[]): number {
|
||||
const sorted = [...values].sort((a, b) => a - b)
|
||||
const mid = Math.floor(sorted.length / 2)
|
||||
// Average the middle pair for even counts: with samples=2, taking the
|
||||
// upper-middle would report every field's worse run.
|
||||
if (sorted.length % 2 === 0) {
|
||||
return (sorted[mid - 1] + sorted[mid]) / 2
|
||||
}
|
||||
return sorted[mid]
|
||||
}
|
||||
|
||||
function medianOrNull(values: Array<number | null>): number | null {
|
||||
const present = values.filter((v): v is number => v !== null)
|
||||
if (present.length === 0) return null
|
||||
return median(present)
|
||||
}
|
||||
|
||||
function medianSample(samples: TraceSample[]): TraceSample {
|
||||
const num = (pick: (s: TraceSample) => number) => median(samples.map(pick))
|
||||
const opt = (pick: (s: TraceSample) => number | null) =>
|
||||
medianOrNull(samples.map(pick))
|
||||
return {
|
||||
fcpMs: opt((s) => s.fcpMs),
|
||||
lcpMs: opt((s) => s.lcpMs),
|
||||
domContentLoadedMs: opt((s) => s.domContentLoadedMs),
|
||||
loadMs: opt((s) => s.loadMs),
|
||||
hydratedMs: opt((s) => s.hydratedMs),
|
||||
evalChunksMs: num((s) => s.evalChunksMs),
|
||||
evalChunkCount: num((s) => s.evalChunkCount),
|
||||
evalInlineMs: num((s) => s.evalInlineMs),
|
||||
evalInlineCount: num((s) => s.evalInlineCount),
|
||||
compileMs: num((s) => s.compileMs),
|
||||
parseBackgroundMs: num((s) => s.parseBackgroundMs),
|
||||
gcMs: num((s) => s.gcMs),
|
||||
longTasksToHydrated: opt((s) => s.longTasksToHydrated),
|
||||
blockingTimeToHydratedMs: opt((s) => s.blockingTimeToHydratedMs),
|
||||
jsTransferBytes: num((s) => s.jsTransferBytes),
|
||||
jsParsedBytes: num((s) => s.jsParsedBytes),
|
||||
jsFileCount: num((s) => s.jsFileCount),
|
||||
}
|
||||
}
|
||||
|
||||
function analyzeTrace(
|
||||
events: TraceEvent[],
|
||||
pageUrl: string,
|
||||
resourceInfo: {
|
||||
transferBytes: number
|
||||
parsedBytes: number
|
||||
fileCount: number
|
||||
}
|
||||
): TraceSample {
|
||||
// Trace event arrays are not guaranteed timestamp-ordered (per-thread
|
||||
// buffers flush independently), so sort before any first/last lookup.
|
||||
const sorted = [...events].sort((a, b) => a.ts - b.ts)
|
||||
|
||||
// The main-thread pid/tid pair is identified by the navigationStart
|
||||
// user-timing event for our document; main-thread buckets filter on it
|
||||
// so worker/compositor/browser-process events never pollute the sums.
|
||||
const navStart = sorted.findLast(
|
||||
(event) =>
|
||||
event.name === 'navigationStart' &&
|
||||
event.cat.includes('blink.user_timing') &&
|
||||
event.args?.data?.documentLoaderURL?.startsWith(pageUrl.split('?')[0])
|
||||
)
|
||||
if (!navStart) {
|
||||
throw new Error(`Trace has no navigationStart for ${pageUrl}`)
|
||||
}
|
||||
const { pid, tid, ts: navTs } = navStart
|
||||
// Redirects (e.g. trailingSlash) can make the final document URL differ
|
||||
// from the requested URL; inline-script eval events carry the former.
|
||||
const documentUrl = navStart.args?.data?.documentLoaderURL ?? pageUrl
|
||||
|
||||
const onMain = (event: TraceEvent) =>
|
||||
event.pid === pid && event.tid === tid && event.ts >= navTs
|
||||
const relMs = (ts: number) => (ts - navTs) / 1000
|
||||
|
||||
const firstInstant = (name: string): number | null => {
|
||||
const event = sorted.find((e) => e.name === name && onMain(e))
|
||||
return event ? relMs(event.ts) : null
|
||||
}
|
||||
const lastInstant = (name: string): number | null => {
|
||||
const event = sorted.findLast((e) => e.name === name && onMain(e))
|
||||
return event ? relMs(event.ts) : null
|
||||
}
|
||||
|
||||
const hydratedEvent = sorted.find(
|
||||
(e) => e.name === 'bench:hydrated' && onMain(e)
|
||||
)
|
||||
const hydratedTs = hydratedEvent?.ts ?? null
|
||||
|
||||
let evalChunksMs = 0
|
||||
let evalInlineMs = 0
|
||||
let evalInlineCount = 0
|
||||
let compileMs = 0
|
||||
let parseBackgroundMs = 0
|
||||
let gcMs = 0
|
||||
let longTasksToHydrated = 0
|
||||
let blockingTimeToHydratedMs = 0
|
||||
const chunkUrls = new Set<string>()
|
||||
|
||||
for (const event of sorted) {
|
||||
if (event.ph !== 'X' || !event.dur || event.ts < navTs) continue
|
||||
const durMs = event.dur / 1000
|
||||
|
||||
// Script streaming parses large external scripts on background
|
||||
// threads of the same renderer process. Sum the nested *Parsing
|
||||
// events (actual parse CPU), not the enclosing v8.parseOnBackground,
|
||||
// whose wall time is mostly waiting on network bytes.
|
||||
if (event.name === 'v8.parseOnBackgroundParsing' && event.pid === pid) {
|
||||
parseBackgroundMs += durMs
|
||||
continue
|
||||
}
|
||||
|
||||
if (event.pid !== pid || event.tid !== tid) continue
|
||||
|
||||
if (event.name === 'EvaluateScript') {
|
||||
const url = event.args?.data?.url ?? ''
|
||||
if (url.includes('/_next/static/')) {
|
||||
evalChunksMs += durMs
|
||||
chunkUrls.add(url)
|
||||
} else if (url === documentUrl) {
|
||||
// Inline scripts carry the document URL. Evals with no URL are
|
||||
// excluded: those are the harness's own waitForFunction/evaluate
|
||||
// calls, not page work. This bucket mixes `self.__next_f.push`
|
||||
// Flight scripts with Fizz's tiny `$RS`/`$RC` boundary-reveal
|
||||
// scripts; the trace does not expose script contents, but Flight
|
||||
// pushes dominate duration.
|
||||
evalInlineMs += durMs
|
||||
evalInlineCount++
|
||||
}
|
||||
} else if (event.name === 'v8.compile') {
|
||||
compileMs += durMs
|
||||
} else if (event.name === 'MinorGC' || event.name === 'MajorGC') {
|
||||
// Only the top-level pause events: the 'v8' category also emits
|
||||
// nested V8.GC_* sub-phase events for the same pauses, and summing
|
||||
// those would multi-count GC time.
|
||||
gcMs += durMs
|
||||
} else if (event.name === 'RunTask' && hydratedTs !== null) {
|
||||
// Count only the pre-hydration portion of the task: the task that
|
||||
// commits hydration typically keeps running afterwards, and its
|
||||
// tail is post-hydration work.
|
||||
const clippedMs =
|
||||
(Math.min(event.ts + event.dur, hydratedTs) - event.ts) / 1000
|
||||
if (clippedMs > 50) {
|
||||
longTasksToHydrated++
|
||||
blockingTimeToHydratedMs += clippedMs - 50
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
return {
|
||||
fcpMs: firstInstant('firstContentfulPaint'),
|
||||
lcpMs: lastInstant('largestContentfulPaint::Candidate'),
|
||||
domContentLoadedMs: firstInstant('MarkDOMContent'),
|
||||
loadMs: firstInstant('MarkLoad'),
|
||||
hydratedMs: hydratedTs !== null ? relMs(hydratedTs) : null,
|
||||
evalChunksMs,
|
||||
evalChunkCount: chunkUrls.size,
|
||||
evalInlineMs,
|
||||
evalInlineCount,
|
||||
compileMs,
|
||||
parseBackgroundMs,
|
||||
gcMs,
|
||||
longTasksToHydrated: hydratedTs !== null ? longTasksToHydrated : null,
|
||||
blockingTimeToHydratedMs:
|
||||
hydratedTs !== null ? blockingTimeToHydratedMs : null,
|
||||
jsTransferBytes: resourceInfo.transferBytes,
|
||||
jsParsedBytes: resourceInfo.parsedBytes,
|
||||
jsFileCount: resourceInfo.fileCount,
|
||||
}
|
||||
}
|
||||
|
||||
async function traceRoute(
|
||||
browser: Browser,
|
||||
options: CliOptions,
|
||||
route: string
|
||||
): Promise<RouteTraceResult | null> {
|
||||
const url = `http://127.0.0.1:${options.port}${route}`
|
||||
const samples: TraceSample[] = []
|
||||
|
||||
for (let i = 0; i < options.samples; i++) {
|
||||
// Fresh context per sample: no HTTP cache or compile cache reuse, so
|
||||
// every sample is a cold visit.
|
||||
const context = await browser.newContext()
|
||||
const page: Page = await context.newPage()
|
||||
let tracing = false
|
||||
try {
|
||||
const cdp = await context.newCDPSession(page)
|
||||
await cdp.send('Emulation.setCPUThrottlingRate', {
|
||||
rate: options.cpuThrottle,
|
||||
})
|
||||
|
||||
await browser.startTracing(page, {
|
||||
screenshots: false,
|
||||
categories: TRACE_CATEGORIES,
|
||||
})
|
||||
tracing = true
|
||||
|
||||
await page.goto(url, {
|
||||
waitUntil: 'load',
|
||||
timeout: options.timeoutMs,
|
||||
})
|
||||
await page
|
||||
.waitForFunction(
|
||||
() => performance.getEntriesByName('bench:hydrated').length > 0,
|
||||
undefined,
|
||||
{ timeout: options.timeoutMs }
|
||||
)
|
||||
.catch(() => {
|
||||
console.warn(
|
||||
`[client-trace] ${route}: bench:hydrated mark not observed (sample ${i + 1})`
|
||||
)
|
||||
})
|
||||
await page.waitForTimeout(options.settleMs)
|
||||
|
||||
const resourceInfo = await page.evaluate(() => {
|
||||
const entries = performance
|
||||
.getEntriesByType('resource')
|
||||
.filter(
|
||||
(entry) =>
|
||||
entry.name.includes('/_next/static/') &&
|
||||
new URL(entry.name).pathname.endsWith('.js')
|
||||
) as PerformanceResourceTiming[]
|
||||
return {
|
||||
transferBytes: entries.reduce((s, e) => s + e.transferSize, 0),
|
||||
parsedBytes: entries.reduce((s, e) => s + e.decodedBodySize, 0),
|
||||
fileCount: entries.length,
|
||||
}
|
||||
})
|
||||
|
||||
const traceBuffer = await browser.stopTracing()
|
||||
tracing = false
|
||||
if (i === 0) {
|
||||
const slug = route.replace(/\W+/g, '-').replace(/^-|-$/g, '') || 'root'
|
||||
await writeFile(
|
||||
resolve(options.artifactDir, `client-trace-${slug}.json`),
|
||||
traceBuffer
|
||||
)
|
||||
}
|
||||
|
||||
const parsed = JSON.parse(traceBuffer.toString('utf8'))
|
||||
const events: TraceEvent[] = Array.isArray(parsed)
|
||||
? parsed
|
||||
: parsed.traceEvents
|
||||
samples.push(analyzeTrace(events, url, resourceInfo))
|
||||
} catch (error) {
|
||||
// A failed sample (navigation timeout, CDP error) should cost one
|
||||
// sample, not the whole run's collected results.
|
||||
console.warn(
|
||||
`[client-trace] ${route}: sample ${i + 1} failed: ${
|
||||
error instanceof Error ? error.message : error
|
||||
}`
|
||||
)
|
||||
} finally {
|
||||
if (tracing) {
|
||||
// Tracing survives context.close(); the next startTracing would
|
||||
// fail if a trace is still active.
|
||||
await browser.stopTracing().catch(() => undefined)
|
||||
}
|
||||
await context.close()
|
||||
}
|
||||
}
|
||||
|
||||
if (samples.length === 0) {
|
||||
console.warn(`[client-trace] ${route}: all samples failed, skipping route`)
|
||||
return null
|
||||
}
|
||||
return { route, samples, median: medianSample(samples) }
|
||||
}
|
||||
|
||||
function formatMs(value: number | null): string {
|
||||
return value === null ? 'n/a' : `${value.toFixed(0)}ms`
|
||||
}
|
||||
|
||||
function formatKb(bytes: number): string {
|
||||
return `${(bytes / 1024).toFixed(1)}KB`
|
||||
}
|
||||
|
||||
function printResults(options: CliOptions, results: RouteTraceResult[]) {
|
||||
console.log(
|
||||
`\nCLIENT TRACE (samples=${options.samples}, cpuThrottle=${options.cpuThrottle}x, cold visit per sample)`
|
||||
)
|
||||
for (const { route, median: m } of results) {
|
||||
console.log(`\n Route: ${route}`)
|
||||
console.log(
|
||||
` milestones FCP=${formatMs(m.fcpMs)} LCP=${formatMs(m.lcpMs)} DCL=${formatMs(m.domContentLoadedMs)} load=${formatMs(m.loadMs)} hydrated=${formatMs(m.hydratedMs)}`
|
||||
)
|
||||
console.log(
|
||||
` main thread eval-chunks=${m.evalChunksMs.toFixed(1)}ms (${m.evalChunkCount} files) eval-inline=${m.evalInlineMs.toFixed(1)}ms (${m.evalInlineCount} scripts) compile=${m.compileMs.toFixed(1)}ms gc=${m.gcMs.toFixed(1)}ms`
|
||||
)
|
||||
console.log(
|
||||
` off thread parse-background=${m.parseBackgroundMs.toFixed(1)}ms`
|
||||
)
|
||||
console.log(
|
||||
` blocking longTasks(pre-hydration)=${m.longTasksToHydrated ?? 'n/a'} tbt=${m.blockingTimeToHydratedMs === null ? 'n/a' : `${m.blockingTimeToHydratedMs.toFixed(1)}ms`}`
|
||||
)
|
||||
console.log(
|
||||
` js ${formatKb(m.jsTransferBytes)} transferred / ${formatKb(m.jsParsedBytes)} parsed (${m.jsFileCount} files)`
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
async function main() {
|
||||
const options = parseCli()
|
||||
|
||||
try {
|
||||
await access(NEXT_BIN)
|
||||
} catch {
|
||||
throw new Error(
|
||||
`Missing ${NEXT_BIN}. Build Next.js first (pnpm --filter=next build).`
|
||||
)
|
||||
}
|
||||
|
||||
await mkdir(options.artifactDir, { recursive: true })
|
||||
|
||||
if (options.build) {
|
||||
const generator = resolve(
|
||||
options.appDir,
|
||||
'scripts/generate-client-graph.mjs'
|
||||
)
|
||||
if (existsSync(generator)) {
|
||||
await runCommand('node', [generator], options.appDir)
|
||||
}
|
||||
console.log('[client-trace] building app fixture...')
|
||||
await runCommand('node', [NEXT_BIN, 'build'], options.appDir)
|
||||
}
|
||||
|
||||
let server: ReturnType<typeof spawn> | null = null
|
||||
let browser: Browser | null = null
|
||||
try {
|
||||
if (options.startServer) {
|
||||
console.log('[client-trace] starting production server (next start)...')
|
||||
await assertPortFree(options.port)
|
||||
server = spawn(
|
||||
'node',
|
||||
[NEXT_BIN, 'start', '--port', String(options.port)],
|
||||
{
|
||||
cwd: options.appDir,
|
||||
env: {
|
||||
...process.env,
|
||||
NODE_ENV: 'production',
|
||||
NEXT_TELEMETRY_DISABLED: '1',
|
||||
},
|
||||
stdio: 'ignore',
|
||||
}
|
||||
)
|
||||
}
|
||||
await waitForServerReady(
|
||||
`http://127.0.0.1:${options.port}${options.routes[0]}`,
|
||||
options.timeoutMs,
|
||||
() =>
|
||||
server !== null &&
|
||||
(server.exitCode !== null || server.signalCode !== null)
|
||||
)
|
||||
|
||||
browser = await chromium.launch()
|
||||
|
||||
const results: RouteTraceResult[] = []
|
||||
for (const route of options.routes) {
|
||||
console.log(`[client-trace] route ${route}: ${options.samples} samples`)
|
||||
const result = await traceRoute(browser, options, route)
|
||||
if (result) results.push(result)
|
||||
}
|
||||
|
||||
printResults(options, results)
|
||||
|
||||
const report = {
|
||||
options,
|
||||
results,
|
||||
generatedAt: new Date().toISOString(),
|
||||
node: process.version,
|
||||
}
|
||||
const reportPath = resolve(options.artifactDir, 'client-trace.json')
|
||||
await writeFile(reportPath, JSON.stringify(report, null, 2))
|
||||
console.log(`\nWrote JSON report: ${reportPath}`)
|
||||
if (options.jsonOut) {
|
||||
await writeFile(
|
||||
resolve(process.cwd(), options.jsonOut),
|
||||
JSON.stringify(report, null, 2)
|
||||
)
|
||||
}
|
||||
} finally {
|
||||
if (browser) await browser.close()
|
||||
if (server) await gracefulKill(server)
|
||||
}
|
||||
}
|
||||
|
||||
main().catch((error) => {
|
||||
console.error(error)
|
||||
process.exit(1)
|
||||
})
|
||||
@@ -15,6 +15,7 @@
|
||||
"dev": "turbo run dev --parallel --filter=\"!@next/bundle-analyzer-ui\"",
|
||||
"bench:render-pipeline": "tsx bench/render-pipeline/benchmark.ts",
|
||||
"bench:render-pipeline:analyze": "tsx bench/render-pipeline/analyze-profiles.ts",
|
||||
"bench:render-pipeline:client": "tsx bench/render-pipeline/client-trace.ts",
|
||||
"pack-next": "tsx scripts/pack-next.ts",
|
||||
"eval": "node run-evals.js",
|
||||
"test-types": "tsc",
|
||||
|
||||
Reference in New Issue
Block a user