feat(perf): a real produce-to-visible latency series, and the end-to-end figure it makes possible - #412
Conversation
|
Important
This repository does not receive automatic reviews because it has fewer than 10 stars. ⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: ASSERTIVE Plan: Pro Plus Run ID: Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
There was a problem hiding this comment.
Pull request overview
Adds a new performance metric to the RustyNES frontend to measure produce-to-visible latency as a true per-sample distribution (rather than attempting to assemble end-to-end latency from separately-percentiled spans). This improves the Latency Oracle’s “end-to-end” reporting by enabling an optional, more complete wall-clock figure once enough lock-free handoff samples exist.
Changes:
- Stamp frames at publish time in
PresentBufferand return that stamp fromtake_into()so the render path can measure produce→present latency per displayed frame. - Add a new
RenderPerfseries (present_lat) and wire it throughPerfViewinto the debugger/latency UI. - Update the Latency panel to report both a “game delay + render work” figure and an optional “game delay + full pipeline” figure (independently sample-gated).
Reviewed changes
Copilot reviewed 7 out of 7 changed files in this pull request and generated 1 comment.
Show a summary per file
| File | Description |
|---|---|
| to-dos/plans/v2.3.9-crucible-plan.md | Updates the v2.3.9 plan text to correct earlier analysis and describe the new metric/approach. |
| crates/rustynes-frontend/src/present_buffer.rs | Adds per-slot publish stamps and changes take_into() to return Option<Instant> for latency measurement. |
| crates/rustynes-frontend/src/perf.rs | Introduces present_lat series in RenderPerf/PerfView and a recorder method to push samples. |
| crates/rustynes-frontend/src/debugger/perf_panel.rs | Exposes the new present_lat stats in PerfPanelState. |
| crates/rustynes-frontend/src/debugger/mod.rs | Passes the new series into the latency panel from the perf snapshot. |
| crates/rustynes-frontend/src/debugger/latency_panel.rs | Displays the optional full-pipeline p95 figure when enough present_lat samples exist. |
| crates/rustynes-frontend/src/app.rs | Records produce→visible latency after present, using the stamp returned from the lock-free handoff. |
Suppressed comments (1)
crates/rustynes-frontend/src/present_buffer.rs:235
- This test comment refers to
take_intoreturningfalse, but the API now returnsNonewhen no new frame is available.
// No new frame -> take returns false and leaves `out` intact.
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
|
@coderabbitai review |
|
…dant annotation Two review findings on #412. Copilot, and it is a real defect: `take_into`'s doc comment still described a `bool` return, in a PR whose whole subject is that it now returns `Option<Instant>`. A doc that contradicts its own signature is the class this release keeps finding, arriving here in the smallest possible form. Rewritten to say what the stamp IS -- the instant the emulation thread published that frame, carried per slot so it travels with the frame it describes -- and why it exists, since a per-sample total is the only way to build a distribution that summing percentiles cannot. A test comment saying "take returns false" is corrected with it. Antigravity reported a BLOCKING build failure: `present_stamp` annotated `Option<std::time::Instant>` against a `web_time::Instant` return, "a distinct newtype wrapper on native targets". That is the inverse of how `web_time` works -- it re-exports std's type on native and substitutes its own only on wasm -- so the annotation compiles, which CI on this branch had already demonstrated across every feature combination before the review was posted. Its SUGGESTION is adopted anyway, for a different reason than the one given. The annotation names a second, coincidentally-equal spelling of one type, and it is correct only because this line is native-only and web_time aliases std there. Dropping it lets the type come from `take_into`, which is where it is actually decided. The comment records both the reason and the fact that the reported build failure was not real, so the next reader does not reinstate the annotation to fix a problem that never existed.
|
Antigravity review addressed. The blocking finding is declined as not reproducible; its suggestion is adopted for a different reason. The reported build failure is not real
That is the inverse of how Checked rather than argued — The suggestion is adopted anywayDropping the annotation is right for a reason the review does not give. Both facts are now in a comment at the site — including that the reported build failure was not real — so the next reader does not reinstate the annotation to fix a problem that never existed. For the record
|
|
Tip For best results, initiate chat on the files or code changes.
The reported native type mismatch does not apply. Under the native-only Removing the explicit The reported finding was from Antigravity. CodeRabbit did not review this PR. ✏️ Learnings added
🧠 Learnings usedYou are interacting with an AI system. |
… over-installed (#417) * fix(ci): the apt bounds were calibrated against a claim, and the step over-installed The aarch64 provision failed on three consecutive PRs (#412, #415, #416) in one hour. The log says exactly where, and it is not a mirror outage: attempt 1 update killed at 180s, precisely the timeout attempt 2 update killed at 180s again attempt 3 update succeeded; install killed at 300s MID-DOWNLOAD, the log ending inside `Get:20 gcc-13-aarch64-linux-gnu [21.1 MB]` No apt error appears anywhere in it. The provision was succeeding slowly, and the wrapper converted that into a hard failure three times over -- the shape this release keeps finding, with the sign reversed: a gate that fires on a healthy run rather than one that passes a broken one. It blocked three PRs while reading as infrastructure decay. The bound came from a premise this script asserted and never measured: "a healthy `update` on these runners is a few seconds", which made 180s look like an order of magnitude of headroom. Rewritten to state the arithmetic instead, since that phrasing is precisely what went unchecked. Two independent changes. `apt-get update` now runs ONLY after a direct install has failed. The runner image ships a populated index, so a refresh does not belong on the happy path -- it is the recovery step for the one failure it fixes, an index stale enough that the requested version has moved. Attempt 1 skips it, removing the 180s that killed two of the three attempts before they reached the package at all. Worst case is now 300 + 15 + 600 + 30 + 600 = 1245s, inside the job's 25-minute budget with room for the check. The step also asked for the wrong package, and the comment above it said so without drawing the conclusion: it named `libc6-dev-arm64-cross` as what actually lands the headers, and stated the cross linker is unused because this gate is `cargo check` only. So it installed a whole cross toolchain to obtain a dependency it had already identified -- 20+ packages, one of them 21.1 MB, for a set of headers. bindgen runs the HOST clang against `--sysroot` and never invokes the cross compiler. Both ARM targets now install the header package directly, plus `--no-install-recommends`, which is the same argument as the timeout: every byte downloaded is time spent inside a bound. The sufficiency of the narrower package is VERIFIED BY THIS JOB, not asserted -- if the headers are not where the export step points clang, bindgen fails loudly in `cargo check` on the very run that installs it. The loop's branch structure is proven with a stubbed dry run: attempt 1 issues `install` alone, attempts 2 and 3 issue `update` then `install`. shellcheck and actionlint both clean. * fix(ci): re-calibrate again, this time against a Fetched line This change's own first CI run passed, and the log says why the previous bounds could not have: Fetched 4201 kB in 4min 45s (14.7 kB/s) Fourteen point seven kilobytes per second. The mirror is degraded by roughly three orders of magnitude, which is why every bound derived from "healthy" behaviour was wrong -- and why the old 40 MB package set was hopeless rather than unlucky: at that rate it needed about 45 minutes, past the whole job budget. Even at 4.2 MB it only just passed, and not the way the first draft of this comment assumed. The real sequence, read from the log rather than inferred from the exit code: attempt 1 install downloaded all 4201 kB (285s), then was killed at 300s during dpkg unpack -- the download finished, the install did not attempt 2 update, then install: NO re-download, because the archives were already in /var/cache/apt/archives. Succeeded. So the run was rescued by apt's archive cache persisting across attempts. That is a genuinely useful property -- each attempt makes progress instead of starting over -- but it was undesigned and undocumented, which puts it in the same class as the bound it rescued: behaviour nobody wrote down, working by accident, and indistinguishable from a design until it stops. It is now written down and no longer load-bearing. INSTALL_TIMEOUT is sized so ONE attempt completes at the worst speed actually observed: 285s of download plus dpkg, so 600s is about 2x that. ATTEMPTS drops to 2 to keep the worst case inside the job's 25 minutes -- 600 + 15 + (180 + 600) = 1395s plus ~45s of surrounding steps. The third attempt is no loss: attempt 2 already retries with a refreshed index AND a warm download cache, covering both the stale index and the slow mirror, so a third would only repeat it. * fix(ci): `--` before the package operand Both reviewers raised it independently on #417. `APT_PACKAGE` comes from a workflow `env:` block and never from event data, so this is not closing a live injection path -- but it is one token that makes the guarantee structural rather than dependent on every future caller remembering where the value came from. A value beginning with a hyphen is now an operand, not an option.
…mple v2.3.9 item C's missing half. The interim figure is `lag + render_work.p95`, valid only because the lag term is a constant, and it excludes the vblank wait, lock contention, and the time a produced frame spends waiting in the handoff. Those cannot simply be added: `work`, `lock` and `wait` are separate percentile series, and summing two p95s is not the p95 of the sum — the defect `RenderPerf::work` already exists to avoid, in the addition direction rather than the subtraction one. A distribution can only be built from per-sample totals, so the total is now measured per sample. `PresentBuffer` stamps each frame when the emulation thread publishes it; `take_into` returns that stamp; the redraw handler records `stamp.elapsed()` AFTER the present. One sample spans the whole pipeline — publish, the wait in the handoff, this redraw's work, and the blocking present that puts the frame on screen. A correction to my own earlier analysis, which said neither end-to-end figure was implementable from existing data. That was wrong for one of them: `render_total` already exists and is a single per-redraw series covering work + lock + wait, so `lag + render_total.p95` is valid arithmetic today. It measures the redraw HANDLER though, not the frame's journey — it cannot see time spent waiting in the handoff — which is why this series is still the right instrument and not merely a tidier one. Only the lock-free handoff path contributes, because it is the only path where a frame crosses a thread boundary and can therefore wait. A redraw that re-presents the previous frame contributes nothing: its age would be measured from a publish two redraws ago and would describe the display's cadence rather than the pipeline's latency. Two mutations failed to be caught, and both taught something worth writing down rather than papering over: Returning the newest publish stamp instead of the taken slot's fails NO test — because `publish` always swaps into `ready` and `take_into` always takes `ready`, so under the lock those cannot differ. My first comment claimed per-slot stamps were necessary to avoid attributing a new timestamp to an old frame. That was wrong, and the comment now says so, keeping per-slot storage for the honest reason: a timestamp is a property OF the frame, so it travels with it and stays correct if the handoff ever hands back something other than the newest slot. Clearing the stamps in `reset()` likewise fails no test, because `has_new` is cleared there and `take_into` returns before touching a stamp while it is false. Kept as defensive, and labelled as such rather than as coverage. `take_into` returns `Option<Instant>` in place of `bool`; the five existing tests move from `assert!(..)` to `.is_some()` / `.is_none()` with no semantic change. Verified: fmt, workspace clippy, `emu-thread` / `debug-hooks` / `full` combos, both wasm32 invocations, rustdoc, frontend suite at 525. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The plan recorded that item C was "not implementable from the data that exists". That was too strong, and found by building the thing rather than re-reading the claim. `render_total` already exists and is a single per-redraw series covering work + lock + wait, so `lag + render_total.p95` is valid arithmetic today: a constant plus ONE series, which is exactly the case the constant-shift argument rescues. The original claim was right about the two figures as I had specified them and wrong about the data available to compute them. What `render_total` cannot see is the time a produced frame spends waiting in the handoff before a redraw picks it up — it measures the redraw HANDLER, not the frame's journey. Under the triple buffer those are different quantities, and the second is what "end-to-end" means. So the new series is still the right instrument rather than merely a tidier one. Recorded as a correction beside the original reasoning rather than a rewrite, because the reasoning was sound and only its conclusion overreached — and because "I checked and it was narrower than I said" is more useful to the next reader than a page that was always right. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…ists Completes v2.3.9 item C. The previous commit added the produce-to-visible series and stopped there — the panel still showed only the interim figure, so the measurement existed and nobody could see it. Building an instrument and not wiring it to the surface is the shape of defect this release line opened with. The panel now leads with `game delay + full pipeline` when that series has samples, and reports the render-work figure beneath it as context: "of which render work is about N ms; the rest is the frame waiting to be shown". That second clause is the point of having built the series — the gap between the two numbers IS the handoff wait, which no existing series could see. Both figures remain `constant + ONE series`, which is the only arithmetic that yields a real percentile. Neither is a sum of percentiles, and the enum carries that reasoning at the field rather than in a comment somewhere upstream. `full_ms` is an `Option`, gated on ITS OWN sample count rather than the work series'. The two fill from different paths — every redraw feeds `work`, only a redraw that took a new frame from the handoff feeds this one — so borrowing the other's sufficiency would publish a percentile over a handful of samples as though it were over hundreds. `None` there means "this path produced no samples", which is neither zero nor the same as the work figure, and the panel says which. Two tests, two mutations. Making the full figure borrow the work series' sample count fails the first; making it use the work p95 fails the second, because that test asserts the full figure is strictly LARGER — the whole pipeline cannot be cheaper than one span of it. Verified: fmt, workspace clippy, `emu-thread` / `debug-hooks` / `full` combos, both wasm32 invocations, rustdoc, frontend suite at 527. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…dant annotation Two review findings on #412. Copilot, and it is a real defect: `take_into`'s doc comment still described a `bool` return, in a PR whose whole subject is that it now returns `Option<Instant>`. A doc that contradicts its own signature is the class this release keeps finding, arriving here in the smallest possible form. Rewritten to say what the stamp IS -- the instant the emulation thread published that frame, carried per slot so it travels with the frame it describes -- and why it exists, since a per-sample total is the only way to build a distribution that summing percentiles cannot. A test comment saying "take returns false" is corrected with it. Antigravity reported a BLOCKING build failure: `present_stamp` annotated `Option<std::time::Instant>` against a `web_time::Instant` return, "a distinct newtype wrapper on native targets". That is the inverse of how `web_time` works -- it re-exports std's type on native and substitutes its own only on wasm -- so the annotation compiles, which CI on this branch had already demonstrated across every feature combination before the review was posted. Its SUGGESTION is adopted anyway, for a different reason than the one given. The annotation names a second, coincidentally-equal spelling of one type, and it is correct only because this line is native-only and web_time aliases std there. Dropping it lets the type come from `take_into`, which is where it is actually decided. The comment records both the reason and the fact that the reported build failure was not real, so the next reader does not reinstate the annotation to fix a problem that never existed.
e8c1bd8 to
653bb15
Compare
Antigravity review (Gemini via Ultra)This PR introduces a real produce-to-visible latency series by timestamping frames at publication and recording their age upon presentation, enabling a complete end-to-end latency metric. Blocking issuesNone found. Suggestions
Nitpicks
Automated first-pass review by |
|
Re-review after the rebase — no blocking issues. Every remaining point is the comment-length suggestion, which has now been raised on four PRs in a row, so it deserves a direct answer rather than a fourth individual decline. This repository has an explicit, opposite rule. From
The generic "add comments sparingly" guidance is a reasonable default; it is not this project's, and a repo-level instruction outranks a default. Matching the surrounding code is itself a review criterion, and the surrounding code looks like this everywhere — On "move it to the commit message or the plan doc": a commit message is not durable in the place it is needed. The question gets asked at the file, months later, by someone changing a constant or deleting a line that looks redundant. This project has repeatedly paid for rationale that lived somewhere else — the v2.3.9 line alone has three cases where a comment asserting an intent, or the absence of one, is exactly how a defect survived releases. Where the criticism does land, and where I have acted on it: a comment that records what a reviewer said without recording what is true is meta-commentary. A comment that records a measurement, a mechanism, or a refuted claim is evidence, and the citation is just its provenance. Where a note was only the former I have cut it; where it is the latter it stays, because the next reader's alternative is to re-derive it or to "simplify" the defect back in. |
The missing half of v2.3.9 item C: a real produce-to-visible latency series, measured per sample.
Why a new series was needed
The interim figure the panel ships today is
lag + render_work.p95— valid only because the lag term is a constant, and adding a constant shifts every percentile by exactly that constant. It excludes the vblank wait, lock contention, and the time a produced frame spends waiting in the handoff.Those cannot simply be added on.
work,lockandwaitare separate percentile series, andp95(A) + p95(B)is notp95(A + B)— the two maxima need not fall on the same sample. That is the defectRenderPerf::workalready exists to avoid, in the addition direction rather than the subtraction one;docs/performance.mdrecords the subtraction case, where the first attempt published a table whosework p95sat below itswork p50.A distribution can only be built from per-sample totals. So the total is now measured per sample.
How
PresentBufferstamps each frame when the emulation thread publishes it;take_intoreturns that stamp; the redraw handler recordsstamp.elapsed()after the present. One sample spans the whole pipeline — publish, the wait in the handoff, this redraw's work, and the blocking present that puts the frame on screen.Only the lock-free handoff path contributes, because it is the only path where a frame crosses a thread boundary and can therefore wait. A redraw that re-presents the previous frame contributes nothing: its age would be measured from a publish two redraws ago and would describe the display's cadence rather than the pipeline's latency.
A correction to my own earlier analysis
I recorded in the v2.3.9 plan that neither end-to-end figure was implementable from existing data. That was wrong for one of them.
render_totalalready exists and is a single per-redraw series covering work + lock + wait, solag + render_total.p95is valid arithmetic today.It measures the redraw handler, though — it cannot see a frame waiting in the handoff — so the new series is still the right instrument rather than merely a tidier one. The plan is corrected accordingly.
Two mutations that were NOT caught, kept as findings
publishalways swaps intoreadyandtake_intoalways takesready, so under the slots lock those cannot differ. My first comment claimed per-slot stamps were necessary to avoid attributing a new timestamp to an old frame — that was wrong. Per-slot storage is kept for the honest reason (a timestamp is a property of the frame, so it travels with it and stays correct if the handoff ever hands back something other than the newest slot), and the comment now says which of those is true.reset()likewise fails no test, becausehas_newis cleared there andtake_intoreturns before touching a stamp while it is false. Kept as defensive and labelled as such rather than as coverage.And then the figure that series makes possible
With a per-sample total in hand, the panel's end-to-end line stops being a single
number.
end_to_end_figurenow returns both:work_ms—lag + render_work.p95, the narrow figure, unchanged and stilllabelled as excluding the vblank wait and lock contention.
full_ms—lag + present_lat.p95, the wall-clock figure, present onlyonce the new series has enough samples.
The two are gated independently:
full_msisOption, arming onpresent_lat.count >= 60without reference torender_work's count. A sessionthat has produced redraws but not yet crossed a thread boundary sixty times
therefore shows the narrow figure alone rather than a figure built on a handful
of samples, and the panel says which one it is showing.
Unavailablekeeps naming both the count it has and the count it needs, so anabsent figure reads as "not yet" rather than as zero — the standing rule that an
empty result is not a passing result.
Signature change
take_intoreturnsOption<Instant>in place ofbool—Nonewhere it returnedfalse. The five existing tests move fromassert!(..)to.is_some()/.is_none()with no semantic change; two new tests cover the stamp itself.Verification
fmt, workspace clippy,
emu-thread/debug-hooks/fullcombos, both wasm32 invocations, rustdoc, frontend suite at 533.No emulation-core file is touched, and no accuracy path — so
test-romsshould be skipped here.