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

* 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

* 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

* feat(vegas): report the worst frame, not just the mean

The loop logged 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 perfectly healthy.
Stutter was unmeasurable, which is why "it sometimes freezes" went
unpinned for so long.

Adding p99 and the worst frame turned that into a number immediately: on
the dev rig, two freezes of 3.2s and 0.7s in twenty minutes with every
other frame under 81ms. Not general slowness -- two rare, total stalls,
which is a different problem with a different fix.

Costs 0.96us per frame, about 0.012% of an 8.3ms frame.

This replaces an earlier version that also shipped a stall watchdog and
a hitch counter. The watchdog never found anything -- one dump in
forty-five minutes, for an unrelated stall -- because it can only notice
a late heartbeat, and the freeze happens in coordinator.start() before
the frame loop begins beating. py-spy found the cause in one recording
by sampling the process externally, which needs no code here. The hitch
counter went with it: it needed a rolling median every frame, which was
most of the cost, to produce a number the worst frame already tells you.

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

* fix(vegas): use the nearest-rank index for p99

int(n * 0.99) is off by one, and at exactly 100 samples it selects the
maximum -- which is the number logged immediately beside it as the worst
frame. The two columns exist to say different things, p99 the
bad-but-ordinary frame and worst the outlier, so they agreed precisely
when the sample was smallest and least informative.

Nearest rank is ceil(n * fraction) - 1. Extracted so it can be tested
directly rather than only through a five-second logging interval.

Reported by CodeRabbit on the PR.

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

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>

src/vegas_mode/coordinator.py

@@ -12,6 +12,7 @@ Supports three display modes per plugin:
 """
 
 import logging
+import math
 import time
 import threading
 from typing import Optional, Dict, Any, List, Callable, TYPE_CHECKING
@@ -30,6 +31,21 @@ if TYPE_CHECKING:
 logger = logging.getLogger(__name__)
 
 
+def _percentile(ordered: List[float], fraction: float) -> float:
+    """Nearest-rank percentile of an already-sorted list.
+
+    Index ceil(n * fraction) - 1, so 100 samples at 0.99 give the 99th-ranked
+    value. The obvious int(n * fraction) is off by one and, at exactly 100
+    samples, lands on the maximum -- which is the number already reported
+    alongside this one as the worst frame, so the two columns would agree
+    precisely when the sample was smallest.
+    """
+    if not ordered:
+        return 0.0
+    index = math.ceil(len(ordered) * fraction) - 1
+    return ordered[min(len(ordered) - 1, max(0, index))]
+
+
 class VegasModeCoordinator:
     """
     Orchestrates Vegas scroll mode operation.
@@ -382,6 +398,12 @@ class VegasModeCoordinator:
         fps_log_interval = 5.0  # Log FPS every 5 seconds
         last_fps_log_time = start_time
         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 --
+        # moves the average from 120.0 to 115.4 and reads as healthy. What a
+        # viewer actually notices is the worst frame, so track that too.
+        frame_worst = 0.0
+        frame_times: List[float] = []
 
         logger.info("Starting Vegas iteration for %.1fs", duration)
 
@@ -417,6 +439,11 @@ class VegasModeCoordinator:
             frame_elapsed = time.time() - frame_started
             time.sleep(max(0.0, frame_interval - frame_elapsed))
 
+            # Measured before the sleep: time spent working, not pacing.
+            if frame_elapsed > frame_worst:
+                frame_worst = frame_elapsed
+            frame_times.append(frame_elapsed)
+
             # Increment frame count and check for interrupt periodically
             frame_count += 1
             fps_frame_count += 1
@@ -425,12 +452,16 @@ 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 = _percentile(sorted(frame_times), 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",
+                    fps, self.vegas_config.target_fps, fps_frame_count,
+                    p99 * 1000.0, frame_worst * 1000.0
                 )
                 last_fps_log_time = current_time
                 fps_frame_count = 0
+                frame_worst = 0.0
+                frame_times.clear()
 
             if (self._interrupt_check and
                     frame_count % self._interrupt_check_interval == 0):

test/test_vegas_frame_percentile.py

@@ -0,0 +1,64 @@
+"""Tests the percentile used by the Vegas frame-time log line.
+
+The FPS line reports p99 next to the worst frame, and the point of having both
+is that they say different things: p99 is the bad-but-ordinary frame, worst is
+the outlier. The obvious index, int(n * 0.99), is off by one and at exactly
+100 samples selects the maximum -- so the two columns would report the same
+number precisely when the sample was smallest.
+"""
+
+import math
+
+import pytest
+
+from src.vegas_mode.coordinator import _percentile
+
+
+class TestNearestRank:
+    def test_a_hundred_samples_do_not_return_the_maximum(self):
+        ordered = [float(i) for i in range(100)]      # 0..99
+        assert _percentile(ordered, 0.99) == 98.0
+        assert _percentile(ordered, 0.99) != max(ordered)
+
+    def test_it_matches_the_nearest_rank_definition(self):
+        for n in (1, 2, 3, 10, 99, 100, 101, 600, 1000):
+            ordered = [float(i) for i in range(n)]
+            expected = ordered[min(n - 1, max(0, math.ceil(n * 0.99) - 1))]
+            assert _percentile(ordered, 0.99) == expected, n
+
+    @pytest.mark.parametrize('fraction,expected', [
+        (0.0, 0.0),      # first
+        (0.5, 49.0),     # median, nearest-rank
+        (1.0, 99.0),     # last
+    ])
+    def test_other_fractions(self, fraction, expected):
+        assert _percentile([float(i) for i in range(100)], fraction) == expected
+
+
+class TestEdges:
+    def test_empty_is_zero_not_an_error(self):
+        # The loop calls this before any frame has been timed.
+        assert _percentile([], 0.99) == 0.0
+
+    def test_a_single_sample_is_itself(self):
+        assert _percentile([4.2], 0.99) == 4.2
+
+    def test_it_never_indexes_past_the_end(self):
+        for n in range(1, 50):
+            _percentile([float(i) for i in range(n)], 1.0)   # must not raise
+
+
+class TestItSaysSomethingUsefulAboutFrames:
+    def test_one_freeze_does_not_drag_p99_up(self):
+        # 599 healthy frames and one 3.2s freeze: p99 should still describe
+        # the healthy population, while the worst frame is reported separately.
+        frames = [0.0083] * 599 + [3.2]
+        p99 = _percentile(sorted(frames), 0.99)
+        assert p99 == pytest.approx(0.0083), p99
+        assert max(frames) == 3.2
+
+    def test_sustained_slowness_does_move_it(self):
+        # Ten percent of frames slow is not an outlier, it is the shape of the
+        # distribution, and p99 must reflect that.
+        frames = [0.0083] * 540 + [0.05] * 60
+        assert _percentile(sorted(frames), 0.99) == pytest.approx(0.05)