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

src/common/scroll_helper.py

@@ -328,6 +328,10 @@ class ScrollHelper:
             elapsed_time = current_time - (self.scroll_start_time or current_time)
             # The image already includes display_width padding, so we only need total_scroll_width
             required_total_distance = self.total_scroll_width
+            # Progress telemetry, emitted every few seconds for the whole of
+            # every scroll. It says how far along a marquee is, which is what
+            # you turn debug on to watch and not something an operator needs
+            # in the journal on a device that scrolls all day.
             self.logger.debug(
                 "Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
                 elapsed_time,

src/vegas_mode/coordinator.py

@@ -31,6 +31,18 @@ if TYPE_CHECKING:
 logger = logging.getLogger(__name__)
 
 
+#: Degradation threshold, as a fraction of target_fps. A marquee jitters a
+#: little all the time, so "anything under target" would report constantly and
+#: mean nothing; 90% of target is the point where a shortfall is real. At a
+#: 60fps target that is 54fps -- 55fps is a normal wobble and stays at DEBUG,
+#: which is deliberate, not an off-by-one.
+_FPS_HEALTHY_FRACTION = 0.9
+
+#: A healthy marquee still reports this often, so silence means stopped
+#: rather than fine.
+_FPS_HEARTBEAT_INTERVAL = 300.0
+
+
 def _percentile(ordered: List[float], fraction: float) -> float:
     """Nearest-rank percentile of an already-sorted list.
 
@@ -96,6 +108,11 @@ class VegasModeCoordinator:
         self._is_active = False
         self._is_paused = False
         self._should_stop = False
+        # Frame-rate health, tracked across run_iteration() calls so the
+        # heartbeat is one-per-interval rather than one-per-cycle, and so a
+        # recovery spanning two cycles is still reported. Reset on start().
+        self._fps_last_health_log = 0.0
+        self._fps_was_degraded = False
         self._state_lock = threading.Lock()
 
         # Live priority tracking
@@ -248,6 +265,11 @@ class VegasModeCoordinator:
             self._is_active = True
             self._should_stop = False
             self._start_time = time.time()
+            # A fresh run starts with a clean health slate: no stale
+            # "was degraded" from the previous run, and a heartbeat that is
+            # due immediately so the first sample confirms the marquee is up.
+            self._fps_last_health_log = 0.0
+            self._fps_was_degraded = False
 
         # Line up the next group immediately, so the first extension is already
         # warm rather than stalling the scroll to fetch it.
@@ -395,8 +417,18 @@ class VegasModeCoordinator:
             duration = self.render_pipeline.get_dynamic_duration()
         start_time = time.time()
         frame_count = 0
-        fps_log_interval = 5.0  # Log FPS every 5 seconds
-        last_fps_log_time = start_time
+        fps_log_interval = 5.0  # Sample FPS every 5 seconds
+        # Health state lives on the coordinator, not here: run_iteration() is
+        # called once per cycle, so locals reset every few seconds. That made
+        # `last_fps_health_log = 0.0` fire the "heartbeat" on the first sample
+        # of every iteration rather than once per interval, and a recovery
+        # that crossed an iteration boundary was never reported at all --
+        # was_degraded had already gone back to False.
+        # Monotonic, and deliberately not start_time: start_time is wall
+        # clock and is used below to report the iteration's duration. Mixing
+        # the two here would make every delta hugely negative and silence the
+        # frame-rate reporting altogether.
+        last_fps_log_time = time.monotonic()
         fps_frame_count = 0
         # A mean hides stutter completely. At 120fps a five-second window is
         # ~600 frames, so a 200ms freeze -- plainly visible on a marquee --
@@ -408,7 +440,13 @@ class VegasModeCoordinator:
         logger.info("Starting Vegas iteration for %.1fs", duration)
 
         while True:
-            frame_started = time.time()
+            # Monotonic, like the FPS window below. These devices have no RTC,
+            # so the wall clock jumps by however wrong boot time was the moment
+            # NTP first syncs. A backward jump makes frame_elapsed negative,
+            # and `frame_interval - frame_elapsed` then sleeps for longer than
+            # the whole budget -- the render loop stalls for the size of the
+            # correction. A forward jump inflates p99 and worst-frame instead.
+            frame_started = time.monotonic()
 
             # Check for STATIC mode plugin that should pause scroll
             static_plugin = self._check_static_plugin_trigger()
@@ -436,7 +474,7 @@ class VegasModeCoordinator:
             # quarter of the budget spent not rendering. Subtracting the work
             # already done keeps the pacing target while reclaiming that time,
             # and yields the GIL either way so other threads still run.
-            frame_elapsed = time.time() - frame_started
+            frame_elapsed = time.monotonic() - frame_started
             time.sleep(max(0.0, frame_interval - frame_elapsed))
 
             # Measured before the sleep: time spent working, not pacing.
@@ -448,16 +486,42 @@ class VegasModeCoordinator:
             frame_count += 1
             fps_frame_count += 1
 
-            # Periodic FPS logging
-            current_time = time.time()
+            # Periodic FPS logging. Reported at INFO only when the frame rate
+            # is actually worth an operator's attention -- a shortfall against
+            # target, or the recovery from one -- with a slow heartbeat so a
+            # healthy marquee still shows a pulse.
+            #
+            # Measured over two hours on a running 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, and
+            # completely invisible inside 1389 lines reading "59.6".
+            # Monotonic: every use of this value in the block below is a
+            # duration, and these devices have no RTC, so the wall clock jumps
+            # by however wrong boot time was the moment NTP first syncs. That
+            # would not only mis-fire the heartbeat, it would corrupt the
+            # frame rate itself, since fps is frames divided by this delta.
+            current_time = time.monotonic()
             if current_time - last_fps_log_time >= fps_log_interval:
                 fps = fps_frame_count / (current_time - last_fps_log_time)
                 p99 = _percentile(sorted(frame_times), 0.99)
+                target = self.vegas_config.target_fps
+                degraded = target > 0 and fps < target * _FPS_HEALTHY_FRACTION
+                due = (current_time - self._fps_last_health_log
+                       >= _FPS_HEARTBEAT_INTERVAL)
+                if degraded or self._fps_was_degraded or due:
                     logger.info(
                         "Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
-                    fps, self.vegas_config.target_fps, fps_frame_count,
+                        fps, target, fps_frame_count,
                         p99 * 1000.0, frame_worst * 1000.0
                     )
+                    self._fps_last_health_log = current_time
+                else:
+                    logger.debug(
+                        "Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
+                        fps, target, fps_frame_count,
+                        p99 * 1000.0, frame_worst * 1000.0
+                    )
+                self._fps_was_degraded = degraded
                 last_fps_log_time = current_time
                 fps_frame_count = 0
                 frame_worst = 0.0

test/test_vegas_fps_health.py

@@ -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")