fix(scroll): stop timing the idle gap between scrolls as a frame (#582)

ScrollHelper.last_frame_time was set once in __init__ and thereafter only
at the end of log_frame_rate(). Nothing re-armed it when a scroll began, so
the first frame of every scroll was timed against the last frame of the
*previous* one and the whole idle period between them was recorded as a
single frame.

Measured over 3 hours on a 256x64 Pi 4, that produced 31 windows reading

    Scroll frame stats - 0.0 fps over 1 frames | median 136776.02ms
    p95 136776.02ms max 136776.02ms min 136776.02ms | stalls 0 (0.0%)

and -- worse, because it is not obviously wrong -- put the same gap in the
max field of otherwise healthy windows, where the worst values were 537s
and 604s. It also counted as one stall per scroll start: at ~500 frames to
a window that is ~0.2%, against measured stall rates of 0.07-0.16%. The
stall rate is the number used to judge whether a scroll change worked, and
it was the same order of magnitude as its own artefact.

The first frame of a scroll has no predecessor, so it has no frame time.
last_frame_time is now None until one is rendered, and reset_scroll() puts
it back -- the same treatment last_update_time already gets three lines
above, for the same reason. reset_scroll() alone is not enough, because the
scrollers actually emitting these lines never call it, so a sample at or
past the 5s log interval is dropped as well: nothing that renders a scroll
takes that long over one frame. Seeding also restarts the window timer, or
the boundary is already overdue when the second frame arrives and every
scroll opens by reporting a window of exactly one frame. A window whose
samples were all dropped now logs nothing rather than reporting the gap.

docs/SCROLL_PERFORMANCE.md documented the diagnostic in terms of a
"Frame time: N ms" line that 6031e705 replaced with the aggregate, so its
grep matched nothing on any rig. The section now describes the line that is
actually emitted, reads duplicate frames off skips and a below-median
result rather than a 2ms mode, and adds a command that ranks every scroller
by p95 -- verified against 3 hours of journal, where it reproduces
src.base_odds_manager at p95 44.08ms against 10.19ms for the two scrollers
already on src/common/scroll_config.py.

requirements.txt still offered scipy for the sub-pixel interpolation path
deleted in #570. Installing it has no effect; the entry says so.


Claude-Session: https://claude.ai/code/session_014RRtqXDCnvnY6EQwhT5CV9

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

docs/SCROLL_PERFORMANCE.md

@@ -203,26 +203,61 @@ configured speed, so position stays proportional to real time.
 
 ## Diagnosing a juddery scroller
 
-**`Avg FPS` will lie to you.** It is a 100-frame moving average, and a 2 ms
+**An average will lie to you.** A 2 ms duplicate frame and a 21 ms double-wait
-duplicate frame plus a 21 ms double-wait average to exactly 10 ms. A ticker
+mean exactly 10 ms, so a ticker stalling on half its frames still averages to a
-that is stalling on half its frames still reports a healthy `100.0`.
+healthy 100 fps. The stats line reports the tail for that reason — read the
+percentiles, not the fps.
 
-Look at the **distribution** instead:
+Every scroller emits one line every 5 seconds covering *every* frame in that
+window, tagged with the plugin it came from:
 
 ```bash
-journalctl -u ledmatrix --since "-10min" --no-pager \
+journalctl -u ledmatrix --since "-10min" --no-pager | grep "Scroll frame stats"
-  | grep -oE "Frame time: [0-9.]+ms" | awk '{print $3}' | sed 's/ms//' \
+```
-  | awk '{printf "%.0f\n", $1}' | sort -n | uniq -c
+
+```
+[Plugin: news] Scroll frame stats - 100.0 fps over 501 frames | median 10.00ms
+p95 10.11ms max 12.03ms min 7.98ms | stalls 0 (0.0%) skips 0 (0.0%)
 ```
 
 Reading it, on a 100 Hz panel:
 
 | you see | it means |
 |---|---|
-| everything at 10 ms | healthy |
+| median 10 ms, p95 within ~0.5 ms of it | healthy — locked to the panel |
-| a mode at ~2 ms | **duplicate frames** — the swap was skipped because the image did not change. The scroller is advancing less than one pixel per frame. |
+| p95 or max at 20/30/50 ms | frames missing refreshes — per-frame work is overrunning, or a background thread is holding the GIL |
-| a mode at 20/30/50 ms | frames missing refreshes — per-frame work is overrunning, or a background thread is holding the GIL |
+| non-zero **skips**, or a median *below* 10 ms | **duplicate frames** — the swap was skipped because the image did not change, so the frame never waited on vsync. The scroller is advancing less than one pixel per frame. |
-| `Avg FPS` above 100 | duplicates present, unless the scroll cycle has completed and is idling |
+| non-zero **stalls** | frames past 1.5× the median, which is the measure of judder that survives averaging |
+
+`stalls` and `skips` are both counted against that window's own median, so they
+stay meaningful on a panel running at any refresh rate.
+
+To rank every scroller at once rather than reading lines one at a time:
+
+```bash
+journalctl -u ledmatrix --since "-3h" --no-pager | grep "Scroll frame stats" \
+  | sed -E 's/.*- (\S+) - (\[Plugin: [^]]+\] )?Scroll.*median ([0-9.]+)ms p95 ([0-9.]+)ms.*/\1 \3 \4/' \
+  | awk '$2 < 1000 {n[$1]++; m[$1]+=$2; p[$1]+=$3} END {for (k in n)
+        printf "%-28s %5d windows  median %6.2fms  p95 %6.2fms\n", k, n[k], m[k]/n[k], p[k]/n[k]}' \
+  | sort -k7 -rn
+```
+
+The `$2 < 1000` guard drops windows whose median is a whole second or more.
+Those are not frames. Until the idle-gap fix in `log_frame_rate()`, the first
+frame of every scroll was timed against the end of the *previous* scroll, so
+the gap between them was recorded as one enormous sample — it landed in the
+`max` field of otherwise healthy windows and counted as one stall per scroll,
+roughly 0.2% at 500 frames to a window, which is the same order as the real
+stall rates it sat beside. Current builds emit none, but the guard costs
+nothing and keeps the command honest against older journals.
+
+A scroller whose p95 sits several times its median is the one to fix, and it is
+usually the one doing the most per-frame work rather than the one configured
+worst. Measured over 20 minutes with two scrollers set identically at 100 px/s,
+the leaderboard held 10 ms flat while the odds ticker spent ~20% of its frames
+on duplicates. Same settings, different render cost: odds does more per-frame
+work, and more variably, so it is first to land a frame that advances less than
+a whole pixel. Check the render path before the config.
 
 Then confirm what the plugin actually loaded — config edits do not always reach
 the running code:

requirements.txt

@@ -43,10 +43,14 @@ packaging>=23.0,<27.0
 # full feature set, or skip them for a minimal install.
 # ───────────────────────────────────────────────────────────────────────
 #
-# scipy             — sub-pixel interpolation in
+# scipy             — nothing, as of #570. It was listed for the sub-pixel
-#                     src/common/scroll_helper.py for smoother
+#                     interpolation path in src/common/scroll_helper.py, but
-#                     scrolling. Falls back to a simpler shift algorithm.
+#                     get_visible_portion never consulted HAS_SCIPY, so that
-#   pip install 'scipy>=1.10.0,<2.0.0'
+#                     path was dead before it was deleted. The blend that
+#                     replaced it is numpy-only. Do not install it expecting
+#                     smoother scrolling: sub-pixel blending is off by default
+#                     because it reads worse on a coarse panel, not because it
+#                     is missing a library. See docs/SCROLL_PERFORMANCE.md.
 #
 # psutil            — per-plugin resource monitoring in
 #                     src/plugin_system/resource_monitor.py. The monitor

src/common/scroll_helper.py

@@ -30,6 +30,12 @@ except ImportError:
     HAS_SCIPY = False
 
 
+# How often the frame-stats line is emitted, and therefore also the ceiling
+# on a believable frame time: a scroll that renders at all cannot take this
+# long over one frame, so a sample this large is an idle gap between scrolls.
+FPS_LOG_INTERVAL = 5.0
+
+
 def frame_stats(frame_times: list) -> Dict[str, Any]:
     """Summary statistics over one window of frame durations (seconds).
 
@@ -158,9 +164,11 @@ class ScrollHelper:
         self.last_progress_log_time: Optional[float] = None
         self.progress_log_interval = 5.0  # seconds
         
-        # Frame rate tracking
+        # Frame rate tracking. last_frame_time is None until the first frame
+        # of a scroll is rendered -- see log_frame_rate() for why timing from
+        # construction (or from the end of the previous scroll) is wrong.
         self.frame_count = 0
-        self.last_frame_time = time.time()
+        self.last_frame_time: Optional[float] = None
         self.last_fps_log_time = time.time()
         self.frame_times = []
         # Every frame time since the last stats line, so the 5s summary can
@@ -764,6 +772,10 @@ class ScrollHelper:
         # Reset last_update_time to prevent large delta_time on next update
         # This ensures smooth scrolling after reset without jumping ahead
         self.last_update_time = now
+        # Same reasoning for the frame-rate clock: the first frame after a
+        # reset has no predecessor in this scroll, and timing it against the
+        # last frame of the previous one measures the idle gap between them.
+        self.last_frame_time = None
         self.logger.debug("Scroll position reset")
 
     def reset(self) -> None:
@@ -962,11 +974,37 @@ class ScrollHelper:
         Log frame rate statistics for performance monitoring.
         """
         current_time = time.time()
-        
+
+        # The first frame of a scroll has no predecessor, so it has no frame
+        # time. Measuring one anyway records the whole idle gap since the last
+        # scroll as a single frame: on hardware that produced windows reading
+        # "0.0 fps over 1 frames | median 136776.02ms", and -- worse, because
+        # it is not obviously wrong -- put that gap in the max field of
+        # otherwise healthy windows and counted it as one stall per scroll.
+        # At ~500 frames to a window that is ~0.2%, which is the same order as
+        # the real stall rates being measured, so the number could not be
+        # trusted at all. Seed the clock and take no sample.
+        if self.last_frame_time is None:
+            self.last_frame_time = current_time
+            # Restart the window with the scroll. Otherwise the boundary is
+            # already long overdue when the second frame arrives, and the new
+            # scroll opens by reporting a window of exactly one frame.
+            self.last_fps_log_time = current_time
+            return
+
         # Calculate instantaneous frame time
         frame_time = current_time - self.last_frame_time
+
+        # A caller that scrolls without ever calling reset_scroll() never arms
+        # the sentinel above, so catch the same gap by its size. Nothing that
+        # renders a scroll produces a frame longer than the log interval; a
+        # sample that large is an idle period, not a frame.
+        if frame_time >= FPS_LOG_INTERVAL:
+            self.last_frame_time = current_time
+            return
+
         self.frame_times.append(frame_time)
-        
+
         # Keep only last 100 frames for average
         if len(self.frame_times) > 100:
             self.frame_times.pop(0)
@@ -979,17 +1017,21 @@ class ScrollHelper:
         # duplicate and a 21ms double-wait mean exactly 10ms). Chasing scroll
         # judder needs the tail, so keep the window and report percentiles.
         self._window.append(frame_time)
-        
+
         # Log FPS every 5 seconds to avoid spam
-        if current_time - self.last_fps_log_time >= 5.0:
+        if current_time - self.last_fps_log_time >= FPS_LOG_INTERVAL:
-            self.logger.info(
+            # An empty window means every sample in this interval was dropped
-                "Scroll frame stats - %s",
+            # as an idle gap. There is nothing to report, and reporting the
-                format_frame_stats(self._window or [frame_time]),
+            # gap itself is the bug above.
-            )
+            if self._window:
+                self.logger.info(
+                    "Scroll frame stats - %s",
+                    format_frame_stats(self._window),
+                )
             self.last_fps_log_time = current_time
             self.frame_count = 0
             self._window = []
-        
+
         self.last_frame_time = current_time
         self.frame_count += 1
     

test/test_scroll_helper.py

@@ -387,9 +387,81 @@ class TestFrameStatsPercentiles:
 
     def test_log_frame_rate_emits_the_line_and_clears_the_window(self, helper):
         helper._window = [0.010] * 20
+        helper.last_frame_time = time.time()  # arm the clock; see below
         helper.last_fps_log_time = 0.0  # force the 5s boundary
         with patch.object(helper.logger, "info") as info:
             helper.log_frame_rate()
         assert info.called
         assert "Scroll frame stats" in info.call_args[0][0]
         assert helper._window == []
+
+
+class TestIdleGapIsNotAFrame:
+    """The first frame of a scroll has no predecessor, so timing one measures
+    the idle gap since the last scroll rather than a frame.
+
+    Left in, that gap lands in the max field of otherwise healthy windows and
+    counts as one stall per scroll start -- about 0.2% at 500 frames to a
+    window, which is the same order as the real stall rates it sits next to.
+    The stall rate is the number used to judge whether a scroll change worked,
+    so it has to be clean.
+    """
+
+    def test_clock_starts_unarmed(self, helper):
+        assert helper.last_frame_time is None
+
+    def test_first_frame_seeds_the_clock_without_sampling(self, helper):
+        helper.log_frame_rate()
+        assert helper.last_frame_time is not None
+        assert helper._window == []
+        assert helper.frame_times == []
+
+    def test_second_frame_is_sampled(self, helper):
+        helper.log_frame_rate()
+        helper.log_frame_rate()
+        assert len(helper._window) == 1
+
+    def test_reset_scroll_disarms_the_clock(self, helper):
+        helper.log_frame_rate()
+        assert helper.last_frame_time is not None
+        helper.reset_scroll()
+        assert helper.last_frame_time is None
+
+    def test_gap_longer_than_the_log_interval_is_dropped(self, helper):
+        """Covers callers that scroll without ever calling reset_scroll()."""
+        helper.last_frame_time = time.time() - 137.0  # a real observed gap
+        helper.log_frame_rate()
+        assert helper._window == []
+        assert helper.frame_times == []
+
+    def test_a_gap_does_not_reach_the_stats_line(self, helper):
+        helper.last_frame_time = time.time() - 137.0
+        helper.last_fps_log_time = 0.0  # the 5s boundary is also due
+        with patch.object(helper.logger, "info") as info:
+            helper.log_frame_rate()
+        assert not info.called, "the idle gap was reported as a frame"
+
+    def test_window_of_only_gaps_logs_nothing(self, helper):
+        """A window whose every sample was dropped has nothing to report --
+        and reporting the gap itself is the bug this guards."""
+        helper.last_fps_log_time = 0.0
+        with patch.object(helper.logger, "info") as info:
+            helper.log_frame_rate()   # seeds
+            helper.last_frame_time = time.time() - 137.0
+            helper.log_frame_rate()   # dropped
+        assert not info.called
+
+    def test_seeding_restarts_the_window_timer(self, helper):
+        """A new scroll should not open by reporting a one-frame window."""
+        helper.last_fps_log_time = 0.0  # boundary long overdue
+        helper.log_frame_rate()         # seeds
+        with patch.object(helper.logger, "info") as info:
+            helper.log_frame_rate()     # first real frame
+        assert not info.called
+        assert len(helper._window) == 1
+
+    def test_a_normal_frame_still_counts(self, helper):
+        helper.last_frame_time = time.time() - 0.010
+        helper.log_frame_rate()
+        assert len(helper._window) == 1
+        assert helper._window[0] == pytest.approx(0.010, abs=0.005)