fix(vegas): let the watchdog see stalls that hold the GIL

The watchdog only noticed a late heartbeat, which a whole class of
freeze can never produce: if the loop is inside one long C call that
holds the GIL, this thread cannot run during the stall, and by the time
it does the loop has already checked in. On the dev rig that hid a
recurring 3.2s freeze completely -- twenty minutes of watching produced
one dump, for an unrelated 0.4s stall.

What it can still observe is that its own sleep ran long. A badly
overshot wait is now reported as a stall in its own right. The stacks
are stale by then and the message says so, but knowing the freeze is
GIL-holding is most of the diagnosis: it rules out lock contention and
scheduling, and points at a single long C call.

This also explains why lowering sys.setswitchinterval changed nothing --
the switch interval cannot preempt a C call that never releases the GIL.

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,81 @@ 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:
+        poll = self.threshold / 4.0
+        while True:
+            woke_at = time.time()
+            if self._stop.wait(poll):
+                break
+            with self._lock:
+                last = self._beat
+            now = time.time()
+            stalled = now - last
+            # A stall inside a C call that holds the GIL never shows up as a
+            # late beat: this thread cannot run during it, and by the time it
+            # does the loop has already checked in. What it can see is that
+            # its own sleep ran long. Treat a badly overshot wait as a stall
+            # in its own right -- the stacks are stale by then, but knowing
+            # the freeze is GIL-holding is itself the diagnosis.
+            overshoot = (now - woke_at) - poll
+            if overshoot > self.threshold:
+                logger.warning(
+                    "render loop stalled %.2fs holding the GIL -- no Python "
+                    "frames ran, so the stacks below are from after it ended; "
+                    "look for one long C call (a large PIL operation, a "
+                    "compress, a big allocation)", overshoot)
+                stalled = overshoot
+            elif 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 +197,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 +461,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 +510,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 +537,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"