perf(vegas): report the frame rate when it is worth reporting

Vegas logged an FPS line at INFO every five seconds for the whole of
every run. Measured over two hours on a rig: 1410 samples, 98.5% of them
within 10% of target. The 1.5% that were not included a reading of
8.6fps against a target of 60 -- a real stall, completely invisible
inside 1389 lines reading "59.6". INFO is now reserved for a shortfall,
the recovery from one, and a slow heartbeat so a healthy marquee still
shows a pulse. Scroll-progress tracing drops to DEBUG for the same
reason: it runs for the whole of every scroll and is what you turn debug
on to watch.

Three review findings, all fixed here.

1. Per-frame timing used the wall clock (critical). The loop sleeps the
   remainder of each frame budget:

       frame_elapsed = <now> - frame_started
       time.sleep(max(0.0, frame_interval - frame_elapsed))

   These devices have no RTC, so the clock jumps by however wrong boot
   time was when NTP first syncs. A backward step makes frame_elapsed
   negative, `frame_interval - frame_elapsed` then exceeds the whole
   budget, and the render loop stalls for the size of the correction. A
   forward step instead inflates the p99 and worst-frame figures this
   telemetry exists to report. Both per-frame timestamps are monotonic
   now. start_time stays wall-clock: it is only used for the iteration
   duration report, where a human-readable clock is the point.

2. FPS health state reset every iteration. last_fps_health_log and
   was_degraded were locals of run_iteration(), which is called once per
   cycle. Starting at 0.0 against a monotonic clock, `due` was true on
   the first sample of every iteration, so the 300s heartbeat degenerated
   into one report per cycle -- reintroducing the noise this change is
   about. A recovery that crossed an iteration boundary was never
   reported either, since was_degraded had already gone back to False.
   Both now live on the coordinator and reset in start().

3. The degraded threshold read as an off-by-one. 90% of target is
   deliberate -- a marquee jitters constantly, so "anything below target"
   would report forever and mean nothing -- but nothing said so, leaving
   55fps-against-60 looking like a missed case. The constant now states
   the band and gives that exact example.

Also drops two soccer logo PNGs that a `git add -A` had swept into the
first commit. They are unreferenced, unrelated to frame-rate telemetry,
and 210KB.

Verified: each fix mutation-checked -- restoring the wall clock on either
per-frame timestamp, or making the health state local again, fails the
new tests. 566 passed across the vegas, coordinator and scroll suites.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
This commit is contained in:
ChuckBuilds
2026-08-21 16:18:14 -04:00
co-authored by Claude Opus 5
parent 863e4a1ecd
commit b7cf94f20a
3 changed files with 178 additions and 11 deletions
+99
View File
@@ -0,0 +1,99 @@
"""Frame pacing and FPS health reporting must not depend on the wall clock.
These devices have no RTC, so the system clock jumps by however wrong boot
time was the moment NTP first syncs. The render loop sleeps the *remainder*
of each frame budget:
frame_elapsed = <now> - frame_started
time.sleep(max(0.0, frame_interval - frame_elapsed))
With a wall-clock `now`, a backward jump makes frame_elapsed negative, so
`frame_interval - frame_elapsed` exceeds the whole budget and the render loop
stalls for the size of the correction. A forward jump instead inflates the
p99 and worst-frame numbers the telemetry reports.
"""
import ast
import sys
from pathlib import Path
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
COORD = (Path(__file__).resolve().parent.parent
/ "src" / "vegas_mode" / "coordinator.py")
TREE = ast.parse(COORD.read_text(encoding="utf-8"))
def _assignments_of(name):
"""Every `name = <expr>` in the module, as unparsed source."""
out = []
for node in ast.walk(TREE):
if isinstance(node, ast.Assign):
for target in node.targets:
if isinstance(target, ast.Name) and target.id == name:
out.append((node.lineno, ast.unparse(node.value)))
return out
def test_per_frame_timestamps_are_monotonic():
for name in ("frame_started", "frame_elapsed"):
assigns = _assignments_of(name)
assert assigns, f"{name} is no longer assigned -- has the loop changed?"
for lineno, expr in assigns:
assert "time.time()" not in expr, (
f"{name} at line {lineno} uses the wall clock ({expr!r}). A "
"backward NTP step makes the per-frame delta negative and the "
"loop then sleeps longer than the whole frame budget.")
assert "time.monotonic()" in expr, (
f"{name} at line {lineno} is {expr!r}, expected monotonic")
def test_the_fps_window_is_monotonic():
for lineno, expr in _assignments_of("current_time"):
assert "time.monotonic()" in expr, (
f"current_time at line {lineno} is {expr!r}; fps is frames divided "
"by this delta, so a clock step would corrupt the rate itself")
def test_health_state_is_not_reset_every_iteration():
"""run_iteration() runs once per cycle -- locals here reset every few seconds.
As locals, `last_fps_health_log = 0.0` made the 300s heartbeat fire on the
first sample of every iteration, and a recovery spanning two iterations was
never reported because was_degraded had already gone back to False.
"""
run_iteration = next(
(n for n in ast.walk(TREE)
if isinstance(n, ast.FunctionDef) and n.name == "run_iteration"), None)
assert run_iteration is not None, "run_iteration() not found"
local_names = {t.id for n in ast.walk(run_iteration)
if isinstance(n, ast.Assign)
for t in n.targets if isinstance(t, ast.Name)}
for leaked in ("last_fps_health_log", "was_degraded"):
assert leaked not in local_names, (
f"{leaked} is a local of run_iteration() again, so it resets every "
"cycle -- the heartbeat degenerates to once per iteration")
body = ast.unparse(run_iteration)
assert "self._fps_last_health_log" in body and "self._fps_was_degraded" in body, (
"the health state should live on the coordinator, across iterations")
def test_start_clears_stale_health_state():
"""A new run must not inherit "was degraded" from the previous one."""
start = next((n for n in ast.walk(TREE)
if isinstance(n, ast.FunctionDef) and n.name == "start"), None)
assert start is not None, "start() not found"
body = ast.unparse(start)
assert "self._fps_last_health_log" in body and "self._fps_was_degraded" in body, (
"start() does not reset the FPS health state")
def test_the_degraded_threshold_is_documented():
"""The 90% band is deliberate; say so where the constant is defined."""
source = COORD.read_text(encoding="utf-8")
idx = source.index("_FPS_HEALTHY_FRACTION = ")
preamble = source[max(0, idx - 700):idx]
assert "90%" in preamble or "0.9" in preamble, (
"the degradation threshold is not explained at its definition, so "
"'below target' reads as a bug rather than a deliberate band")