Skip to content
Work in progress. These docs describe Spawnite at launch, and some parts are still being built.

Measuring a frame

Frame describes what one frame runs and what each line cost when it was measured. This page describes how to measure it again.

The engine’s own frame bench runs in Node beside its physics bench and prints a table of the loop’s lines, in the loop’s order.

In the browser, the devtools overlay splits every frame while it is mounted: the step, the pose and animation, the transforms and camera, the render and the rest on the CPU, and the GPU’s time where the browser has a timer query, each by its mean and its worst over the last 60 frames. The top bar shows the CPU’s and the GPU’s means, the Frame tab every line, and an agent reads frameSplit off the store; the devtools page says what each line holds.

Inside the step, the profile times each system with no bench to write. spawnite simulate --profile prints each system’s mean and worst milliseconds per step over the last 60 steps, slowest first, with recordPreviousTransforms among them; --json carries them as profile. The MCP’s simulate tool takes profile and replies with the same lines under the hash. In the browser, the devtools store’s setProfiling(true) times the running world, and readProfile() reads the same lines. A page opened with ?profile times its step from the start, a production build too, and spawnite play profile opens the build that way and prints the same lines after the frame’s, as profile under --json. The page’s clock reads in steps of 0.1 ms, so a system under that reads as a mean of a few hundredths and a worst of 0.1 or 0. Headless, a world with the StepProfileTrait trait is timed, and readStepProfile(world) reads it. While profiling is off, the step reads no clock.

The browser numbers come from a CPU profile of the built app. Build the game without minification and with a source map, so the profile’s function names and positions map back to the engine’s files, then profile it:

Terminal window
pnpm build --minify=false --sourcemap=true
spawnite play profile --seconds 20

The command serves the build with vite preview and opens it in a headless Chromium at 1920x1080, so nothing shows on the desktop; --headed plays it fullscreen on the screen at the display’s own rate instead, and --window places a visible window. With either, --person hands the page to a person at the window: nothing drives it, the page takes the pointer as a player’s browser does, and the recording starts as the loading screen lifts, as a capture of a person’s own play, as Capturing your own play says. The result’s renderer names the GPU the run got. Once the loading screen has gone, it plays 20 s as a player does: it walks, jumps, strafes and drags the camera round. The first 7 s of the same walk run before the recording, so every clip’s shader has compiled by then. V8 samples the main thread every 100 µs while it plays. The table sums each sample into its function and every function above it, counting a function once per stack, and divides by the frames requestAnimationFrame counted over the same span. Each function is named by the source file and line its source map gives, so an anonymous one, such as the Frameloop’s callback, still has a name. --url profiles a page that is already served, and --json prints the same numbers as fields. The MCP’s profile_game tool takes the same options, functions for each --function and queries for each --query, apart from --probe, --check and the visible windows of --headed and --window, and returns the same fields as JSON; with repeat or several queries it runs the sweep, at most 10 rounds of 5 queries, and returns its JSON, and a run that fails names the folder that holds the runs before it. A game that throws while it plays fails the run, and the command prints the page’s errors in place of numbers that would time a stopped game.

Adding two lines that nest counts the inner one twice: measureEscape calls closestPointToPoint, and three-mesh-bvh’s closestPointToPoint and Rapier’s computeColliderMovement each wrap a function of the same name.

The command also times each frame and counts what it draws. The following options change what it reads:

  • --budget <ms>, 7.5 by default, is the frame’s budget, and framesOver counts the frames that took longer. frameMs spreads each frame’s time, from one requestAnimationFrame to the next, as p50, p95, p99, worst and mean; mainThreadMs spreads the main thread’s, from the frame’s first callback to the end of its task.
  • --no-vsync launches Chromium with --disable-frame-rate-limit --disable-gpu-vsync, so a frame’s time is its cost rather than the display’s period.
  • --fps <n> paces the page’s frame callbacks to a rate, each at the first display tick past its 1/n s, as the check’s pinned run does. Beside --no-vsync the ticks come as fast as the machine allows, so --no-vsync --fps 120 gives a frame that fits in 8.33 ms the rest of its period, as a 120 Hz display does. A frame that does not fit runs late rather than waiting for the next tick, as a display would make it, so a slow page reads a higher rate than a display would show. The output says paced to 120 fps. Every frame of a paced run takes about 8.33 ms, so --budget 12.5, one and a half periods as the check’s pinned run takes, counts the long frames. It undercounts the ticks a display would miss: a page that takes 10 ms every frame paces to 100 fps with no frame over 12.5 ms, where a display would show 60. A headless Chromium with vsync on runs at the machine’s own display’s rate where it has one, 120 Hz on a 120 Hz screen, and a frame that misses a tick there reads 16.7 ms as on the screen, so on such a machine vsync on with no --fps reads a 120 Hz frame closest. --trace refuses --no-vsync --fps: the pacing waits through hundreds of native frames a second, each of which the trace records, and the page slows to about half its rate.
  • --gpu times each frame’s GL work with EXT_disjoint_timer_query_webgl2 into gpuMs. With vsync on, the query spans the wait for the display, so the command reads GPU time only with --no-vsync and says so otherwise.
  • --gpu-passes times each pass of the GPU’s frame into gpuPasses: the sun’s shadow map, the scene, its resolve out of the multisampled buffer, ambient occlusion with its transparency targets and composite, bloom, the merged effects and the copy to the canvas, each by its own time and its share of the frame, the costliest first. A page opened with ?profile names its passes, since only the engine knows which pass is which; a pass inside another, such as the shadow map inside the scene’s render, reads apart from it, as scene › shadow map, and each frame’s passes sum to its time. The timer query runs one at a time, so the recorder ends one at every pass’s start and end and begins the next, as Chromium’s own GPU timing does. It does this on every other frame, and times the frames between as one query into gpuMs, as --gpu does. Where the GPU is the limit the two agree: Holdfast with four wardens at 3440x1440 read 4.84 ms a frame either way. Where the CPU is, they part, since a query measures the GPU’s clock from its start to its end, idle time while the CPU feeds it included, and on Chrome’s Direct3D backend each query’s end sends the commands queued so far, which keeps the GPU fed: the same game at 1920x1080 read 3.30 ms split against 3.98 whole. Read the passes for where the time goes, and gpuMs against an older run’s. Another timer on the page, such as the devtools overlay’s, takes the context from the split; on a page opened with ?profile the engine’s overlay leaves it to the profile. The browser’s resolve of the canvas’s own samples and its compositing of the canvas run outside the page’s queries. The MCP’s profile_game takes it as gpuPasses.
  • --scene <name> opens the game on one of its registered scenes in place of its start scene, such as the bench page’s dusk, through the address’s ?scene=, which the engine reads on a page opened with ?profile alone. The MCP’s profile_game takes it as scene.
  • --render counts each frame’s WebGL2 calls into gl, each counter’s mean, min and max: the draws, triangles and instances to the screen and into render targets such as the shadow map, the program switches and links, the programs the frame used, and the texture uploads and the buffer uploads apart. A WEBGL_multi_draw call, as a BatchedMesh makes, counts as one draw of all its ranges. The multi-draw calls and the ranges they hold, their sub-draws, are also counted apart, per pass, because ANGLE’s Direct3D 11 backend likely runs each sub-draw as a draw of its own. Only the game’s context is counted: the first WebGL2 context the page makes, which the GPU timer times too.
  • --skip <class> drops one class of draw: rt, rtinstanced, instanced, skinned, rtskinned or sky. What those draws cost is the frame time’s difference from a run that draws them.
  • --probe lists the first recorded frame’s draws into probe, in the order the frame drew them, folded by pass, program, what the program draws, vertex count and instances, with how many draws each holds. A program is numbered in the order the page first used it, and it draws skinned or sky where its uniforms say so. A multi-draw call is one entry, with its ranges’ vertices summed and its sub-draws. Each entry names the three.js objects it folds, each once, by the path of named ancestors down to the object, or by its type where nothing on the path has a name, and their materials by name, or by type where the name is empty. An Entity names its group after its name and an InstancedModel after its model, so a draw reads as Rider, sling-post or Rock/tripo_node_…. A draw three.js did not issue carries no name. The names come from three.js’s devtools hook, which the page defines only under --probe, so a run without it draws as it would anyway.
  • --alloc samples the heap’s allocations into allocations, the objects a collection freed too, since those are the frame’s garbage. allocations.top lists the bytes a frame by call site, a function and up to three callers, each named through the source map. The recorder’s own allocations are left out. V8’s sampler never sees the backing store of a typed array or an ArrayBuffer, which lives outside its heap, so the recorder counts the bytes of each one the page makes while recording and lists them as the site typed arrays' backing stores. A view on a buffer that already exists makes no backing store and counts nothing.
  • --trace records a Chromium trace and reads it between the marks it sets as the recording starts and stops, into trace: the page’s minor and major collections, its paints and its raster tasks, and each task past 4 ms on the GPU process’s main thread as gpuStalls, by what it ran, WebGL commands, the page’s raster or the compositor’s paint, and whether it ran on the CPU or waited. A worker’s collection holds no frame up, so it is not counted. The output prints the paints and the raster a second, and the timeline names each GPU-process task on the hitch it held back, as Finding hitches says. A trace too long for one string, past about a minute with these categories, is read a line at a time.
  • --quality <level>, one of auto, minimum, low, medium or high, plays at that quality level in place of the one the game picks, through the address’s ?quality=.
  • --scale <n> sets the headless page’s device scale, so its drawing buffer is n times the page’s size on each side. A retina laptop draws at 2, and a frame bound by its pixels costs more than twice as much there. A visible window draws at its screen’s own scale, so --headed and --window refuse it.
  • --viewport <width>x<height> sets the headless page’s size in CSS pixels, 1920x1080 when left out, such as 3440x1440 for an ultrawide screen at its own size. The MCP’s profile_game takes it as viewport: { width, height }. A visible window takes its screen’s size, so --headed and --window refuse it.
  • --no-jump plays the walk without its Space, for a game where Space does more than jump. In the sled, Space fires the sling, so a run without it measures the rider held on the sling.
  • --until <expression> keeps playing the walk after its first 7 s until a JavaScript expression holds in the page, then records, so a run measures a point later in the game, such as document.body.innerText.includes('Finish!'). The build mounts no devtools, so the expression reads what the page shows or exposes on window, and the engine’s own camera, loop, cursor and room, such as camera.turned > 90 once the walk has turned the camera a quarter. It fails when the expression does not hold within two minutes.
  • --map-camera <zoom> records under the map editor’s top-down camera, flown out over the map to that zoom of the whole map’s frame, as a screenshot’s --zoom reads one: 3 is where the map camera’s own flight lands, the far stop a creator reaches, and 6 stands twice as close. It serves the dev page, since the map camera is the devtools’ and the build mounts none, turns edit mode on and records once the flight has landed. Nobody plays unless --drive says so, since the walk’s keys pan the map. The MCP’s profile_game takes it as mapCamera. --map-camera 3 --drive idle --render --gpu --no-vsync --no-cpu prices what a creator’s view of the whole map costs, such as the scatter’s far fade.
  • --function <name> times one function a call, and takes another --function for each more. A path on the page’s window, such as createImageBitmap or Worker.prototype.postMessage, is wrapped before the page’s own scripts run, or as the recording starts where the page defines it later, and each call’s synchronous part is timed while the recording runs: the calls, the milliseconds a frame, and a call’s p50, p95, worst and mean, into timedFunctions. Any other name, such as a function inside the game’s bundle, is read from V8’s sampler over the whole profile, not only the table’s top 40, one entry for each script that holds a function of that name, with its calls counted by V8’s precise coverage, which slows the page’s JavaScript a little: the milliseconds a frame and a call’s mean. A name that neither reaches is named in the notes.
  • --keep-profile [folder] keeps the browser’s profile between runs, in the folder given or in one for the game under the temp folder’s spawnite/profile/browsers; the MCP’s profile_game takes it as keepProfile. Without it every run plays on a fresh profile, a first visit, and the first line says which it was. The two differ by Chrome’s disk caches of compiled shader programs: Skia’s for the page’s HTML and CSS, and ANGLE’s for its WebGL. A first visit compiles each program the first time its effect or material appears, on the GPU process’s thread, which holds the next frames back; a return visit, a second run on the same kept profile, loads them from the cache. A returning player’s browser is a return visit, and every new player’s first session is a first visit, so a number states which it came from, beside the machine’s load and the frame clock: on Holdfast, a first visit created 7 of Skia’s programs after the loading screen lifted, each a GPU-process task of 10 ms or more, and the same profile’s return visit created none.
  • --no-cpu leaves the sampler off. The sampler slows every frame, so a run that reads the frame times against the budget passes it.

The machine’s other work moves every number. Run one configuration three times and read the spread before reading a difference.

--repeat <n> runs that for you. Give --query once for each configuration of the page, and the command runs each in turn, round after round, so the machine’s drift over the sweep falls on every configuration alike. Each configuration keeps its runs in a folder of its own under --out, named for its parameters, such as replay=off/1.json, and an empty --query "" adds none and keeps its runs in no-query. Without --out, the sweep goes to a new folder under the temp folder’s spawnite/profile/sweeps, which keeps the newest 20. The command then sets each configuration beside the first, as profile compare sets two folders, or prints one configuration’s runs as a series. Each run prints its phases on stderr as it goes, such as Profile run 3 of 4, replay=off, round 2: recording 20 s, and a line as it ends. A setting that a query parameter reaches is then priced with no source edited between runs:

Terminal window
pnpm spawnite play profile --project holdfast --dev --drive bot --invulnerable --seconds 60 --query "" --query replay=off --repeat 3 --out runs/replay

Performance on main says where each game’s frame time on main is recorded.

Checking a game’s counts

Section titled “Checking a game’s counts”

The machine’s other work moves the timings by about 20%, but it does not move the counts, so the check fails on counts and only prints timings. Each game commits the counts its frame makes in test/profile-baseline.json. Build the game, then run spawnite play profile --check in its folder. One check profiles at a time on a machine: a check holds check.lock, which names its pid, in the profile folder under the system’s temp folder, while it runs. A second check prints once that it waits and for which pid, and gives up after ten minutes, naming the pid. A lock whose pid is gone is removed. An app whose game is one of its routes names that route as spawnite.page in its package.json, as the tools app names /bench, and the check, play profile and play start open it there. A game whose package.json names a spawnite.room, such as the arena, plays in a fresh room of its own: the profile starts the game’s room on a free port and names it in the page’s room parameter, so the frame never depends on whatever else answers on the target’s port. The check profiles the build three times in one configuration, at the high quality level with the sampler off:

  1. Vsync on, with --render and --alloc: the counts and the garbage, at the display’s rate, or at the rate the baseline pins. The run is traced too and reads the page’s HTML counts, paintsPerSecond and rasterTasksPerSecond: a HUD that changes every frame paints every frame, and its raster runs on the GPU process’s thread beside the page’s WebGL, as Frame pacing says.
  2. Vsync off, with --gpu: the GPU’s time.
  3. A still camera, with --drive idle --render for 5 s: the uploads a frame makes while nothing moves.

It prints the runs’ timings and each count beside its baseline, and exits 1 when a count rose past it. When a count rose, it also prints the first-parent merges since the previous row on the same machine in test/profile-history.jsonl that touch the game’s folder, packages/engine or packages/assets, one line each as git log --first-parent --oneline prints them, or says that the history holds no row for this machine or that git cannot read the row’s commit, as in a shallow clone. A count is its highest frame over the walk, because the walk’s timing moves a count’s mean between runs and not its highest frame. The check reads the programs a frame uses rather than its program switches: the order a page’s models load in sets the order three.js draws their materials, which moves the switches from one run of a build to the next, 13 or 16 in the example’s, and not the programs. Four kinds of count may rise a little. The garbage a frame makes may rise by a tenth, because V8 samples it and runs of one build spread by up to 4%. The triangles and the instances of each pass may rise by 3%, because the scatter culls each instance, so the busiest frame’s view moves with the walk’s timing. The HTML counts may rise by a fifth, two a second at least, because a panel that changes on an event, such as a wave’s banner, lands in the walk’s seconds as its timing moves, where a panel that changes every frame adds a paint a frame. A count that only one side holds fails too.

The walk moves the camera every frame, so work a frame redoes while nothing moves, such as the scatter culling and uploading its instances again, hides under the walk’s own. The still camera’s counts are each upload counter’s busiest frame, stillBufferUploads and stillTextureUploads, so an upload that fires only now and then while nothing moves, such as once a second, still counts. The check always records the still camera, so a baseline without these counts fails until --update-baseline writes it again. When a walk’s count rises, the check walks once more and keeps each count’s lower reading, so a one-off frame, such as a model compiled late, does not fail it and a rise that repeats does. The still camera records once, after the page loads and its loading screen lifts, with no warm-up, so an upload in any of its frames counts.

The check also keeps the timings, one row per run of the check in test/profile-history.jsonl beside the baseline, and Performance on main says what a row holds. Other sessions’ load moves the timings, so the check times a fixed spin of arithmetic before and after its runs and prints both, as Spin: 232 ms before the runs, 240 ms after. The median of the spins already in the history on the same CPU is the machine’s floor, so one lucky spin moves nothing. A spin more than 15% over the floor, before or after, prints Under load and appends no row. No timing is corrected by the spin. The check also prints each run’s timings beside the previous row’s on the same machine, for information only. Every run counts a frame over 6.94 ms, the platform’s frame budget, except a run pinned to 60 fps: its frames all take a sixtieth of a second, so it prints the frames that missed the pin and its main-thread milliseconds instead. When the pinned run held under 95% of its rate, the garbage per frame reads high for the rate’s sake, so the check prints garbageBytesPerFrame as inconclusive and leaves it out of the comparison.

When a change adds draws on purpose, spawnite play profile --update-baseline writes the baseline, and the pull request says why. --update-baseline=stillBufferUploads,stillTextureUploads rewrites only the counts it names and leaves the rest of the file as it is; a name the baseline does not hold is an error that lists the names it does. A baseline written with no fps gets "fps": 60, and its runs are pinned to that rate. It takes each count’s highest over three runs of the counts, because a camera that follows a steered character, as the sled’s does, reaches its busiest view at a different moment each run. The check and --update-baseline both draw a headless page at 1920 by 1080, whatever the machine’s display, so every machine sees the same view of the world.

To find the commit that raised a count, check out each commit in turn, build it fresh, and run the check on it.

A frame’s garbage is part per frame and part per second, so it depends on the display’s rate: the sled makes 37,000 bytes a frame at 144 Hz and 57,000 at 60 Hz. A baseline that sets "fps": 60 pins the counts run to 60 frames a second on any display at least that fast, each frame at the first vsync tick past its sixtieth of a second, so a 120 Hz machine reads the counts a 144 Hz one wrote. The arena, the example, the mmorpg and the sled set it. A display slower than the pinned rate runs at its own, and a machine too loaded to hold the rate drops frames: either way the garbage reads high, and the check prints a warning, and the garbage as inconclusive, when the counts run held under 95% of the pinned rate.

A baseline sets "jump": false for a game whose check walks without jumps, and --update-baseline writes it back. The sled sets it: with Space, its walk fires the sling, runs out of steam, plays again and fires again, about every 10 s, and a run that reaches the finish loads the next track inside the recording. Without Space, the rider stays on the sling, the level’s busiest view, for the whole run.

A baseline can also cap a count under caps: a value the count may never read past, whatever the baseline beside it says. The tenth the garbage may rise lets it creep, because each rewrite of the baseline raises the next check’s allowance with it. A cap does not move. The check fails a count past its cap, and --update-baseline writes no baseline while a count reads past one, so a cap moves only by hand, with the reason in the pull request. A cap on a count neither side holds fails, as a count only one side holds does. The arena caps the garbage its frame makes in a room:

{
    "garbageBytesPerFrame": 153926,
    "fps": 60,
    "caps": { "garbageBytesPerFrame": 175000 }
}