diff --git a/src/vegas_mode/coordinator.py b/src/vegas_mode/coordinator.py index e75e8c51..59f57743 100644 --- a/src/vegas_mode/coordinator.py +++ b/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): diff --git a/test/test_vegas_stall_watchdog.py b/test/test_vegas_stall_watchdog.py new file mode 100644 index 00000000..598e76c0 --- /dev/null +++ b/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"