feat(perf): tick_lat/tick_iv verified — the trigger is late, not the emulator (F15 + F18) - #366
Merged
Merged
Conversation
|
Warning Review limit reached
Next review available in: 117 minutes You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. How can I continue?After more reviews become available, a review can be triggered using the To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews. How do review limits work?CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability. For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: ASSERTIVE Plan: Pro Plus Run ID: 📒 Files selected for processing (9)
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 and documents new display-trigger timing instrumentation (tick_lat / tick_iv) to close remaining unknowns in the display-sync shudder investigation, and updates the perf-log validity gate so “window mapping” discards don’t falsely invalidate captures.
Changes:
- Add
tick_lat(winit→emu hop) andtick_iv(tick send interval) sampling, logging, and tests in the frontend perf pipeline. - Refine
present_discardedcapture-validity gating to use a post-warmup delta rate instead of failing on a non-zero cumulative counter. - Extend performance documentation and changelog entries with F15/F18 verified findings and corrected methodology notes.
Reviewed changes
Copilot reviewed 9 out of 9 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| scripts/perf/perf_log_check.py | Updates capture validity logic around present_discarded (but currently risks false failures on short final rows; see comment). |
| docs/performance.md | Adds detailed write-up for F15/F18 findings and methodology corrections. |
| crates/rustynes-frontend/src/perf.rs | Adds new perf rings + reporting for tick_lat / tick_iv. |
| crates/rustynes-frontend/src/perf_log.rs | Extends perf CSV schema to include the new trigger timing series. |
| crates/rustynes-frontend/src/lib.rs | Adds new clock module export (but accidentally ungates cli for wasm; see comment). |
| crates/rustynes-frontend/src/emu_thread.rs | Changes tick channel payload to monotonic timestamp and records hop + interval timings; adds plumbing tests. |
| crates/rustynes-frontend/src/clock.rs | Introduces centralized monotonic + thread CPU-time clock access with a single clock_gettime site. |
| crates/rustynes-frontend/src/app.rs | Refactors clock reads to delegate to the new clock module. |
| CHANGELOG.md | Adds Unreleased highlights for the new verified perf conclusions and supporting instrumentation. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
…r (F15)
Decomposes the produce interval, whose standard deviation tracks missed presents
at r = 0.937 (F17's data), so its variance is where the display cadence error
comes from. The interval has exactly three terms -- how regularly the trigger is
SENT, how long it takes to ARRIVE, and how long the frame takes to MAKE -- and
only the third was measured.
`tick_iv` and `tick_lat` are the first two, recorded as two INDEPENDENTLY-RANKED
series, never one derived by subtracting the other (the F8 rule). The display
tick's channel payload becomes a CLOCK_MONOTONIC timestamp instead of `()`, which
is what makes a cross-thread hop measurable at all; `clock.rs` is added to hold
the frontend's only `clock_gettime` call site, since F15 needs the reading on the
emulation thread too and duplicating it would duplicate an unsafe block and its
safety argument.
VERIFIED (SMB, run_ahead = 1, display-sync /2, window on screen and confirmed
valid by F16's gate, 18 post-warmup rows):
tick_lat p50 0.033 p95 0.043 p99 0.050 ms
tick_iv p50 16.289 p95 24.578 p99 28.637 ms
produced p50 16.269 p95 24.635 ms
The cross-thread hop is 33-50 MICROSECONDS. It is not a contributor, and the last
completely unmeasured step in the produce chain is now measured and eliminated.
One 13.155 ms outlier in `tick_lat_max` across 1494 ticks is a single scheduler
hiccup, not a systematic cost.
`produced` p95 matches `tick_iv` p95 to within 0.06 ms. With `rlock` at 0.000,
`tick_timeout` at 0 of 1494, and `cost_p95` 9.198 ms (55% of budget, F17's
healthy band), the produce tail is inherited WHOLESALE from the trigger interval:
the emulator is not late, it is asked late.
First positive location this campaign has produced rather than an elimination.
The remaining defect is in WHEN the winit thread decides to send the tick --
`display_produce_due` and the present cadence feeding it -- and every other
candidate in the chain is now ruled out by measurement.
Plumbing tests, mutation-checked
---------------------------------
Five tests pin every way the staging could lie: zero-payload guard (a 0 means
"clock unavailable", not "sent at the epoch" -- ungarded the latency reads as
machine uptime), absent-clock, first-tick-has-no-interval (also pinning that the
interval is send-to-send, not recv-to-recv), take-clears (so a watchdog-driven
frame does not re-record the previous frame's sample), and reversed-stamps-
saturate. Each guard was removed in turn and the corresponding test observed to
fail. The first attempt at that mutation check was itself wrong -- written against
unformatted source, it silently did not match and the test "passed", looking
exactly like a test that fails to discriminate -- so the mutation is now asserted
to have applied before the result is read.
Those tests were green for hours while the instrument had never carried a single
real sample: five verification captures all read 0.000 because the window was
occluded and display-sync never engaged, which is precisely what F16 detects.
Plumbing tests cannot verify an instrument, only that it lies in none of the ways
anticipated. The numbers above are the verification.
Capture-validity gate corrected alongside
------------------------------------------
F16's gate failed closed on a NON-ZERO cumulative `present_discarded`, and that
was wrong: the verified capture above carried 5 discards, 3 of them in the first
second while the window was being mapped. Rejecting it is a false negative on
exactly the capture the gate exists to bless, and it would have sent the next
person hunting a problem that was window mapping.
The counter is cumulative, so the gate now takes the post-warmup DELTA as a rate.
An occluded window is not subtle -- it discards every frame, ~61/s -- so the two
separate cleanly where a non-zero test cannot: the good capture reports
`+2 discards after warmup (0.15% of presents), consistent with compositor noise`
and passes; the known-occluded one reports 101.7% and fails.
Gates: fmt; clippy -D warnings on the frontend all-targets; 488 frontend lib
tests; RUSTDOCFLAGS="-D warnings" cargo doc --workspace (two private intra-doc
links caught and demoted to code spans, same rule as `note_clock_id`);
thumbv7em-none-eabihf no_std cross-build; markdownlint. Output-only and
native-gated -- the emulation core is untouched, so AccuracyCoin and nestest are
unaffected by construction.
Sixteen captures, four at each depth 0-3, in a LATIN SQUARE: each depth appears
in each round-position exactly once, so run-order drift cannot load onto any one
depth. That is F13's correction applied -- strict alternation balances the
DIRECTION of a monotone drift but does not buy exchangeability; a Latin square
does. Every capture validity-gated by F16 first, 16/16 passing (window on screen,
display-sync /2, discard rate <= 1%).
ra n cost_p50 %budget cost_p95 %budget throttled
0 4 4.180ms 25.1% 4.404ms 26.5% no
1 4 8.671ms 52.1% 9.060ms 54.5% no
2 4 12.884ms 77.4% 13.385ms 80.4% no
3 4 4.276ms 25.7% 4.516ms 27.1% YES
Cost is linear in depth
------------------------
Increments +4.491 ms and +4.213 ms, equal within 6% -- one extra `run_frame`
each, at the ~4.3 ms the core costs per frame. With snapshot + restore measured
at ~136 us (F19), run-ahead's cost is the emulated frames and essentially nothing
else. It is the PRICE of the feature, not overhead around it, and the only way to
reduce it is to make the core faster. F18's question is answered and closed.
This also retires a loose end the task explicitly said not to build on. The
earlier increments, read off captures taken in DIFFERENT sessions, were +3.09 and
+4.20 ms -- a 1.1 ms asymmetry that would have read as a real finding about
run-ahead's cost structure. Controlled, they are +4.49 and +4.21. The asymmetry
was session artefact, and quoting it would have sent someone hunting a structure
that does not exist.
Depth 3 throttles itself
-------------------------
`ra = 3` measures identically to `ra = 0`, which reads as a defect and is the
opposite. `run_ahead_throttled` is `true` in every one of its captures while
`run_ahead` still reports the requested 3: `update_runahead_throttle` engages at
85% of the frame budget and releases below 40%, and depth 3 would cost ~17.2 ms
against a 16.639 ms period. The guard correctly refuses it. Recorded because the
raw cost table cannot distinguish "requested depth had no effect" from "budget
guard did its job" -- only that column can.
F15 replicates across all four depths
--------------------------------------
ra tick_iv p95 produced p95 tick_lat p95
0 17.562ms 17.572ms 0.048ms
1 23.814ms 23.782ms 0.044ms
2 25.970ms 26.063ms 0.045ms
3 17.586ms 17.581ms 0.046ms
The produce interval IS the trigger interval at every depth, with the
cross-thread hop steady at 44-48 us. "The emulator is not late, it is asked late"
is now a four-condition replication rather than a single capture.
Documentation only in this commit; the sweep used the binary built from the F15
instrument earlier on this branch. The user's config was backed up before the
sweep (which rewrites `run_ahead`) and restored byte-identically afterwards.
The F15 commit inserted `pub mod clock;` between `#[cfg(not(target_arch = "wasm32"))]` and the `pub mod cli;` it belonged to, so the attribute bound to `clock` and `cli` compiled unconditionally -- and on wasm its clap / clap_complete / color-print deps are gated out of Cargo.toml, so the wasm32 job failed on E0433 for `clap`. THIRD time today for this exact bug: inserting code between an attribute (or a doc comment) and its item. It is invisible in review because both lines are individually correct, and the native build never notices. The wasm32 clippy job is the only gate that catches it, and it is not in the local batch I habitually run -- which is the actual lesson: after inserting a module or item, check what attribute now sits above it. `clock` is declared unconditionally on purpose: it cfg-gates its own bodies and returns `None` wherever the clocks are unreachable (wasm, non-unix, emu-thread off), so callers need no cfg. Noted in its doc comment so the next person does not "fix" it by adding one. Verified both wasm targets (default and wasm-canvas) plus native all-targets and the 488 frontend lib tests.
`col_float` maps a missing or unparseable cell to 0.0 by design -- correct for a scalar read, wrong for a min/max range. A capture ends by killing the process, so the final row is routinely a partial write, and that synthetic 0.0 becomes the `min`. The delta then reads as the whole cumulative count rather than the post-warmup change, and an entirely healthy capture fails the gate as "occluded". Now only rows that actually carry the column contribute to the range. Verified by truncating a known-good capture mid-row: it still reports "+2 discards after warmup (0.15% of presents)" and passes, where before the truncation alone would have failed it. Raised in review on PR #366.
doublegate
force-pushed
the
perf/v2.3.3-f15-verify
branch
from
August 13, 2026 22:52
b3a382e to
149a9f4
Compare
Antigravity review (Gemini via Ultra)This PR extracts clock readings into a dedicated module, instruments the display tick's cross-thread latency and send interval to diagnose pacing issues, and updates the perf log checker to correctly handle incomplete final rows. Blocking issues
Suggestions
Nitpicks
Automated first-pass review by |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two verified results, both from the first captures this campaign has taken with
the window actually on screen.
F15 — the trigger is late, not the emulator
The produce interval's variance is where display cadence error comes from
(r = 0.937 against missed presents, F17). It has three terms — how regularly the
trigger is sent, how long it takes to arrive, how long the frame takes to
make — and only the third was measured.
tick_ivandtick_latare theother two, as independently-ranked series (never one derived by subtracting the
other, per F8). The tick channel's payload became a
CLOCK_MONOTONICtimestampinstead of
(), which is what makes a cross-thread hop measurable at all.tick_lat— winit→emu hoptick_iv— between tick sendsproducedThe hop is 33–50 µs — the last unmeasured step in the chain, now measured and
eliminated.
producedp95 matchestick_ivp95 to within 0.06 ms, withrlockat 0.000,tick_timeoutat 0 of 1494, and cost at 55% of budget.First positive location this campaign has produced rather than an elimination:
the remaining defect is in when the winit thread sends the tick —
display_produce_dueand the present cadence feeding it.F18 — run-ahead's cost is the frames
Sixteen captures, four per depth, in a Latin square (each depth in each
round-position exactly once — F13's correction, since alternation balances drift
direction but doesn't buy exchangeability). Every capture validity-gated by
F16; 16/16 passed.
racost_p50Increments +4.491 and +4.213 ms — equal within 6%, one extra
run_frameeach. With snapshot+restore at ~136 µs (F19), run-ahead's cost is the emulated
frames and essentially nothing else — the price of the feature, not overhead
around it. F18 answered and closed.
Depth 3 throttles itself. It measures like depth 0, which reads as a defect
and is the opposite:
run_ahead_throttledistruein every one of itscaptures, the guard engaging at 85% of budget against depth 3's ~17.2 ms. Only
that column distinguishes "requested depth had no effect" from "budget guard did
its job".
F15 replicates across all four depths —
tick_ivp95 vsproducedp95:17.562/17.572, 23.814/23.782, 25.970/26.063, 17.586/17.581, with the hop steady
at 44–48 µs.
Corrections folded in
present_discarded— but the verified capture carries 5, three in the firstsecond during window mapping. That's a false negative on exactly the capture
the gate exists to bless. Now a post-warmup delta as a rate: the good
capture reads
+2 (0.15%), consistent with compositor noise; the occluded onereads 101.7% and fails.
suggesting non-linear run-ahead cost were session noise. Controlled: +4.49 and
+4.21.
Verification
fmt; clippy
-D warningson the frontend all-targets; 488 frontend lib tests(five new, each mutation-checked);
RUSTDOCFLAGS="-D warnings" cargo doc --workspace;thumbv7em-none-eabihfno_std cross-build; markdownlint;pre-commit. Output-only and native-gated — the emulation core is untouched, so
AccuracyCoin and nestest are unaffected by construction.
The sweep rewrites the
run_aheadconfig key; the user's config was backed upbeforehand and verified byte-identical afterwards.