feat(vegas): make scroll stutter visible, and catch it in the act

The loop reported only a mean FPS over a five-second window. At 120fps
that is ~600 frames, so a 200ms freeze -- plainly visible on a marquee --
moves the average from 120.0 to 115.4 and reads as healthy. Stutter was
literally unmeasurable.

The FPS line now carries p99, the worst frame, and a hitch count. On the
dev rig that immediately turned "it sometimes stutters" into a number:
two freezes of 3.2s and 0.7s in twenty minutes, with every other frame
under 81ms.

Statistics say a stall happened but not what caused it, and by the time
they are logged the stack is gone. So there is also a watchdog that dumps
every thread's stack while the loop is still wedged. It is off unless
LEDMATRIX_STALL_WATCHDOG is set to a threshold in seconds, since it
prints a lot. Pointed at the 3.2s freeze it named the culprit on the
first try: a plugin generating a 17,000px scroll image, logo PNG decode
and all, synchronously on the render thread.

The hitch threshold is relative to what frames actually cost, not to the
configured target. The target is routinely set above what the panel can
hold so vsync does the pacing; measured against that budget every
ordinary frame counts as a hitch, and the first version of this counter
duly reported 250 per window on a display running perfectly smoothly.

The watchdog is owned by the coordinator, not created per iteration --
run_iteration is called repeatedly, so building one there would leak a
thread each time.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Udr6MfaFLUPhX5Fgo67Jf5

src/vegas_mode/coordinator.py

@@ -12,8 +12,11 @@ Supports three display modes per plugin:
 """
 
 import logging
-import time
+import os
+import sys
 import threading
+import time
+import traceback
 from typing import Optional, Dict, Any, List, Callable, TYPE_CHECKING
 
 from src.vegas_mode.config import VegasModeConfig
@@ -29,6 +32,62 @@ if TYPE_CHECKING:
 
 logger = logging.getLogger(__name__)
 
+# A frame is a "hitch" once it takes this many times the typical frame. Two
+# is deliberately forgiving: one dropped frame at 120fps is 8ms and invisible,
+# whereas a marquee moving a steady few pixels per frame shows a stall of
+# twice that as a visible jerk.
+_HITCH_FACTOR = 2.0
+
+# How many recent frames define "typical". Big enough to ride out noise, small
+# enough to track a genuine change in what the loop costs.
+_TYPICAL_SAMPLE = 60
+
+# A stall long enough that a viewer sees the marquee stop dead. Frame-time
+# statistics say one happened but not what did it, and by the time the numbers
+# are logged the stack is long gone -- so a watchdog samples every thread while
+# the loop is still wedged. Off unless LEDMATRIX_STALL_WATCHDOG is set, since
+# it dumps a lot of text.
+_STALL_DUMP_SECONDS = float(os.environ.get('LEDMATRIX_STALL_WATCHDOG', '0') or 0)
+
+
+class _StallWatchdog:
+    """Dumps every thread's stack when the render loop stops checking in."""
+
+    def __init__(self, threshold: float):
+        self.threshold = threshold
+        self._beat = time.time()
+        self._lock = threading.Lock()
+        self._stop = threading.Event()
+        self._dumped_for = 0.0
+        self._thread = threading.Thread(
+            target=self._watch, name="VegasStallWatchdog", daemon=True)
+        self._thread.start()
+
+    def beat(self) -> None:
+        with self._lock:
+            self._beat = time.time()
+
+    def stop(self) -> None:
+        self._stop.set()
+
+    def _watch(self) -> None:
+        while not self._stop.wait(self.threshold / 4.0):
+            with self._lock:
+                last = self._beat
+            stalled = time.time() - last
+            if stalled < self.threshold or last == self._dumped_for:
+                continue
+            self._dumped_for = last          # one dump per stall, not per poll
+            frames = sys._current_frames()
+            names = {t.ident: t.name for t in threading.enumerate()}
+            lines = ["render loop stalled %.2fs -- thread stacks:" % stalled]
+            for ident, frame in frames.items():
+                lines.append("  --- %s (%s) ---" % (names.get(ident, "?"), ident))
+                for fn, lineno, func, _text in traceback.extract_stack(frame)[-8:]:
+                    lines.append("    %s:%d in %s" % (fn, lineno, func))
+            logger.warning("\n".join(lines))
+
+
 
 class VegasModeCoordinator:
     """
@@ -119,6 +178,7 @@ class VegasModeCoordinator:
             'static_pauses': 0,
         }
         self._start_time: Optional[float] = None
+        self._stall_watchdog: Optional['_StallWatchdog'] = None
 
         logger.info(
             "VegasModeCoordinator initialized: enabled=%s, fps=%d, buffer_ahead=%d",
@@ -382,6 +442,20 @@ class VegasModeCoordinator:
         fps_log_interval = 5.0  # Log FPS every 5 seconds
         last_fps_log_time = start_time
         fps_frame_count = 0
+        # Stutter is invisible in a mean. At 120fps a 5s window covers ~600
+        # frames, so a 200ms freeze -- plainly visible on a marquee -- moves
+        # the average from 120.0 to 115.4 and reads as healthy. What a viewer
+        # notices is the worst frame, so track that separately.
+        frame_worst = 0.0
+        frame_hitches = 0
+        frame_times: List[float] = []
+        frame_typical = 0.0
+
+        # One per coordinator, not per iteration -- run_iteration is called
+        # repeatedly, so building one here would leak a thread each time.
+        if _STALL_DUMP_SECONDS > 0 and self._stall_watchdog is None:
+            self._stall_watchdog = _StallWatchdog(_STALL_DUMP_SECONDS)
+        watchdog = self._stall_watchdog
 
         logger.info("Starting Vegas iteration for %.1fs", duration)
 
@@ -417,6 +491,25 @@ class VegasModeCoordinator:
             frame_elapsed = time.time() - frame_started
             time.sleep(max(0.0, frame_interval - frame_elapsed))
 
+            # Measured before the sleep, so this is time spent working rather
+            # than time spent pacing. A frame that overruns the budget is one
+            # the viewer sees as a jerk in otherwise smooth motion.
+            if frame_elapsed > frame_worst:
+                frame_worst = frame_elapsed
+            # Measured against what frames actually cost here, not against
+            # the configured target. The target is routinely set above what
+            # the panel can hold so vsync does the pacing -- against that
+            # budget every ordinary frame looks like a hitch, which is how
+            # the first version of this counter reported 250 per window on a
+            # display that was running perfectly smoothly.
+            if frame_typical and frame_elapsed > _HITCH_FACTOR * frame_typical:
+                frame_hitches += 1
+            if len(frame_times) >= _TYPICAL_SAMPLE:
+                frame_typical = sorted(frame_times[-_TYPICAL_SAMPLE:])[_TYPICAL_SAMPLE // 2]
+            frame_times.append(frame_elapsed)
+            if watchdog:
+                watchdog.beat()
+
             # Increment frame count and check for interrupt periodically
             frame_count += 1
             fps_frame_count += 1
@@ -425,12 +518,22 @@ class VegasModeCoordinator:
             current_time = time.time()
             if current_time - last_fps_log_time >= fps_log_interval:
                 fps = fps_frame_count / (current_time - last_fps_log_time)
+                p99 = 0.0
+                if frame_times:
+                    ordered = sorted(frame_times)
+                    p99 = ordered[min(len(ordered) - 1,
+                                      int(len(ordered) * 0.99))]
                 logger.info(
-                    "Vegas FPS: %.1f (target: %d, frames: %d)",
-                    fps, self.vegas_config.target_fps, fps_frame_count
+                    "Vegas FPS: %.1f (target: %d, frames: %d) "
+                    "p99 %.1fms worst %.1fms hitches %d",
+                    fps, self.vegas_config.target_fps, fps_frame_count,
+                    p99 * 1000.0, frame_worst * 1000.0, frame_hitches
                 )
                 last_fps_log_time = current_time
                 fps_frame_count = 0
+                frame_worst = 0.0
+                frame_hitches = 0
+                frame_times.clear()
 
             if (self._interrupt_check and
                     frame_count % self._interrupt_check_interval == 0):

test/test_vegas_stall_watchdog.py

@@ -0,0 +1,119 @@
+"""Tests the watchdog that catches a stalled render loop in the act.
+
+Frame-time statistics can say a stall happened but not what caused it, and by
+the time the numbers reach the log the stack is long gone. On a live rig the
+Vegas loop showed a 3.2s freeze roughly twice an hour with every other frame
+under 25ms -- invisible in the mean, and unattributable from the log alone.
+This watchdog samples every thread's stack while the loop is still wedged,
+which is how that freeze was traced to a plugin generating a 17,000px scroll
+image, logo PNG decode and all, on the render thread.
+"""
+
+import threading
+import time
+
+import pytest
+
+from src.vegas_mode.coordinator import _StallWatchdog
+
+
+@pytest.fixture
+def watchdog():
+    made = []
+
+    def build(threshold):
+        w = _StallWatchdog(threshold)
+        made.append(w)
+        return w
+
+    yield build
+    for w in made:
+        w.stop()
+    for w in made:
+        w._thread.join(timeout=2.0)
+        assert not w._thread.is_alive(), "watchdog thread outlived its owner"
+
+
+def _dumps(caplog):
+    return [r for r in caplog.records if 'render loop stalled' in r.getMessage()]
+
+
+class TestItFiresOnlyWhenStalled:
+    def test_a_beating_loop_is_never_reported(self, watchdog, caplog):
+        w = watchdog(0.2)
+        deadline = time.time() + 0.9
+        while time.time() < deadline:
+            w.beat()
+            time.sleep(0.02)
+        assert not _dumps(caplog)
+
+    def test_a_stalled_loop_is_reported(self, watchdog, caplog):
+        w = watchdog(0.2)
+        w.beat()
+        time.sleep(0.9)
+        assert _dumps(caplog), "no stall dump for a loop that stopped beating"
+
+    def test_one_dump_per_stall_not_per_poll(self, watchdog, caplog):
+        # The watchdog polls at threshold/4, so a stall lasting many poll
+        # intervals must not flood the log with a dump each time.
+        w = watchdog(0.2)
+        w.beat()
+        time.sleep(1.2)
+        assert len(_dumps(caplog)) == 1, (
+            "%d dumps for one stall" % len(_dumps(caplog)))
+
+    def test_a_later_stall_is_reported_again(self, watchdog, caplog):
+        w = watchdog(0.2)
+        w.beat()
+        time.sleep(0.6)
+        first = len(_dumps(caplog))
+        w.beat()                      # recovered
+        time.sleep(0.6)               # then stalled again
+        assert len(_dumps(caplog)) == first + 1
+
+
+class TestWhatItReports:
+    def test_the_dump_names_threads_and_shows_frames(self, watchdog, caplog):
+        started = threading.Event()
+        release = threading.Event()
+
+        def parked():
+            started.set()
+            release.wait(3.0)
+
+        t = threading.Thread(target=parked, name="CulpritThread", daemon=True)
+        t.start()
+        started.wait(2.0)
+        try:
+            w = watchdog(0.2)
+            w.beat()
+            time.sleep(0.7)
+            dumps = _dumps(caplog)
+            assert dumps
+            text = dumps[0].getMessage()
+            assert "CulpritThread" in text, text
+            assert " in " in text, "no frames in the dump"
+            assert ".py:" in text, "no file:line in the dump"
+        finally:
+            release.set()
+            t.join(timeout=2.0)
+
+    def test_it_reports_how_long_the_stall_ran(self, watchdog, caplog):
+        w = watchdog(0.2)
+        w.beat()
+        time.sleep(0.8)
+        text = _dumps(caplog)[0].getMessage()
+        assert "stalled" in text
+        # Long enough to have tripped, and not an absurd value.
+        stalled = float(text.split("stalled")[1].split("s")[0])
+        assert 0.2 <= stalled <= 3.0, stalled
+
+
+class TestItIsCheapWhenIdle:
+    def test_stop_is_prompt(self, caplog):
+        w = _StallWatchdog(4.0)          # long threshold, long poll interval
+        t0 = time.time()
+        w.stop()
+        w._thread.join(timeout=3.0)
+        assert not w._thread.is_alive(), "stop() did not end the thread"
+        assert time.time() - t0 < 2.0, "stop() waited out the poll interval"