Finding hitches
A game that stutters holds one frame far longer than the rest: a shader that compiles as a monster first draws, a script that blocks the page as a room answers. The spreads Measuring a frame reads hide a frame like that, so every run of spawnite play profile also keeps a timeline from the page’s first frame, and prints each frame longer than --hitch milliseconds, 50 by default, with what it waited on and the event before it. 50 ms is three frames at 60 Hz, the threshold Chrome’s long animation frames use.
For each frame, the timeline keeps the following:
- compile: the time WebGL’s shader compile and link calls held the page, and the programs it waited on, each named by its material and by the object three.js was drawing, such as
MeshStandardMaterial for brute. - texture upload: the time the page’s texture uploads took.
- draw: three.js’s renders, less the compile and upload waits inside them.
- script: the JavaScript outside the renders that V8’s sampler caught, with the three functions it spent most in, named through the source map.
- garbage collection: the collector’s samples.
- other: what none of those explains, the browser’s own work or a wait on the GPU.
- GPU process, with
--trace: the longest task on the GPU process’s main thread across the frame, such asGPU process: the page's raster 16 ms, waiting. That one thread runs the page’s WebGL commands, the raster of its HTML and CSS and the compositor’s paint in turn, so a long task of any of them holds the next frame back while the page’s own frame is short; it names theothertime. Working means the task ran on the CPU, such as the driver building a draw’s vertex layout the first time a model draws; waiting means it sat on the driver or the GPU. - the machine’s load: the share of every core’s time busy in the second the frame ended, which a hitch line names past 70%. Other programs then take the cores the browser’s threads wait for, and a slow frame there is the machine’s, not the game’s.
V8’s sampler runs from the navigation unless --no-cpu turns it off, and without it no frame names its script. The timeline also keeps when each frame’s first callback ran, beside the time the browser handed it, and the output reads the 1% low as the engine’s overlay reads it, over each ten seconds after the lift, on both: the median and the lowest window on the browser’s time, which the overlay reads, and the median on the callbacks’ own, which reads lower wherever something holds a frame’s start back. The timeline’s clock is the page’s own, in seconds from its navigation, as performance.now() counts it.
A frame that ends before the loading screen’s fade has ended is listed apart, longest first, since no player sees it as a hitch; the frames after it are listed in the order they ran. The engine marks the lift on a page opened with ?profile, which the profile opens; a build from before the mark gives it by the page’s [role="progressbar"] leaving the page.
The engine also marks its own events on the page’s performance timeline, under ?profile alone, so a production page opened without it marks nothing:
| Mark | When |
|---|---|
spawn, destroy |
An entity with a model, health or a character spawns or is destroyed, named by its model where it has one. |
load |
three’s loaders let a file go, with its address. |
scene |
A scene mounts, with its name. |
shot |
A weapon fires, sent to the room or fired off one. |
loading stage |
A stage of the loading screen passes, with its name. |
loading screen lifted |
The loading screen’s fade has ended. |
A game adds its own with the browser’s performance.mark(name, { detail }), such as performance.mark("wave", { detail: "3" }), and nothing else: the profile reads every mark on the page. Each hitch names the last mark in the second before it, and the output ends with the frames in the half second after each kind of mark: how many there were, their p99 and longest frame, and the programs linked there.
--drive picks who plays:
walk, the default, plays the walk Measuring a frame describes and records after its first 7 s, as the check does.idleplays nothing, so the world runs on its own, and records from the lift.botrecords from the lift, and plays from what the engine tells a profiled page. It turns the camera toward the nearest living entity with health but a character, fires the primary button at the middle of the screen once it looks at one, walks toward a far one and strafes beside a near one. With none in sight, it sweeps the camera and walks a loop. The engine asks an automated browser for no pointer lock and turns its camera only under one, so the bot’s page reads its canvas as locked while no real lock is ever asked for.
--invulnerable starts the game’s own room with ROOM_INVULNERABLE=1, which gives every character the InvulnerableTrait trait: dealDamage leaves her be, so the bot plays on through a long run.
A game whose package.json names a spawnite.room plays in a fresh room of its own, which the command starts with a heartbeat a second, and the output prints the room’s steps over the recording under the page’s frame times: how many it ran, a step’s mean and longest milliseconds as the room timed each step without its replay checkpoint, as spawnite play room’s table reads them, the longest checkpoint, and its memory. --json and the run’s file carry them as room, each heartbeat with the second of the recording it landed at. --room-env NAME=VALUE sets the room’s environment over its target’s, once for each setting, so a run measures the room’s recording on and off with no edit to package.json:
$ pnpm spawnite play profile --project holdfast --dev --drive bot --invulnerable --seconds 20Frame ms: p50 8.30, p95 8.40, p99 8.50, worst 66.60, mean 8.47.The room ran 1,209 steps over 20 heartbeats in 20.5 s, 59.0 a second: a step took 0.79 ms on average and 6.34 ms at the longest, without its replay checkpoints, the longest of which took 37.97 ms; 221 MB.
$ pnpm spawnite play profile --project holdfast --dev --drive bot --invulnerable --seconds 20 --room-env ROOM_REPLAY=0Frame ms: p50 8.30, p95 8.40, p99 8.50, worst 41.70, mean 8.44.The room ran 1,204 steps over 20 heartbeats in 20 s, 60.2 a second: a step took 0.66 ms on average and 3.13 ms at the longest; 357 MB.A heartbeat counts the steps since the one before it, and the output reads each heartbeat that landed from half an interval into the recording to half an interval past it. A run shorter than ROOM_HEARTBEAT_SECONDS may read none, or one heartbeat that mostly covers time outside it; set it with --room-env for a finer or a coarser reading. spawnite play room reads the same steps from a room its bots play with no page.
report of several runs and compare set the room’s steps beside the page’s readings: the room step mean, the longest room step and, where the room recorded, the longest room checkpoint, each over the whole run whatever --from and --to say. A step takes well under a millisecond, so a step’s time moves past a fifth and 0.1 ms rather than 5 ms. A recording room’s step times leave its checkpoints out, so a comparison of runs with the recording off and on prices what recording adds to each step, and the recording run’s longest room checkpoint, printed in its own output, is the rest. A run’s file keeps checkpointsIn on its room steps, true where a room built before it timed each step without its checkpoint counted them in; compare and a series add a line where their runs differ in it, since the longest room step then differs by a checkpoint’s time with no change in the game:
pnpm spawnite play profile --project holdfast --dev --drive bot --invulnerable --seconds 20 --room-env ROOM_REPLAY=0 --out off/1.jsonpnpm spawnite play profile --project holdfast --dev --drive bot --invulnerable --seconds 20 --out on/1.jsonpnpm spawnite play profile compare off onThis is what a run from the loading screen of Holdfast printed on main at cdbbe9a9, before the loading screen waited for the scene’s shaders:
$ pnpm spawnite play profile --project holdfast --drive idle --seconds 15Timeline from 0.25 to 22.32 s on the page's clock, from its navigation; the loading screen lifted at 7.16 s.Programs linked under the loading screen: 72, 4,754 ms waited on; after it: 26, 174 ms waited on.4 hitches over 50 ms after the loading screen lifted, in the order they ran; the p99 10.1 ms: 7.29 s 468 ms, 0.12 s after loading screen lifted: draw 6 ms, script 461 ms (getNativeRtpCapabilities mediasoup-client/lib/handlers/Chrome111.js:83 457 ms, ...), garbage collection 3 ms. 7.75 s 180 ms, 0.59 s after loading screen lifted: compile 148 ms on 7 programs (Material.001, MeshDepthMaterial for Root_Scene/RootNode/Cube/Cube_1, ...), draw 15 ms, script 13 ms (...).When the page marked its loading stages, a line after the first names each stage with its time since the stage before it, such as The loading screen's stages: page 0.49 s, engine 0.44 s, assets 3.12 s, world 0.52 s, shaders 1.20 s.
The next line says what the page downloaded before the loading screen lifted, which is what a player waits for, and by the end of the run: Before the loading screen lifted, the page fetched 6,049,280 bytes in 29 requests, the player's wait; 6,049,280 bytes in 29 requests by the end of the run. The bytes are each response’s transfer size, compressed as it was sent, the page’s own document among them. A response from another origin that sends no Timing-Allow-Origin header counts as a request of 0 bytes. A page that shows no loading screen, such as a model viewer, has no lift to read: with --until <expression> the profile notes when the expression held, and the line reads Before the recording started, the page fetched ... from that moment. --json carries the sums as timelineSummary.downloads. A series and a comparison list the same as rows, the bytes and requests before the lift (or before the recording started) and by the end of the run, where every run kept downloads; a change in bytes under 1,024 counts as the same.
The sums say how much the page fetched, not which files. --har <path> writes every request the page made to a HAR file, with each request’s URL and sizes and no response bodies, so a file the page fetched, or no longer fetches, is read from its URL. A sweep (several --query or --repeat) ignores the path and writes each run’s HAR beside its run file, as <round>.har in the configuration’s folder. To list the URLs a run requested, in the order the page asked for them:
node -e 'for (const { request } of JSON.parse(require("fs").readFileSync(process.argv[1])).log.entries) console.log(request.url)' .work/pr1.harOn the example, play profile --project example --drive idle --seconds 3 --no-cpu --har .work/pr1.har printed this, shortened to the files that matter:
http://localhost:58384/?profile=http://localhost:58384/assets/index-DFpzlAV9.js...http://localhost:58384/assets/rapier-BhH15pMY.js...http://localhost:58384/assets/visor-bot.glbhttp://localhost:58384/assets/draco_wasm_wrapper-fZCQGLGb.jshttp://localhost:58384/assets/draco_decoder-Z1_iN-Ht.wasmA change that stops a page requesting a file, such as the Rapier module on a page with no World, is proved by running this command on a HAR from before and after it and finding the URL gone from the second list. The HAR covers the whole run, so a file that only moves to after the loading screen lifts stays in the list; the bytes before the lift, above, show that move.
Where a real GPU compiles a shader faster than the machine that measured it, the milliseconds shrink and the count of programs linked does not, so read the counts first.
Each run writes the whole of itself, every frame and mark, to a JSON file whose path its output names: spawnite/profile in the system’s temp folder, which keeps the newest 20, or the file --out names, which nothing prunes. --json prints the result with the timeline read in place of its frames, as timelineSummary. Two commands read a file again:
spawnite play profile report <file>prints the run again. Several files, or a folder of them, print as a series: each reading’s median, its lowest and highest, and every run’s value.spawnite play profile compare <before> <after>sets two runs side by side: when the loading screen lifted, the longest frame and the programs linked under it and after it, the hitches, the p99, and each mark’s longest frame. It marks each reading better or worse where a time moved by more than a fifth and 5 ms, or a count moved at all, then prints the hitches and the programs behind each reading that got worse. Each side may be a folder of runs.
Both take --hitch, and --from and --to in seconds on the page’s clock, so a run reads 78 to 90 s alone; the run itself takes them too. A threshold lower than the run’s names no script, since the run kept the samples of the frames over its own.
To check a change for hitches, keep a run from before it, change the game, build it, and compare:
pnpm spawnite play profile --project holdfast --drive bot --invulnerable --seconds 90 --out before.jsonpnpm spawnite play profile --project holdfast --drive bot --invulnerable --seconds 90 --out after.jsonpnpm spawnite play profile compare before.json after.jsonThe other engines answer the same question for a person at a desktop tool. Unreal’s CSV profiler writes a row a frame and its report counts hitches past 60 ms a minute, Insights draws bookmarks and regions on a timeline, and Gauntlet runs a bot for either. Unity’s Profiler flags frames past a target time, and its Profile Analyzer compares two captures marker by marker. Chrome’s own long animation frames name the script a long frame ran, and DevTools draws performance.mark on its timings track. This command answers an agent in text, in the game’s own terms, from the marks the engine already sets and the browser’s own performance.mark.
Capturing your own play
Section titled “Capturing your own play”A headless page has no screen of the player’s, so the last word on a stutter is a minute of a person’s own play on their own screen. One command records it in a game’s build and names each slow frame’s cause:
pnpm build --minify=false --sourcemap=truespawnite play profile --headed --person --trace --hitch 12.5 --budget 12.5 --seconds 60 --out capture.jsonThe window opens fullscreen at the display’s own rate, the loading screen comes up, and the minute starts as it lifts: play as you would, the page takes the mouse as a player’s browser does, and Escape gives it back. When the minute is over the window closes and the output lists each frame past 12.5 ms, one and a half refreshes at 120 Hz, with what it waited on: the page’s own work by part, the GPU process’s task across it, and the machine’s load in its second, then the 1% low as the engine’s overlay reads it. capture.json holds the whole run for spawnite play profile report and compare, and an agent reads the same file when a player reports a stutter.
--trace is what names the GPU process; without it the output still names the page’s own parts, and other stands for the rest. --url takes a page already served in place of --project.