diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index a4368014..ef410913 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/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. | diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index 11921ae6..da233da7 100644 --- a/scripts/frame_soak.py +++ b/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 diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index c71399ff..ee554398 100644 --- a/src/common/frame_timing.py +++ b/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 diff --git a/src/display_manager.py b/src/display_manager.py index 23cdc717..529e1f6c 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -1282,6 +1282,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() diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index f3238212..e3ffae68 100644 --- a/test/test_frame_timing.py +++ b/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)