Merge branch 'claude/frame-timing-harness' into claude/scan-order-compensation

docs/SCROLL_PERFORMANCE.md

@@ -334,7 +334,7 @@ service's user.
 | line | what it tells you |
 |---|---|
 | **Late frames** | Frames presented one or more refreshes after they were due: the panel showed the previous frame again, a visible hitch. **The pass/fail number**, 0.1% by default (`--max-late-pct`). Only intervals between two scrolling frames count, and a frame held for `frame_hold` refreshes is due `frame_hold` refreshes after the last. |
-| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers, blocking calls on the render thread. Reported but not failed on, because some are handovers between plugins rather than faults. A gap still counts when the display's scroll state went missing across it (it expires after 2 s, and plugins clear it from their own `display()`), as long as the scroll carries on straight after. |
+| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers, blocking calls on the render thread. Reported but not failed on, because some are handovers between plugins rather than faults. A gap still counts when the display's scroll state went missing for one frame across it, as long as scrolling resumes within 1 s: both of that frame's intervals count. Two static frames in a row end the scroll. (The state expires after 2 s without scroll activity, and plugins can clear it from their own `display()`.) The late and early rates are over frames judged against a known refresh period, which the recorder adopts once two windows in a row agree on it. |
 | **blit** | Copying the frame into the matrix canvas (`SetImage`). It grows with width × height × `pwm_bits`: ~5.5 ms at 512×64 with 8 bits on a Pi 4. It is the biggest fixed cost, and it sets the refresh rates a rig can hold one pixel per refresh at. |
 | **wait** | Time blocked in `SwapOnVSync`, i.e. the slack left in each refresh. A p50 near zero means the rig has no headroom and anything extra lands a frame late. |
 | **work** | Everything else between two frames: drawing, scrolling, and waiting for the GIL. A wide gap between its p50 and p99 is another thread getting in the way. |

scripts/frame_soak.py

@@ -130,6 +130,9 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
     delta = diff(before, after)
     totals = delta["totals"]
     frames = totals["scroll_frames"]
+    # The rates are over frames judged against a known refresh period. Stats
+    # from a recorder that predates the count fall back to every frame.
+    timed = totals.get("timed_frames", frames) if "timed_frames" in totals else frames
     hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0
     bucket_ms = after.get("bucket_ms", 0.25)
     report = {
@@ -141,12 +144,13 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
         "scroll_frames": frames,
         "static_frames": totals["static_frames"],
         "late_frames": totals["late_frames"],
-        "late_pct": round(100.0 * totals["late_frames"] / frames, 3) if frames else None,
+        "timed_frames": timed,
+        "late_pct": round(100.0 * totals["late_frames"] / timed, 3) if timed else None,
         "missed_refreshes": totals["missed_refreshes"],
         "late_by": totals["late_by"],
         "early_frames": totals.get("early_frames", 0),
-        "early_pct": (round(100.0 * totals.get("early_frames", 0) / frames, 3)
-                      if frames else None),
+        "early_pct": (round(100.0 * totals.get("early_frames", 0) / timed, 3)
+                      if timed else None),
         "freeze_by": totals.get("freeze_by", {}),
         "freezes": totals["freezes"],
         "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None,
@@ -161,8 +165,13 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
     # bit-banging the panel and pushing frames at once); a widening gap between
     # the two is a render-cost regression even when nothing is late.
     typical = (report["timing_ms"].get("interval_per_hold") or {}).get("p50")
-    report["held_refresh_hz"] = (round(1000.0 / typical, 1)
-                                 if isinstance(typical, (int, float)) and typical else None)
+    # percentiles() reports a bucket's upper edge; the midpoint is the better
+    # estimate, and half a 0.25ms bucket is already ~1% at 100Hz -- the size
+    # of the idle-vs-held gap this number exists to show.
+    if isinstance(typical, (int, float)) and typical > bucket_ms / 2:
+        report["held_refresh_hz"] = round(1000.0 / (typical - bucket_ms / 2), 1)
+    else:
+        report["held_refresh_hz"] = None
     return report
 
 

src/common/frame_timing.py

@@ -83,6 +83,7 @@ three times per threshold, so keep it to diagnostic runs, not soaks.
 
 from __future__ import annotations
 
+import copy
 import json
 import logging
 import os
@@ -263,6 +264,8 @@ class FrameTimingRecorder:
         self.started = time.time()
         self.refresh_period: Optional[float] = (
             1.0 / refresh_hz if refresh_hz and refresh_hz > 0 else None)
+        # The first estimate, until a second window agrees with it.
+        self._refresh_candidate: Optional[float] = None
         self.totals: Dict[str, Any] = {
             "static_frames": 0,
             "scroll_frames": 0,
@@ -270,6 +273,10 @@ class FrameTimingRecorder:
             "missed_refreshes": 0,
             "late_by": {"1": 0, "2": 0, "3-5": 0, "6+": 0},
             "early_frames": 0,
+            # Frames judged against a known refresh period: the denominator
+            # for the late and early rates. Frames before the period is known
+            # are neither, and must not dilute them.
+            "timed_frames": 0,
             "freezes": 0,
             "freeze_seconds": 0.0,
             "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS},
@@ -290,6 +297,12 @@ class FrameTimingRecorder:
         self.scrolling_now: Optional[Callable[[], bool]] = None
         self.watchdog: Optional["StallWatchdog"] = None
 
+    def close(self) -> None:
+        """Stop the stall watchdog, if one was started."""
+        watchdog, self.watchdog = self.watchdog, None
+        if watchdog is not None:
+            watchdog.stop()
+
     # -- render thread ------------------------------------------------------
 
     def record(self, blit: float, wait: float, hold: int, scrolling: bool,
@@ -381,9 +394,20 @@ class FrameTimingRecorder:
         if len(per_hold) >= MIN_FRAMES_FOR_REFRESH:
             estimate = per_hold[len(per_hold) // 10]
             current = self.refresh_period
-            if estimate > 0 and (
-                    current is None
-                    or current * (1.0 - MAX_REFRESH_DROP) <= estimate < current):
+            if estimate <= 0:
+                pass
+            elif current is None:
+                # Adopt the first period only once two windows in a row agree:
+                # one loaded window at startup, most of its frames a refresh
+                # late, would otherwise fix a period twice the real one for
+                # the life of the process, since later windows may only lower
+                # it by MAX_REFRESH_DROP.
+                candidate = self._refresh_candidate
+                if candidate and abs(estimate - candidate) <= candidate * MAX_REFRESH_DROP:
+                    self.refresh_period = min(candidate, estimate)
+                else:
+                    self._refresh_candidate = estimate
+            elif current * (1.0 - MAX_REFRESH_DROP) <= estimate < current:
                 self.refresh_period = estimate
         period = self.refresh_period
 
@@ -406,6 +430,7 @@ class FrameTimingRecorder:
                 histogram = histograms[name]
                 histogram[bucket] = histogram.get(bucket, 0) + 1
             if period:
+                totals["timed_frames"] += 1
                 missed = round(interval / period) - hold
                 if missed >= 1:
                     totals["late_frames"] += 1
@@ -434,7 +459,7 @@ class FrameTimingRecorder:
             "measured_refresh_hz": round(1.0 / period, 2) if period else None,
             "binding_releases_gil": self._binding_gil,
             "info": info,
-            "totals": self.totals,
+            "totals": copy.deepcopy(self.totals),
             # JSON keys are strings; readers convert back.
             "histograms": {name: {str(k): v for k, v in sorted(h.items())}
                            for name, h in self.histograms.items()},
@@ -497,18 +522,25 @@ class StallWatchdog:
         self.stalls = 0
         self._last_dump: Optional[float] = None
         self._thread: Optional[threading.Thread] = None
+        self._stop = threading.Event()
 
     def start(self) -> None:
         self._thread = threading.Thread(
             target=self._run, daemon=True, name="stall-watchdog")
         self._thread.start()
 
+    def stop(self, timeout: float = 1.0) -> None:
+        """End the polling thread (DisplayManager.cleanup calls this)."""
+        self._stop.set()
+        thread = self._thread
+        if thread is not None and thread is not threading.current_thread():
+            thread.join(timeout)
+
     def _run(self) -> None:
         last_wake = self.clock()
         stall_from: Optional[float] = None   # presented_at of the stalled frame
         dumped = False
-        while True:
-            time.sleep(self.poll)
+        while not self._stop.wait(self.poll):
             now = self.clock()
             late = max(0.0, now - last_wake - self.poll)
             last_wake = now
@@ -534,8 +566,11 @@ class StallWatchdog:
             return None, False
 
         scrolling_now = self.recorder.scrolling_now
-        if stall_from is not None and (scrolling_now is None or not scrolling_now()):
+        if (stall_from is not None and now - stall_from >= GAP_SECONDS
+                and (scrolling_now is None or not scrolling_now())):
             # The scroll ended without another frame: nothing more to time.
+            # Only past GAP_SECONDS: the scroll state expires after 2s without
+            # activity, which a stall outlasts, and its end still wants saying.
             return None, False
         age = now - presented_at
         if (stall_from is None and scrolling and age >= self.threshold

src/display_manager.py

@@ -1326,6 +1326,8 @@ class DisplayManager:
 
     def cleanup(self):
         """Clean up resources."""
+        if getattr(self, 'frame_timing', None) is not None:
+            self.frame_timing.close()
         if hasattr(self, 'matrix') and self.matrix is not None:
             try:
                 self.matrix.Clear()

test/test_frame_timing.py

@@ -40,24 +40,48 @@ def _aggregate(recorder):
     return recorder.totals
 
 
-def _recorder(tmp_path):
+def _recorder(tmp_path, **kwargs):
     # A flush interval nothing in these tests reaches, so aggregation is
     # driven explicitly and no worker thread starts.
     return FrameTimingRecorder(path=str(tmp_path / "stats.json"),
-                               flush_interval=1e9)
+                               flush_interval=1e9, **kwargs)
+
+
+def _settle(recorder, interval=PERIOD, hold=1, start=0.0):
+    """Two agreeing windows: the refresh period is adopted from the second."""
+    for offset in (0.0, 50.0):
+        _feed(recorder, [interval] * 200, hold=hold, start=start + offset)
+        _aggregate(recorder)
 
 
 def test_steady_frames_are_on_time_and_give_the_refresh(tmp_path):
     r = _recorder(tmp_path)
     _feed(r, [PERIOD] * 200)
+    _aggregate(r)
+    assert r.refresh_period is None       # one window proves nothing yet
+    _feed(r, [PERIOD] * 200, start=500.0)
     totals = _aggregate(r)
-    assert totals["scroll_frames"] == 200
+    assert totals["scroll_frames"] == 400
+    assert totals["timed_frames"] == 200  # the second window, judged
     assert totals["late_frames"] == 0
     assert abs(1.0 / r.refresh_period - 100.0) < 0.5
 
 
-def test_a_frame_a_refresh_late_is_counted(tmp_path):
+def test_a_bad_first_window_does_not_fix_the_period(tmp_path):
+    # Startup: nine frames in ten a refresh late, so that window's low end is
+    # two periods. Adopted outright, every later window (a 50% "drop") would
+    # be refused and one-refresh-late frames would read as on time for good.
     r = _recorder(tmp_path)
+    _feed(r, [2 * PERIOD if i % 10 else PERIOD for i in range(200)])
+    _aggregate(r)
+    for start in (500.0, 1000.0):
+        _feed(r, [PERIOD] * 200, start=start)
+        _aggregate(r)
+    assert abs(1.0 / r.refresh_period - 100.0) < 0.5
+
+
+def test_a_frame_a_refresh_late_is_counted(tmp_path):
+    r = _recorder(tmp_path, refresh_hz=100.0)
     intervals = [PERIOD] * 200
     intervals[50] = 2 * PERIOD      # one refresh late
     intervals[120] = 4 * PERIOD     # three refreshes late
@@ -71,9 +95,8 @@ def test_a_frame_a_refresh_late_is_counted(tmp_path):
 def test_a_held_frame_is_not_late(tmp_path):
     # 50px/s on a 100Hz panel is 1px every 2 refreshes: 20ms is on time.
     r = _recorder(tmp_path)
-    _feed(r, [2 * PERIOD] * 200, hold=2)
-    totals = _aggregate(r)
-    assert totals["late_frames"] == 0
+    _settle(r, 2 * PERIOD, hold=2)
+    assert r.totals["late_frames"] == 0
     assert abs(1.0 / r.refresh_period - 100.0) < 0.5
 
 
@@ -204,8 +227,7 @@ def test_early_frames_are_counted(tmp_path):
 
 def test_refresh_estimate_survives_a_window_full_of_misses(tmp_path):
     r = _recorder(tmp_path)
-    _feed(r, [PERIOD] * 200)
-    _aggregate(r)
+    _settle(r)
     # A bad window where every frame is late must not redefine the refresh.
     _feed(r, [2 * PERIOD] * 200, start=1000.0)
     totals = _aggregate(r)
@@ -249,8 +271,7 @@ def test_soak_report_is_the_difference_between_snapshots(tmp_path):
 
 def test_soak_fails_a_run_that_was_not_locked(tmp_path):
     r = _recorder(tmp_path)
-    _feed(r, [2 * PERIOD] * 200, hold=2)
-    _aggregate(r)
+    _settle(r, 2 * PERIOD, hold=2)
     before = json.loads(json.dumps(r.snapshot()))
     _feed(r, [PERIOD] * 1000, hold=2, start=500.0)   # never waited out the hold
     _aggregate(r)
@@ -262,6 +283,50 @@ def test_soak_fails_a_run_that_was_not_locked(tmp_path):
     assert not frame_soak.passed(report, 0.1)
 
 
+def test_frames_before_the_period_is_known_do_not_make_a_verdict(tmp_path):
+    # With no period, nothing was judged: 0 late of 200 is not a pass.
+    r = _recorder(tmp_path)
+    before = json.loads(json.dumps(r.snapshot()))
+    _feed(r, [PERIOD] * 200)
+    _aggregate(r)
+    after = json.loads(json.dumps(r.snapshot()))
+    after["updated"] = before["updated"] + 10.0
+    report = frame_soak.build_report(before, after, preview=False)
+    assert report["scroll_frames"] == 200
+    assert report["timed_frames"] == 0
+    assert report["late_pct"] is None
+    assert not frame_soak.passed(report, 0.1)
+
+
+def test_a_snapshot_is_not_changed_by_what_comes_after_it(tmp_path):
+    # render_bench keeps the snapshot object itself, no JSON round trip; it
+    # used to share the live totals, so every graded run differenced to zero.
+    r = _recorder(tmp_path, refresh_hz=100.0)
+    _feed(r, [PERIOD] * 100)
+    _aggregate(r)
+    before = r.snapshot()
+    _feed(r, [PERIOD] * 300, start=500.0)
+    _aggregate(r)
+    after = r.snapshot()
+    after["updated"] = before["updated"] + 10.0
+    report = frame_soak.build_report(before, after, preview=False)
+    assert report["scroll_frames"] == 300
+    assert report["late_pct"] == 0.0
+
+
+def test_the_held_rate_is_read_from_the_bucket_midpoint(tmp_path):
+    # percentiles() gives a bucket's upper edge. At the midpoint of the
+    # [10.0, 10.25)ms bucket the upper edge would say 97.6Hz.
+    r = _recorder(tmp_path, refresh_hz=100.0)
+    before = json.loads(json.dumps(r.snapshot()))
+    _feed(r, [0.010125] * 300)
+    _aggregate(r)
+    after = json.loads(json.dumps(r.snapshot()))
+    after["updated"] = before["updated"] + 10.0
+    report = frame_soak.build_report(before, after, preview=False)
+    assert report["held_refresh_hz"] == round(1000.0 / 10.125, 1)
+
+
 def test_soak_percentiles_mark_the_overflow_bucket():
     top = frame_timing.BUCKET_COUNT - 1
     result = frame_soak.percentiles({0: 98, top: 2}, 0.25)
@@ -269,10 +334,9 @@ def test_soak_percentiles_mark_the_overflow_bucket():
     assert str(result["max"]).startswith(">=")
 
 
-def test_display_manager_records_every_presented_frame():
+def test_display_manager_records_every_presented_frame(monkeypatch):
     """The hook sits in update_display, so every source is covered."""
-    import os
-    os.environ["EMULATOR"] = "true"
+    monkeypatch.setenv("EMULATOR", "true")
     from src.display_manager import DisplayManager
     DisplayManager._instance = None
     DisplayManager._initialized = False
@@ -371,6 +435,36 @@ def test_watchdog_rate_limits_its_dumps(caplog):
     assert dog.stalls == 2
 
 
+def test_watchdog_reports_the_end_of_a_stall_that_outlasts_the_scroll_state(caplog):
+    # The scroll state expires after 2s without activity; a stall longer than
+    # that must still have its end reported.
+    rec = _FakeRecorder()
+    dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0)
+    rec.last_frame = (10.0, True, 1)
+    with caplog.at_level("WARNING", logger="src.common.frame_timing"):
+        state = dog.check(10.3, 0.0, None, False)          # dumped
+        rec.scrolling = False                               # state expired at 12.0
+        state = dog.check(12.5, 0.0, *state)
+        rec.last_frame = (13.0, True, 1)                    # the frame arrives
+        dog.check(13.05, 0.0, *state)
+    over = [r.getMessage() for r in caplog.records
+            if r.getMessage().startswith("Render stall over")]
+    assert over == ["Render stall over: no frame for 3000ms"]
+
+
+def test_closing_the_recorder_stops_its_watchdog(tmp_path, monkeypatch):
+    monkeypatch.delenv("LEDMATRIX_STALL_WATCHDOG", raising=False)
+    r = _recorder(tmp_path)
+    r.scrolling_now = lambda: True
+    r.record(0.001, 0.009, 1, True, 1.0)
+    thread = r.watchdog._thread
+    assert thread.is_alive()
+    r.close()
+    thread.join(2)
+    assert not thread.is_alive()
+    assert r.watchdog is None
+
+
 def test_watchdog_threshold_can_be_lowered_for_a_diagnostic_run(monkeypatch):
     monkeypatch.delenv("LEDMATRIX_STALL_WATCHDOG_MS", raising=False)
     assert frame_timing.watchdog_settings() == {}
@@ -470,6 +564,8 @@ def test_soak_calls_a_rate_faster_than_the_panel_not_locked(tmp_path):
     before = json.loads(json.dumps(r.snapshot()))
     _feed(r, [0.0012] * 500)           # unseeded: nothing looks early...
     r.drain()
+    _feed(r, [0.0012] * 500, start=500.0)
+    r.drain()
     after = json.loads(json.dumps(r.snapshot()))
     after["updated"] = before["updated"] + 10.0
     report = frame_soak.build_report(before, after, preview=False)