From 3eb7a2e34973efa6233afcca31225ef4912fb551 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Wed, 23 Sep 2026 21:50:30 -0400 Subject: [PATCH 1/8] feat(perf): time every presented frame, and a soak script to judge a rig Each scroller already logs its own stats line, but in different formats, per source, and Vegas logs a healthy window only at DEBUG. None of it answers the question a release has to answer on each rig: over a long run, how often did a moving frame reach the panel late? Every frame reaches the panel through DisplayManager.update_display, so it is timed there once, whoever drew it: the blit (SetImage), the vsync wait, and the interval since the previous frame. The render thread only appends a tuple. A worker thread aggregates cumulative counters and histograms and rewrites /dev/shm/ledmatrix_frame_stats.json every 10s (RAM, so no SD wear). A frame due after `hold` refreshes that lands one or more refreshes later is "late": the panel repeated the previous frame, a visible hitch. Gaps of 250ms+ inside a scroll are "freezes" (recomposes, handovers, blocking calls), counted separately so one handover does not read as 40 missed refreshes. Static frames, the first frame of a scroll and gaps between scrolls are not timed. The refresh period is estimated from the frames themselves. scripts/frame_soak.py runs next to the service as any user, diffs two snapshots over a run (default 10 minutes), optionally keeps the web preview's viewer marker fresh, and exits non-zero above 0.1% late frames. It also reports whether the loaded rgbmatrix binding releases the GIL. Documented under "Soaking a rig" in docs/SCROLL_PERFORMANCE.md. Co-Authored-By: Claude Opus 5.5 --- CLAUDE.md | 1 + docs/SCROLL_PERFORMANCE.md | 46 ++++++ scripts/frame_soak.py | 309 +++++++++++++++++++++++++++++++++++++ src/common/frame_timing.py | 288 ++++++++++++++++++++++++++++++++++ src/display_manager.py | 23 +++ test/test_frame_timing.py | 181 ++++++++++++++++++++++ 6 files changed, 848 insertions(+) create mode 100644 scripts/frame_soak.py create mode 100644 src/common/frame_timing.py create mode 100644 test/test_frame_timing.py diff --git a/CLAUDE.md b/CLAUDE.md index 714ff7b0..ddc8c516 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -34,6 +34,7 @@ - Browser preview without the display loop: `python3 scripts/dev_server.py` → http://localhost:5001 - Full display in emulator mode: `python3 run.py -e` (or `EMULATOR=true python3 run.py`) - Validate one plugin headlessly: `python3 scripts/check_plugin.py --plugin ` +- Soak a rig for frame timing (on the Pi, service running): `python3 scripts/frame_soak.py --preview` — late-frame rate across every scroller; see `docs/SCROLL_PERFORMANCE.md` ## Plugin Store Architecture - Official plugins live in the `ledmatrix-plugins` monorepo (not individual repos) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 82e9f912..05ce11ed 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -231,6 +231,9 @@ advances by elapsed time at `scroll_speed / scroll_delay` px/s. ## Diagnosing a juddery scroller +To check a whole rig rather than one scroller, soak it -- see *Soaking a rig* +below. + **An average will lie to you.** A 2 ms duplicate frame and a 21 ms double-wait mean exactly 10 ms, so a ticker stalling on half its frames still averages to a healthy 100 fps. The stats line reports the tail for that reason — read the @@ -303,6 +306,49 @@ journalctl -u ledmatrix --since "-5min" --no-pager | grep -iE "px/s|px/frame" If a plugin logs its scroll config **twice** with different modes, the second line is what is running. +## Soaking a rig + +The per-scroller lines above tell you *which* scroller misbehaves. The soak +answers the question a release has to answer for each rig: **over a long run, +how often did a moving frame reach the panel late?** + +Every frame reaches the panel through `DisplayManager.update_display`, so it is +timed there once, whoever drew it -- Vegas, a ticker plugin, anything. The +render thread only appends a tuple; a worker thread aggregates and rewrites +`/dev/shm/ledmatrix_frame_stats.json` every 10 seconds (RAM, so no SD-card +wear). `src/common/frame_timing.py` has the details. + +```bash +python3 scripts/frame_soak.py # 10 minutes, as the display is now +python3 scripts/frame_soak.py --preview # with the web preview open +python3 scripts/frame_soak.py --show # totals since the service started +python3 scripts/frame_soak.py --json a.json # keep the report to compare later +``` + +It runs as any user next to the display service and stops nothing. It needs +something to *scroll* during the run: a live game holding a static scoreboard +on screen gives no verdict. `--preview` keeps the web preview's viewer marker +fresh, which puts the preview's PNG encoding at full rate -- run it as the web +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. | +| **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. | +| **Binding** | `STOCK` means the rgbmatrix binding holds the GIL through the vsync wait, which starves every other thread. See *Rebuilding the binding*. | + +The refresh rate is estimated from the frames themselves (swaps that block on +vsync can only land on refresh boundaries). Cross-check it with +`scroll_speeds.py --measure` if it looks wrong. It can read high on a rig where +nothing ever presented at the full refresh rate. + +A soak is only meaningful against a fixed workload. Compare runs with the same +content and `--preview` setting, and alternate which build goes first when you +A/B two of them. A live-API workload drifts over time. + ## Rebuilding the binding ```bash diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py new file mode 100644 index 00000000..a53b2ce5 --- /dev/null +++ b/scripts/frame_soak.py @@ -0,0 +1,309 @@ +#!/usr/bin/env python3 +"""Soak a running display and report how often moving frames reached the panel late. + +Runs NEXT TO the display service, as any user: it only reads the stats file the +service writes (src/common/frame_timing.py) at the start and end of the run and +reports the difference. Nothing is stopped, restarted or drawn. + + # 10 minutes, as the display is now + python3 scripts/frame_soak.py + + # the same with the web preview open (the preview's PNG encodes are one of + # the things that used to make the render loop miss refreshes) + python3 scripts/frame_soak.py --preview + + # quick look at the totals since the service started + python3 scripts/frame_soak.py --show + + # keep the report for a before/after comparison + python3 scripts/frame_soak.py --duration 600 --json soak-before.json + +Exit status: 0 when the late-frame rate is within ``--max-late-pct``, 1 when it +is not, 2 when there was nothing to measure (no stats file, the service +restarted mid-run, or nothing scrolled). + +What the numbers mean +--------------------- +late frames frames that reached the panel one or more refreshes after they + were due -- the panel showed the previous frame again, which on + a moving strip is a visible hitch. This is the pass/fail number. +freezes gaps of 250ms+ inside a scroll: recomposes, plugin handovers, + blocking calls on the render thread. Reported, not failed on, + since some are handovers between plugins rather than faults. +blit copying the frame into the matrix canvas (rgbmatrix SetImage). + Grows with width x height x pwm_bits. +wait blocked in SwapOnVSync, i.e. slack before the refresh. +work everything else between two frames: drawing, scrolling, and + waiting for the GIL. +""" +from __future__ import annotations + +import argparse +import json +import os +import sys +import time +from pathlib import Path +from typing import Any, Dict, Optional + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common.frame_timing import ( # noqa: E402 + BUCKET_COUNT, + SCHEMA_VERSION, + default_stats_path, +) + +#: Touched by the web UI while someone has the preview open; a fresh marker +#: puts the display service's snapshot writer at full rate. Same path as +#: DisplayManager._viewer_marker_path. +VIEWER_MARKER = "/tmp/led_matrix_preview_viewer" # nosec B108 - fixed path shared with the service + +#: A stats file not rewritten for this long means nothing is being presented. +STALE_SECONDS = 30.0 + + +def load(path: str) -> Optional[Dict[str, Any]]: + try: + with open(path, encoding="utf-8") as handle: + stats = json.load(handle) + except (OSError, ValueError): + return None + if not isinstance(stats, dict) or stats.get("version") != SCHEMA_VERSION: + return None + return stats + + +def _histogram(stats: Dict[str, Any], name: str) -> Dict[int, int]: + raw = (stats.get("histograms") or {}).get(name) or {} + return {int(k): int(v) for k, v in raw.items()} + + +def diff(before: Dict[str, Any], after: Dict[str, Any]) -> Dict[str, Any]: + """What happened between two snapshots of the same process.""" + tb, ta = before["totals"], after["totals"] + totals = {} + for key, value in ta.items(): + if key == "late_by": + totals[key] = {k: v - tb[key].get(k, 0) for k, v in value.items()} + elif key == "worst_interval_ms": + # A running maximum can't be differenced; it is reported as the + # worst since the service started. + totals[key] = value + else: + totals[key] = value - tb[key] + histograms = {} + for name in (after.get("histograms") or {}): + hb, ha = _histogram(before, name), _histogram(after, name) + histograms[name] = {k: v - hb.get(k, 0) for k, v in ha.items() + if v - hb.get(k, 0) > 0} + return {"totals": totals, "histograms": histograms, + "seconds": after["updated"] - before["updated"]} + + +def percentiles(histogram: Dict[int, int], bucket_ms: float) -> Dict[str, Any]: + """p50/p95/p99/max from a sparse histogram, as each bucket's upper edge.""" + count = sum(histogram.values()) + if not count: + return {} + out = {} + targets = {"p50": 0.50, "p95": 0.95, "p99": 0.99} + running = 0 + for index in sorted(histogram): + running += histogram[index] + for name, fraction in list(targets.items()): + if running >= fraction * count: + out[name] = _edge(index, bucket_ms) + del targets[name] + out["max"] = _edge(max(histogram), bucket_ms) + return out + + +def _edge(index: int, bucket_ms: float): + if index >= BUCKET_COUNT - 1: + return f">={index * bucket_ms:g}" + return round((index + 1) * bucket_ms, 2) + + +def build_report(before, after, preview: bool) -> Dict[str, Any]: + delta = diff(before, after) + totals = delta["totals"] + frames = totals["scroll_frames"] + hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0 + bucket_ms = after.get("bucket_ms", 0.25) + return { + "seconds": round(delta["seconds"], 1), + "preview": preview, + "info": after.get("info"), + "binding_releases_gil": after.get("binding_releases_gil"), + "measured_refresh_hz": after.get("measured_refresh_hz"), + "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, + "missed_refreshes": totals["missed_refreshes"], + "late_by": totals["late_by"], + "freezes": totals["freezes"], + "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None, + "freeze_seconds": round(totals["freeze_seconds"], 2), + "worst_interval_ms": (round(totals["worst_interval_ms"], 1) + if totals["worst_interval_ms"] else None), + "timing_ms": {name: percentiles(h, bucket_ms) + for name, h in delta["histograms"].items()}, + } + + +def print_report(report: Dict[str, Any], limit: float) -> None: + info = report.get("info") or {} + size = "{}x{}".format( + (info.get("cols") or 0) * (info.get("chain_length") or 1), + (info.get("rows") or 0) * (info.get("parallel") or 1)) + gil = {True: "releases the GIL", False: "STOCK (holds the GIL in SwapOnVSync)", + None: "unknown"}[report.get("binding_releases_gil")] + print(f"Rig {info.get('pi_model') or 'unknown'}") + print(f"Panel {size} chain {info.get('chain_length')} x parallel " + f"{info.get('parallel')} pwm_bits {info.get('pwm_bits')} " + f"slowdown {info.get('gpio_slowdown')} mapping {info.get('hardware_mapping')}") + print(f"Refresh {report.get('measured_refresh_hz') or '?'} Hz measured, " + f"cap {info.get('limit_refresh_rate_hz')}") + print(f"Binding {gil}") + print(f"Run {report['seconds']:.0f}s, preview " + f"{'open (simulated)' if report['preview'] else 'as-is'}") + print() + frames = report["scroll_frames"] + print(f"Scrolling frames {frames}") + if frames: + late_by = report["late_by"] + print(f"Late frames {report['late_frames']} ({report['late_pct']}%)" + f" missed refreshes {report['missed_refreshes']}" + f" [by 1: {late_by['1']}, 2: {late_by['2']}, " + f"3-5: {late_by['3-5']}, 6+: {late_by['6+']}]") + print(f"Freezes >=250ms {report['freezes']}" + f" ({report['freezes_per_hour']}/h, {report['freeze_seconds']}s total)" + f" worst gap since start {report['worst_interval_ms'] or '-'} ms") + print() + print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}") + for name in ("blit", "wait", "work", "interval_per_hold"): + row = report["timing_ms"].get(name) or {} + print(f"{name:<18}" + "".join(f"{str(row.get(k, '-')):>8}" + for k in ("p50", "p95", "p99", "max"))) + print() + if report["late_pct"] is None: + print("RESULT nothing scrolled - no verdict") + elif report["late_pct"] <= limit: + print(f"RESULT PASS {report['late_pct']}% late <= {limit}%") + else: + print(f"RESULT FAIL {report['late_pct']}% late > {limit}%") + + +def touch_marker() -> bool: + try: + with open(VIEWER_MARKER, "a"): + pass + os.utime(VIEWER_MARKER, None) + return True + except OSError: + return False + + +def wait_for_fresh(path: str, timeout: float) -> Optional[Dict[str, Any]]: + """The first snapshot written after now, so both ends of the run are exact.""" + first = load(path) + deadline = time.time() + timeout + while time.time() < deadline: + current = load(path) + if current and (first is None or current["updated"] != first["updated"]): + return current + time.sleep(0.5) + return None + + +def main(argv=None) -> int: + parser = argparse.ArgumentParser(description=__doc__.split("\n")[0]) + parser.add_argument("--duration", type=float, default=600.0, + help="seconds to soak (default 600)") + parser.add_argument("--preview", action="store_true", + help="keep the web-preview viewer marker fresh, as an " + "open preview tab does") + parser.add_argument("--max-late-pct", type=float, default=0.1, + help="fail above this percentage of late frames (default 0.1)") + parser.add_argument("--stats", default=default_stats_path(), + help="stats file written by the display service") + parser.add_argument("--json", metavar="PATH", + help="also write the report as JSON") + parser.add_argument("--show", action="store_true", + help="print totals since the service started and exit") + args = parser.parse_args(argv) + + current = load(args.stats) + if current is None: + print(f"No frame stats at {args.stats}. Is the display service running a " + "build with frame timing, and has anything scrolled for ~10s?", + file=sys.stderr) + return 2 + if time.time() - current["updated"] > STALE_SECONDS: + print(f"Frame stats are {time.time() - current['updated']:.0f}s old: nothing " + "has been presented recently (static screen, or the service stopped).", + file=sys.stderr) + if not args.show: + return 2 + + if args.show: + empty = json.loads(json.dumps(current)) + for key, value in empty["totals"].items(): + empty["totals"][key] = ({k: 0 for k in value} if isinstance(value, dict) + else 0) + empty["histograms"] = {} + empty["updated"] = current["started"] + report = build_report(empty, current, preview=False) + print_report(report, args.max_late_pct) + return 0 + + if args.preview and not touch_marker(): + print(f"Cannot touch {VIEWER_MARKER}; run as the web service's user to " + "simulate an open preview.", file=sys.stderr) + return 2 + + print(f"Waiting for a fresh baseline from {args.stats} ...", flush=True) + before = wait_for_fresh(args.stats, timeout=60.0) + if before is None: + print("The stats file stopped updating.", file=sys.stderr) + return 2 + + end = time.time() + args.duration + next_progress = time.time() + 60.0 + while time.time() < end: + if args.preview: + touch_marker() + time.sleep(1.0) + if time.time() >= next_progress: + now = load(args.stats) + if now and now.get("pid") == before["pid"]: + done = now["totals"]["scroll_frames"] - before["totals"]["scroll_frames"] + late = now["totals"]["late_frames"] - before["totals"]["late_frames"] + print(f" {int(end - time.time())}s left: {done} scrolling frames, " + f"{late} late", flush=True) + next_progress += 60.0 + + after = wait_for_fresh(args.stats, timeout=60.0) + if after is None: + print("The stats file stopped updating during the run.", file=sys.stderr) + return 2 + if after.get("pid") != before.get("pid"): + print("The display service restarted during the run; results discarded.", + file=sys.stderr) + return 2 + + report = build_report(before, after, preview=args.preview) + print() + print_report(report, args.max_late_pct) + if args.json: + with open(args.json, "w", encoding="utf-8") as handle: + json.dump(report, handle, indent=2) + if report["late_pct"] is None: + return 2 + return 0 if report["late_pct"] <= args.max_late_pct else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py new file mode 100644 index 00000000..3743569b --- /dev/null +++ b/src/common/frame_timing.py @@ -0,0 +1,288 @@ +"""System-wide frame timing: one set of numbers for every presented frame. + +Each scroller already logs its own stats line (ScrollHelper.log_frame_rate, +the Vegas coordinator's "Vegas FPS"), but in different formats, per source, +and Vegas only logs a healthy window at DEBUG. None of that answers the +question a release has to answer on each rig: *over a long run, how often did +a moving frame reach the panel late?* + +Every frame reaches the panel through ``DisplayManager.update_display``, so it +is recorded there, once, whoever drew it. The render thread only appends a +tuple; a worker thread aggregates, and every ``flush_interval`` seconds writes +cumulative counters and histograms to a small JSON file -- in ``/dev/shm`` where +it exists, so a stats file refreshed all day costs no SD-card writes. +``scripts/frame_soak.py`` reads it twice and reports the difference. + +What is counted +--------------- +Only intervals between two consecutive *scrolling* frames count: a static +screen that changes once a second has no timing to get wrong, and the first +frame of a scroll has no predecessor worth measuring against. + +A frame held for ``hold`` refreshes should arrive ``hold`` refresh periods +after the one before it. One that arrives a whole refresh or more after that is +**late**: the panel showed the previous frame again, which on a moving strip is +a visible hitch. ``missed_refreshes`` sums how many refreshes late. + +An interval of ``FREEZE_SECONDS`` or more is a **freeze** instead -- a +recompose, a plugin handover, a blocking call on the render thread. Those are +counted separately, both because they are a different fault and because +folding a single 400ms handover into the late count as "40 missed refreshes" +would drown the jitter the late count exists to measure. Intervals of +``GAP_SECONDS`` or more are not frames at all (one scroll ending, another +starting later) and are ignored. + +The refresh period is estimated from the frames themselves: swaps that block +on vsync can only land on refresh boundaries, so the low end of +interval / hold is the period. It is the smallest per-window 10th percentile +seen so far, over windows with enough frames to trust. +""" + +from __future__ import annotations + +import json +import logging +import os +import queue +import sys +import tempfile +import threading +import time +from typing import Any, Dict, List, Optional, Tuple + +logger = logging.getLogger(__name__) + +#: Bumped when a field changes meaning, so a reader can refuse stale files. +SCHEMA_VERSION = 1 + +#: Histogram resolution. 64ms of range covers any frame worth drawing a +#: distribution of; everything beyond lands in the last bucket. +BUCKET_MS = 0.25 +BUCKET_COUNT = 256 + +#: See the module docstring. +FREEZE_SECONDS = 0.25 +GAP_SECONDS = 1.0 + +#: A window needs this many scrolling frames before its refresh estimate is +#: trusted -- about a second of scrolling. +MIN_FRAMES_FOR_REFRESH = 90 + +FLUSH_INTERVAL = 10.0 + +#: Written by the display service, read by scripts/frame_soak.py and anything +#: else that wants the numbers. The web UI's viewer marker lives in /tmp; this +#: goes to RAM where there is some, since it is rewritten all day. +STATS_FILENAME = "ledmatrix_frame_stats.json" + + +def default_stats_path() -> str: + base = "/dev/shm" if os.path.isdir("/dev/shm") else tempfile.gettempdir() + return os.path.join(base, STATS_FILENAME) + + +def _bucket(seconds: float) -> int: + index = int(seconds * 1000.0 / BUCKET_MS) + return min(max(index, 0), BUCKET_COUNT - 1) + + +def binding_releases_gil() -> Optional[bool]: + """Whether the loaded rgbmatrix binding releases the GIL, or None. + + The stock binding blocks in SwapOnVSync holding the GIL, which starves + every other thread for most of each frame (docs/SCROLL_PERFORMANCE.md). + scripts/build_rgbmatrix_nogil.sh rebuilds it, and the rebuilt module links + PyEval_SaveThread where the stock one never does -- a crude test, but the + only one that needs neither a probe on the panel nor the source tree the + module was built from. None when no hardware binding is loaded. + """ + module = sys.modules.get("rgbmatrix.core") + path = getattr(module, "__file__", None) + if not path: + return None + try: + with open(path, "rb") as handle: + return b"PyEval_SaveThread" in handle.read() + except OSError: + return None + + +def _pi_model() -> Optional[str]: + try: + with open("/proc/device-tree/model", "rb") as handle: + return handle.read().rstrip(b"\0").decode("ascii", "replace").strip() + except OSError: + return None + + +class FrameTimingRecorder: + """Collects per-frame timings on the render thread; aggregates elsewhere. + + ``record`` is the only method the render thread calls, and it does no more + than compare two floats and append a tuple. + """ + + def __init__( + self, + path: Optional[str] = None, + flush_interval: float = FLUSH_INTERVAL, + info: Optional[Dict[str, Any]] = None, + ): + self.path = path or default_stats_path() + self.flush_interval = flush_interval + self.info = dict(info or {}) + + # Render-thread state. + self._pending: List[Tuple[float, float, float, int]] = [] + self._static_frames = 0 + self._previous: Optional[Tuple[float, bool, int]] = None + self._last_flush: Optional[float] = None + self._queue: "queue.SimpleQueue" = queue.SimpleQueue() + self._worker: Optional[threading.Thread] = None + + # Worker-thread state. Nothing on the render thread reads these. + self.started = time.time() + self.refresh_period: Optional[float] = None + self.totals: Dict[str, Any] = { + "static_frames": 0, + "scroll_frames": 0, + "late_frames": 0, + "missed_refreshes": 0, + "late_by": {"1": 0, "2": 0, "3-5": 0, "6+": 0}, + "freezes": 0, + "freeze_seconds": 0.0, + "worst_interval_ms": 0.0, + } + self.histograms: Dict[str, Dict[int, int]] = { + "blit": {}, "wait": {}, "work": {}, "interval_per_hold": {}, + } + self._binding_gil: Optional[bool] = None + self._binding_checked = False + + # -- render thread ------------------------------------------------------ + + def record(self, blit: float, wait: float, hold: int, scrolling: bool, + presented_at: float) -> None: + """One frame reached the panel. + + :param blit: seconds spent copying the frame into the canvas. + :param wait: seconds SwapOnVSync blocked. + :param hold: the refreshes this frame was held for. + :param scrolling: whether a scroll was running when it was presented. + :param presented_at: ``time.perf_counter()`` when the swap returned. + """ + previous = self._previous + self._previous = (presented_at, scrolling, hold) + if not scrolling: + self._static_frames += 1 + elif previous is not None and previous[1]: + interval = presented_at - previous[0] + if interval < GAP_SECONDS: + self._pending.append((interval, blit, wait, hold)) + + if self._last_flush is None: + self._last_flush = presented_at + elif presented_at - self._last_flush >= self.flush_interval: + self._hand_off() + self._last_flush = presented_at + + def _hand_off(self) -> None: + batch, self._pending = self._pending, [] + static, self._static_frames = self._static_frames, 0 + self._queue.put((batch, static)) + if self._worker is None or not self._worker.is_alive(): + self._worker = threading.Thread( + target=self._run, daemon=True, name="frame-timing") + self._worker.start() + + # -- worker thread ------------------------------------------------------ + + def _run(self) -> None: + while True: + batch, static = self._queue.get() + try: + self.aggregate(batch, static) + self.write() + except Exception: # never let telemetry take anything down + logger.debug("Frame timing flush failed", exc_info=True) + + def aggregate(self, batch: List[Tuple[float, float, float, int]], + static: int) -> None: + """Fold one window of frames into the running totals.""" + totals = self.totals + totals["static_frames"] += static + + per_hold = sorted(interval / max(1, hold) + for interval, _, _, hold in batch + if interval < FREEZE_SECONDS) + if len(per_hold) >= MIN_FRAMES_FOR_REFRESH: + estimate = per_hold[len(per_hold) // 10] + if estimate > 0 and (self.refresh_period is None + or estimate < self.refresh_period): + self.refresh_period = estimate + period = self.refresh_period + + histograms = self.histograms + for interval, blit, wait, hold in batch: + totals["worst_interval_ms"] = max(totals["worst_interval_ms"], + interval * 1000.0) + if interval >= FREEZE_SECONDS: + totals["freezes"] += 1 + totals["freeze_seconds"] += interval + continue + totals["scroll_frames"] += 1 + for name, value in (("blit", blit), ("wait", wait), + ("work", max(0.0, interval - blit - wait)), + ("interval_per_hold", interval / max(1, hold))): + bucket = _bucket(value) + histogram = histograms[name] + histogram[bucket] = histogram.get(bucket, 0) + 1 + if period: + missed = round(interval / period) - hold + if missed >= 1: + totals["late_frames"] += 1 + totals["missed_refreshes"] += missed + key = ("1" if missed == 1 else "2" if missed == 2 + else "3-5" if missed <= 5 else "6+") + totals["late_by"][key] += 1 + + def snapshot(self) -> Dict[str, Any]: + """The JSON document: cumulative since this process started.""" + if not self._binding_checked: + self._binding_gil = binding_releases_gil() + self._binding_checked = True + info = dict(self.info) + info.setdefault("pi_model", _pi_model()) + period = self.refresh_period + return { + "version": SCHEMA_VERSION, + "pid": os.getpid(), + "started": self.started, + "updated": time.time(), + "bucket_ms": BUCKET_MS, + "freeze_seconds": FREEZE_SECONDS, + "measured_refresh_hz": round(1.0 / period, 2) if period else None, + "binding_releases_gil": self._binding_gil, + "info": info, + "totals": 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()}, + } + + def write(self) -> None: + """Replace the stats file atomically with the current snapshot.""" + directory = os.path.dirname(self.path) or "." + fd, tmp = tempfile.mkstemp(dir=directory, prefix=".frame_stats.", + suffix=".tmp") + try: + with os.fdopen(fd, "w", encoding="utf-8") as handle: + json.dump(self.snapshot(), handle) + os.chmod(tmp, 0o644) + os.replace(tmp, self.path) + except Exception: + try: + os.unlink(tmp) + except OSError: + pass + raise diff --git a/src/display_manager.py b/src/display_manager.py index bcbdfeac..84079738 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -52,6 +52,7 @@ import zlib import freetype from src.common import snapshot_policy +from src.common.frame_timing import FrameTimingRecorder from src.deprecation import deprecated from src.common.permission_utils import ( ensure_directory_permissions, @@ -232,6 +233,10 @@ class DisplayManager: # See src/common/scroll_config.py and scripts/scroll_speeds.py. self._frame_hold = 1 + # Timing of every presented frame, whoever drew it, for + # scripts/frame_soak.py. See src/common/frame_timing.py. + self.frame_timing = FrameTimingRecorder(info=self._frame_timing_info()) + self._scrolling_state = { 'is_scrolling': False, 'last_scroll_activity': 0, @@ -808,15 +813,21 @@ class DisplayManager: # Copy the current image to the offscreen canvas. In double-sided # mode the logical screen is first tiled across the full chain. + blit_started = time.perf_counter() if self._double_sided is not None: self.offscreen_canvas.SetImage(self._composite_double_sided()) else: self.offscreen_canvas.SetImage(self.image) + blit_done = time.perf_counter() # Swap buffers immediately. framerate_fraction holds the frame # for N refreshes; SwapOnVSync blocks for all of them, which is # what paces the render loop to the chosen frame rate. self.matrix.SwapOnVSync(self.offscreen_canvas, self._frame_hold) + presented_at = time.perf_counter() + self.frame_timing.record( + blit_done - blit_started, presented_at - blit_done, + self._frame_hold, self.is_currently_scrolling(), presented_at) # Swap our canvas references self.offscreen_canvas, self.current_canvas = self.current_canvas, self.offscreen_canvas @@ -1448,6 +1459,18 @@ class DisplayManager: value = 0.0 return value if value > 0 else 100.0 + def _frame_timing_info(self) -> Dict[str, Any]: + """What the frame-timing stats were measured on, for the soak report.""" + display = self.config.get('display') or {} + hardware = display.get('hardware') or {} + runtime = display.get('runtime') or {} + info = {key: hardware.get(key) for key in ( + 'rows', 'cols', 'chain_length', 'parallel', 'pwm_bits', + 'hardware_mapping', 'limit_refresh_rate_hz', 'pixel_mapper_config')} + info['gpio_slowdown'] = runtime.get('gpio_slowdown') + info['emulator'] = os.environ.get('EMULATOR', 'false') == 'true' + return info + def set_frame_hold(self, refreshes: int) -> None: """Hold each pushed frame for this many panel refreshes (>=1). diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py new file mode 100644 index 00000000..67703af1 --- /dev/null +++ b/test/test_frame_timing.py @@ -0,0 +1,181 @@ +"""System-wide frame timing (src/common/frame_timing.py) and its soak report. + +The recorder's job is to separate what a viewer sees as a hitch -- a moving +frame one or more refreshes late -- from things that are not jitter: static +screens, the first frame of a scroll, gaps between scrolls, and freezes. +""" +import json +import sys +import time +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common import frame_timing # noqa: E402 +from src.common.frame_timing import FrameTimingRecorder # noqa: E402 + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent / "scripts")) +import frame_soak # noqa: E402 + +PERIOD = 0.010 # a 100Hz panel + + +def _feed(recorder, intervals, hold=1, scrolling=True, start=100.0, + blit=0.002, wait=0.004): + """Present one frame, then one more per interval.""" + t = start + recorder.record(blit, wait, hold, scrolling, t) + for interval in intervals: + t += interval + recorder.record(blit, wait, hold, scrolling, t) + return t + + +def _aggregate(recorder): + batch, static = recorder._pending, recorder._static_frames + recorder._pending, recorder._static_frames = [], 0 + recorder.aggregate(batch, static) + return recorder.totals + + +def _recorder(tmp_path): + # 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) + + +def test_steady_frames_are_on_time_and_give_the_refresh(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD] * 200) + totals = _aggregate(r) + assert totals["scroll_frames"] == 200 + 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): + r = _recorder(tmp_path) + intervals = [PERIOD] * 200 + intervals[50] = 2 * PERIOD # one refresh late + intervals[120] = 4 * PERIOD # three refreshes late + _feed(r, intervals) + totals = _aggregate(r) + assert totals["late_frames"] == 2 + assert totals["missed_refreshes"] == 1 + 3 + assert totals["late_by"] == {"1": 1, "2": 0, "3-5": 1, "6+": 0} + + +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 + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + + +def test_small_jitter_is_not_late(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD * (1 + 0.03 * ((i % 5) - 2)) for i in range(300)]) + assert _aggregate(r)["late_frames"] == 0 + + +def test_static_frames_and_the_start_of_a_scroll_are_not_timed(tmp_path): + r = _recorder(tmp_path) + t = _feed(r, [1.0, 1.0, 1.0], scrolling=False) + # The first scrolling frame follows a static one 300ms later: that is a + # scroll starting, not a 30-refresh stall. + _feed(r, [PERIOD] * 100, start=t + 0.3) + totals = _aggregate(r) + assert totals["static_frames"] == 4 + assert totals["scroll_frames"] == 100 + assert totals["late_frames"] == totals["freezes"] == 0 + + +def test_freezes_are_separate_from_late_frames_and_gaps_are_ignored(tmp_path): + r = _recorder(tmp_path) + intervals = [PERIOD] * 200 + intervals[80] = 0.400 # a recompose: freeze + intervals[150] = 3.0 # one scroll ended, another began later: ignored + _feed(r, intervals) + totals = _aggregate(r) + assert totals["freezes"] == 1 + assert abs(totals["freeze_seconds"] - 0.4) < 1e-9 + assert totals["late_frames"] == 0 + assert totals["scroll_frames"] == 198 + + +def test_refresh_estimate_survives_a_window_full_of_misses(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD] * 200) + _aggregate(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) + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + assert totals["late_frames"] == 200 + + +def test_record_hands_off_and_the_worker_writes_the_file(tmp_path): + path = tmp_path / "stats.json" + r = FrameTimingRecorder(path=str(path), flush_interval=0.5, + info={"cols": 128, "rows": 32}) + _feed(r, [PERIOD] * 120) # 1.2s of frames: at least one flush + deadline = time.time() + 5 + while not path.exists() and time.time() < deadline: + time.sleep(0.02) + stats = json.loads(path.read_text(encoding="utf-8")) + assert stats["version"] == frame_timing.SCHEMA_VERSION + assert stats["info"]["cols"] == 128 + assert stats["totals"]["scroll_frames"] > 0 + + +def test_soak_report_is_the_difference_between_snapshots(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD] * 200) + _aggregate(r) + before = json.loads(json.dumps(r.snapshot())) + intervals = [PERIOD] * 1000 + intervals[500] = 0.0201 # a refresh late; off a bucket boundary + _feed(r, intervals, start=500.0) + _aggregate(r) + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + + report = frame_soak.build_report(before, after, preview=True) + assert report["scroll_frames"] == 1000 + assert report["late_frames"] == 1 + assert report["late_pct"] == 0.1 + assert report["timing_ms"]["blit"]["p50"] == 2.25 # 2ms lands in [2, 2.25) + assert report["timing_ms"]["interval_per_hold"]["max"] == 20.25 + + +def test_soak_percentiles_mark_the_overflow_bucket(): + top = frame_timing.BUCKET_COUNT - 1 + result = frame_soak.percentiles({0: 98, top: 2}, 0.25) + assert result["p50"] == 0.25 + assert str(result["max"]).startswith(">=") + + +def test_display_manager_records_every_presented_frame(): + """The hook sits in update_display, so every source is covered.""" + import os + os.environ["EMULATOR"] = "true" + from src.display_manager import DisplayManager + DisplayManager._instance = None + DisplayManager._initialized = False + dm = DisplayManager({"display": { + "hardware": {"rows": 32, "cols": 64, "chain_length": 1, "parallel": 1}, + "runtime": {"gpio_slowdown": 0}}}, suppress_test_pattern=True) + try: + assert dm.frame_timing.info["cols"] == 64 + dm.set_scrolling_state(True) + for shade in (10, 20, 30): + dm.draw.rectangle([0, 0, 4, 4], fill=(shade, 0, 0)) + dm.update_display() + assert len(dm.frame_timing._pending) == 2 # 3 frames, 2 intervals + finally: + dm.set_scrolling_state(False) + DisplayManager._instance = None + DisplayManager._initialized = False From 98728d3b811466de8d90ec221aebac7d1cd99836 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 08:49:37 -0400 Subject: [PATCH 2/8] fix(perf): count 1-2s stalls, flag early frames, and keep the refresh estimate honest Three gaps found by the first hdpi soaks: - Intervals of 1s or more between two scrolling frames were dropped as "gaps between scrolls". But the scrolling state lapses only after 2s, so every 1-2s stall inside a scroll vanished from the report. Those are now freezes (the gap bound is a 5s sanity limit), with a breakdown by length. - A frame a whole refresh early means the swap did not wait for the panel. Those are counted, and a soak with more than the threshold of them fails as NOT LOCKED instead of reporting a flattering late rate. - The refresh estimate took the lowest window it had seen, so one window of non-blocking swaps halved it and made every early frame look on time. A window may now lower it by at most 20%. Co-Authored-By: Claude Opus 5.5 --- scripts/frame_soak.py | 33 +++++++++++++++++++++--- src/common/frame_timing.py | 43 ++++++++++++++++++++++++++----- test/test_frame_timing.py | 53 ++++++++++++++++++++++++++++++++++---- 3 files changed, 113 insertions(+), 16 deletions(-) diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index a53b2ce5..24a8857e 100644 --- a/scripts/frame_soak.py +++ b/scripts/frame_soak.py @@ -84,14 +84,15 @@ def diff(before: Dict[str, Any], after: Dict[str, Any]) -> Dict[str, Any]: tb, ta = before["totals"], after["totals"] totals = {} for key, value in ta.items(): - if key == "late_by": - totals[key] = {k: v - tb[key].get(k, 0) for k, v in value.items()} + if isinstance(value, dict): + totals[key] = {k: v - tb.get(key, {}).get(k, 0) + for k, v in value.items()} elif key == "worst_interval_ms": # A running maximum can't be differenced; it is reported as the # worst since the service started. totals[key] = value else: - totals[key] = value - tb[key] + totals[key] = value - tb.get(key, 0) histograms = {} for name in (after.get("histograms") or {}): hb, ha = _histogram(before, name), _histogram(after, name) @@ -143,6 +144,10 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]: "late_pct": round(100.0 * totals["late_frames"] / frames, 3) if frames 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), + "freeze_by": totals.get("freeze_by", {}), "freezes": totals["freezes"], "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None, "freeze_seconds": round(totals["freeze_seconds"], 2), @@ -178,9 +183,15 @@ def print_report(report: Dict[str, Any], limit: float) -> None: f" missed refreshes {report['missed_refreshes']}" f" [by 1: {late_by['1']}, 2: {late_by['2']}, " f"3-5: {late_by['3-5']}, 6+: {late_by['6+']}]") + if report["early_frames"]: + print(f"Early frames {report['early_frames']} " + f"({report['early_pct']}%) swaps returned a refresh early") print(f"Freezes >=250ms {report['freezes']}" f" ({report['freezes_per_hour']}/h, {report['freeze_seconds']}s total)" f" worst gap since start {report['worst_interval_ms'] or '-'} ms") + if report["freezes"]: + print(" by length: " + ", ".join( + f"{k}: {v}" for k, v in report["freeze_by"].items())) print() print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}") for name in ("blit", "wait", "work", "interval_per_hold"): @@ -190,12 +201,26 @@ def print_report(report: Dict[str, Any], limit: float) -> None: print() if report["late_pct"] is None: print("RESULT nothing scrolled - no verdict") + elif not locked(report, limit): + print(f"RESULT FAIL NOT LOCKED: {report['early_pct']}% of frames came a " + "refresh early, so the swaps were not waiting for the panel and " + "the late count means nothing") elif report["late_pct"] <= limit: print(f"RESULT PASS {report['late_pct']}% late <= {limit}%") else: print(f"RESULT FAIL {report['late_pct']}% late > {limit}%") +def locked(report: Dict[str, Any], limit: float) -> bool: + """Whether the loop was paced by the panel at all.""" + return (report.get("early_pct") or 0.0) <= limit + + +def passed(report: Dict[str, Any], limit: float) -> bool: + return (report["late_pct"] is not None and locked(report, limit) + and report["late_pct"] <= limit) + + def touch_marker() -> bool: try: with open(VIEWER_MARKER, "a"): @@ -302,7 +327,7 @@ def main(argv=None) -> int: json.dump(report, handle, indent=2) if report["late_pct"] is None: return 2 - return 0 if report["late_pct"] <= args.max_late_pct else 1 + return 0 if passed(report, args.max_late_pct) else 1 if __name__ == "__main__": diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 3743569b..c6d69689 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -28,14 +28,22 @@ An interval of ``FREEZE_SECONDS`` or more is a **freeze** instead -- a recompose, a plugin handover, a blocking call on the render thread. Those are counted separately, both because they are a different fault and because folding a single 400ms handover into the late count as "40 missed refreshes" -would drown the jitter the late count exists to measure. Intervals of -``GAP_SECONDS`` or more are not frames at all (one scroll ending, another -starting later) and are ignored. +would drown the jitter the late count exists to measure. ``freeze_by`` splits +them by length. Intervals of ``GAP_SECONDS`` or more are ignored as not being +frames of one scroll at all. + +A frame that arrives a whole refresh or more *early* means the swap did not +wait for the panel: the emulator, the fallback display, or a hold that was not +the one in effect. Those are counted as **early**, and a run with more than a +trace of them was not locked to the panel, so its late count means nothing. The refresh period is estimated from the frames themselves: swaps that block on vsync can only land on refresh boundaries, so the low end of interval / hold is the period. It is the smallest per-window 10th percentile -seen so far, over windows with enough frames to trust. +seen so far, over windows with enough frames to trust -- except that a window +cutting it by more than ``MAX_REFRESH_DROP`` is ignored. A panel's refresh does +not jump like that; swaps that stopped blocking do, and adopting their period +would make every early frame look on time. """ from __future__ import annotations @@ -62,7 +70,19 @@ BUCKET_COUNT = 256 #: See the module docstring. FREEZE_SECONDS = 0.25 -GAP_SECONDS = 1.0 + +#: Two frames that are both "scrolling" can be at most DisplayManager's +#: scroll_inactivity_threshold (2s) apart: after that the second is recorded +#: as static. This used to be 1s, which silently dropped every 1-2s stall +#: inside a scroll. It is now only a sanity bound. +GAP_SECONDS = 5.0 + +#: Buckets for freeze length, as cumulative counters a soak can difference. +FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"), + (float("inf"), "2s+")) + +#: A window may lower the refresh-period estimate by at most this fraction. +MAX_REFRESH_DROP = 0.2 #: A window needs this many scrolling frames before its refresh estimate is #: trusted -- about a second of scrolling. @@ -149,8 +169,10 @@ class FrameTimingRecorder: "late_frames": 0, "missed_refreshes": 0, "late_by": {"1": 0, "2": 0, "3-5": 0, "6+": 0}, + "early_frames": 0, "freezes": 0, "freeze_seconds": 0.0, + "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS}, "worst_interval_ms": 0.0, } self.histograms: Dict[str, Dict[int, int]] = { @@ -217,8 +239,10 @@ class FrameTimingRecorder: if interval < FREEZE_SECONDS) if len(per_hold) >= MIN_FRAMES_FOR_REFRESH: estimate = per_hold[len(per_hold) // 10] - if estimate > 0 and (self.refresh_period is None - or estimate < self.refresh_period): + current = self.refresh_period + if estimate > 0 and ( + current is None + or current * (1.0 - MAX_REFRESH_DROP) <= estimate < current): self.refresh_period = estimate period = self.refresh_period @@ -229,6 +253,9 @@ class FrameTimingRecorder: if interval >= FREEZE_SECONDS: totals["freezes"] += 1 totals["freeze_seconds"] += interval + label = next(name for limit, name in FREEZE_BUCKETS + if interval < limit) + totals["freeze_by"][label] += 1 continue totals["scroll_frames"] += 1 for name, value in (("blit", blit), ("wait", wait), @@ -245,6 +272,8 @@ class FrameTimingRecorder: key = ("1" if missed == 1 else "2" if missed == 2 else "3-5" if missed <= 5 else "6+") totals["late_by"][key] += 1 + elif missed <= -1: + totals["early_frames"] += 1 def snapshot(self) -> Dict[str, Any]: """The JSON document: cumulative since this process started.""" diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index 67703af1..700e2c5d 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -96,14 +96,42 @@ def test_static_frames_and_the_start_of_a_scroll_are_not_timed(tmp_path): def test_freezes_are_separate_from_late_frames_and_gaps_are_ignored(tmp_path): r = _recorder(tmp_path) intervals = [PERIOD] * 200 - intervals[80] = 0.400 # a recompose: freeze - intervals[150] = 3.0 # one scroll ended, another began later: ignored + intervals[80] = 0.400 # a render-thread plugin fetch: freeze + intervals[120] = 1.5 # a longer stall, still inside the scroll: freeze + intervals[150] = 6.0 # past any scroll's inactivity window: ignored _feed(r, intervals) totals = _aggregate(r) - assert totals["freezes"] == 1 - assert abs(totals["freeze_seconds"] - 0.4) < 1e-9 + assert totals["freezes"] == 2 + assert abs(totals["freeze_seconds"] - 1.9) < 1e-9 + assert totals["freeze_by"] == {"<0.5s": 1, "0.5-1s": 0, "1-2s": 1, "2s+": 0} + assert totals["late_frames"] == 0 + assert totals["scroll_frames"] == 197 + + +def test_a_stall_between_one_and_two_seconds_is_not_lost(tmp_path): + # Two "scrolling" frames can be up to DisplayManager's 2s inactivity + # threshold apart. The first version ignored everything past 1s, so a + # 1.4s render-thread stall vanished from the report. + r = _recorder(tmp_path) + intervals = [PERIOD] * 100 + intervals[40] = 1.4 + _feed(r, intervals) + assert _aggregate(r)["freezes"] == 1 + + +def test_early_frames_are_counted(tmp_path): + # Hold 2 on a 100Hz panel: frames are due every 20ms. A swap that returns + # after 10ms did not wait out the hold. + r = _recorder(tmp_path) + _feed(r, [2 * PERIOD] * 200, hold=2) + _aggregate(r) + intervals = [2 * PERIOD] * 200 + for i in range(0, 200, 20): + intervals[i] = PERIOD + _feed(r, intervals, hold=2, start=1000.0) + totals = _aggregate(r) + assert totals["early_frames"] == 10 assert totals["late_frames"] == 0 - assert totals["scroll_frames"] == 198 def test_refresh_estimate_survives_a_window_full_of_misses(tmp_path): @@ -151,6 +179,21 @@ def test_soak_report_is_the_difference_between_snapshots(tmp_path): assert report["timing_ms"]["interval_per_hold"]["max"] == 20.25 +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) + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [PERIOD] * 1000, hold=2, start=500.0) # never waited out the hold + _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["late_pct"] == 0.0 + assert report["early_pct"] == 100.0 + assert not frame_soak.passed(report, 0.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) From ac841f4583993535c1d6e79cb06c682167f1e7ba Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 08:56:49 -0400 Subject: [PATCH 3/8] docs(perf): hdpi soak results, main vs #628 Co-Authored-By: Claude Opus 5.5 --- docs/SCROLL_PERFORMANCE.md | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 05ce11ed..50044443 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -349,6 +349,31 @@ A soak is only meaningful against a fixed workload. Compare runs with the same content and `--preview` setting, and alternate which build goes first when you A/B two of them. A live-API workload drifts over time. +### Results: hdpi, 2026-09-24 + +Pi 4, 4×128×64 on one chain (512×64), `gpio_slowdown` 3, cap 120 Hz, the +GIL-releasing binding. Vegas mode with live content, 8-minute soaks with +`--preview`, run in the order shown so each build went both first and last. + +| run | build | pacing | pwm_bits | refresh | late | 1 | 2 | 3–5 | 6+ | freezes | +|---|---|---|---|---|---|---|---|---|---|---| +| 1 | main | time-based, blended, 90 px/s | 8 | 94.5 Hz | 6.33% | 2,542 | 74 | 19 | 4 | 0 | +| 2 | #628 | 1 px / refresh | 8 | 100.2 Hz | 0.66% | 238 | 32 | 30 | 5 | 2 | +| 3 | #628 | 1 px / refresh | 8 | 100.3 Hz | 0.70% | 252 | 38 | 26 | 6 | 2 | +| 4 | main | time-based, blended, 90 px/s | 8 | 94.5 Hz | 6.46% | 2,659 | 90 | 10 | 4 | 0 | +| 5 | #628 | 1 px / 2 refreshes (53 px/s) | **7** | 107.2 Hz | 0.32% | 68 | 7 | 4 | 2 | 1 | + +- Blending cost the panel refresh rate as well as frames: 94.5 Hz against + ~100 Hz for the same hardware under whole-pixel pacing. +- The freezes and the 3+ rows in the #628 runs line up with canvas-bound + plugins fetched on the render thread (`drain_deferred`): `news` took ~320 ms + and `hockey-scoreboard` ~660 ms there. Moving those + fetches off the render thread is proposed separately (offscreen rendering). +- Run 5 changed two things at once: the speed, and `pwm_bits` (changed on the + rig between runs). Its lower late rate cannot be credited to either alone. +- These soaks were taken before the recorder counted 1–2 s stalls as freezes, + so a stall of that length would be missing from these rows. + ## Rebuilding the binding ```bash From c883a2fd1e1cbf35b48287218c9d298e717a1dc7 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 10:58:27 -0400 Subject: [PATCH 4/8] feat(perf): a stall watchdog that logs what the render thread is waiting on The recorder counts freezes; it cannot say why. hdpi showed 1-2s freezes in both the #628 and offscreen builds, one lining up with hockey's 2s NHL fetch on the update thread, and nothing in the logs explained it. StallWatchdog polls every 50ms from its own thread. When a scroll's last frame is more than 250ms old (and a scroll is still running, so the end of a scroll is not a stall), it logs the stack of the thread that presented that frame and the top of every other thread's, then the stall's length when frames resume. It also measures how late its own wake-up was: if it was held up as long as the render thread, the whole interpreter was blocked (C code holding the GIL), not one thread on a lock. One dump per 30s at most; LEDMATRIX_STALL_WATCHDOG=0 disables it. Co-Authored-By: Claude Opus 5.5 --- src/common/frame_timing.py | 135 ++++++++++++++++++++++++++++++++++++- src/display_manager.py | 10 +++ test/test_frame_timing.py | 79 ++++++++++++++++++++++ 3 files changed, 223 insertions(+), 1 deletion(-) diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index c6d69689..9cd56e31 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -44,6 +44,17 @@ seen so far, over windows with enough frames to trust -- except that a window cutting it by more than ``MAX_REFRESH_DROP`` is ignored. A panel's refresh does not jump like that; swaps that stopped blocking do, and adopting their period would make every early frame look on time. + +Stall watchdog +-------------- +Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the +same frames from its own thread and, when a scroll's last frame is more than +``STALL_SECONDS`` old, logs the stack of the thread that presented it and the +top of every other thread's, so the log names what the render thread was +waiting on. It also measures how late its own wake-up was: if the watchdog was +held up as long as the render thread, the whole interpreter was blocked (C +code holding the GIL, or the process not scheduled), not one thread on a lock. +Set ``LEDMATRIX_STALL_WATCHDOG=0`` to turn it off. """ from __future__ import annotations @@ -56,7 +67,8 @@ import sys import tempfile import threading import time -from typing import Any, Dict, List, Optional, Tuple +import traceback +from typing import Any, Callable, Dict, List, Optional, Tuple logger = logging.getLogger(__name__) @@ -90,6 +102,14 @@ MIN_FRAMES_FOR_REFRESH = 90 FLUSH_INTERVAL = 10.0 +#: A scroll's last frame older than this is a stall worth a stack dump. +STALL_SECONDS = 0.25 +#: How often the watchdog looks. Also the resolution of its starvation check. +WATCHDOG_POLL_SECONDS = 0.05 +#: At most one stack dump per this many seconds: a stall that repeats every +#: extension would otherwise write the same stacks to the SD card all day. +STALL_LOG_INTERVAL = 30.0 + #: Written by the display service, read by scripts/frame_soak.py and anything #: else that wants the numbers. The web UI's viewer marker lives in /tmp; this #: goes to RAM where there is some, since it is rewritten all day. @@ -181,6 +201,15 @@ class FrameTimingRecorder: self._binding_gil: Optional[bool] = None self._binding_checked = False + # Read by the stall watchdog from its own thread: one tuple assignment, + # so it always sees a consistent (time, scrolling, thread) triple. + self.last_frame: Optional[Tuple[float, bool, int]] = None + #: Whether a scroll is running *now*, supplied by the display manager. + #: The last frame's flag alone would call the end of every scroll a + #: stall. + self.scrolling_now: Optional[Callable[[], bool]] = None + self.watchdog: Optional["StallWatchdog"] = None + # -- render thread ------------------------------------------------------ def record(self, blit: float, wait: float, hold: int, scrolling: bool, @@ -195,8 +224,13 @@ class FrameTimingRecorder: """ previous = self._previous self._previous = (presented_at, scrolling, hold) + self.last_frame = (presented_at, scrolling, threading.get_ident()) if not scrolling: self._static_frames += 1 + elif self.watchdog is None and self.scrolling_now is not None \ + and os.environ.get("LEDMATRIX_STALL_WATCHDOG", "1") != "0": + self.watchdog = StallWatchdog(self) + self.watchdog.start() elif previous is not None and previous[1]: interval = presented_at - previous[0] if interval < GAP_SECONDS: @@ -315,3 +349,102 @@ class FrameTimingRecorder: except OSError: pass raise + + +class StallWatchdog: + """Log what the render thread is doing when a scroll stops presenting. + + See the module docstring. Polls; never touches the render thread. + """ + + def __init__( + self, + recorder: FrameTimingRecorder, + threshold: float = STALL_SECONDS, + poll: float = WATCHDOG_POLL_SECONDS, + log_interval: float = STALL_LOG_INTERVAL, + clock: Callable[[], float] = time.perf_counter, + ): + self.recorder = recorder + self.threshold = threshold + self.poll = poll + self.log_interval = log_interval + self.clock = clock + self.stalls = 0 + self._last_dump: Optional[float] = None + self._thread: Optional[threading.Thread] = None + + def start(self) -> None: + self._thread = threading.Thread( + target=self._run, daemon=True, name="stall-watchdog") + self._thread.start() + + 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) + now = self.clock() + late = max(0.0, now - last_wake - self.poll) + last_wake = now + try: + stall_from, dumped = self.check(now, late, stall_from, dumped) + except Exception: # never let a diagnostic take anything down + logger.debug("Stall watchdog check failed", exc_info=True) + + def check(self, now: float, late: float, stall_from: Optional[float], + dumped: bool) -> Tuple[Optional[float], bool]: + """One look. Returns the updated (stall_from, dumped) state.""" + frame = self.recorder.last_frame + if frame is None: + return None, False + presented_at, scrolling, ident = frame + + if stall_from is not None and presented_at != stall_from: + # A frame arrived: the stall is over. + if dumped: + logger.warning( + "Render stall over: no frame for %.0fms", + (presented_at - stall_from) * 1000.0) + return None, False + + scrolling_now = self.recorder.scrolling_now + if stall_from is not None and (scrolling_now is None or not scrolling_now()): + # The scroll ended without another frame: nothing more to time. + return None, False + age = now - presented_at + if (stall_from is None and scrolling and age >= self.threshold + and scrolling_now is not None and scrolling_now()): + self.stalls += 1 + if self._last_dump is None or now - self._last_dump >= self.log_interval: + self._last_dump = now + logger.warning(self.describe(ident, age, late)) + return presented_at, True + return presented_at, False + return stall_from, dumped + + def describe(self, ident: int, age: float, late: float) -> str: + """The stack dump: the stalled thread in full, the rest in brief.""" + names = {t.ident: t.name for t in threading.enumerate()} + frames = sys._current_frames() + lines = [ + f"Render stall: no frame for {age * 1000.0:.0f}ms mid-scroll " + f"(watchdog woke {late * 1000.0:.0f}ms late" + + ("; the interpreter itself was blocked" if late >= age / 2 else "") + + ")", + f"-- {names.get(ident, ident)} (presents frames):", + ] + stalled = frames.get(ident) + if stalled is not None: + lines.extend(line.rstrip() for line in + traceback.format_stack(stalled, limit=12)) + for other, frame in frames.items(): + if other in (ident, threading.get_ident()): + continue + top = traceback.extract_stack(frame, limit=3) + where = " <- ".join( + f"{os.path.basename(f.filename)}:{f.lineno} {f.name}" + for f in reversed(top)) + lines.append(f"-- {names.get(other, other)}: {where}") + return "\n".join(lines) diff --git a/src/display_manager.py b/src/display_manager.py index 84079738..07ef642a 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -236,6 +236,7 @@ class DisplayManager: # Timing of every presented frame, whoever drew it, for # scripts/frame_soak.py. See src/common/frame_timing.py. self.frame_timing = FrameTimingRecorder(info=self._frame_timing_info()) + self.frame_timing.scrolling_now = self._scrolling_now self._scrolling_state = { 'is_scrolling': False, @@ -1459,6 +1460,15 @@ class DisplayManager: value = 0.0 return value if value > 0 else 100.0 + def _scrolling_now(self) -> bool: + """Whether a scroll is running, without is_currently_scrolling()'s + side effect of expiring the state -- safe from the stall watchdog's + thread.""" + state = self._scrolling_state + return bool(state['is_scrolling']) and ( + time.time() - state['last_scroll_activity'] + <= state['scroll_inactivity_threshold']) + def _frame_timing_info(self) -> Dict[str, Any]: """What the frame-timing stats were measured on, for the soak report.""" display = self.config.get('display') or {} diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index 700e2c5d..e45707c3 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -222,3 +222,82 @@ def test_display_manager_records_every_presented_frame(): dm.set_scrolling_state(False) DisplayManager._instance = None DisplayManager._initialized = False + + +# --- stall watchdog ---------------------------------------------------------- + +class _FakeRecorder: + def __init__(self): + self.last_frame = None + self.scrolling = True + self.scrolling_now = lambda: self.scrolling + + +def test_watchdog_reports_a_stall_once_and_its_end(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + ident = __import__("threading").get_ident() + rec.last_frame = (10.0, True, ident) + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + state = dog.check(10.1, 0.0, None, False) # 100ms: fine + assert state == (None, False) + state = dog.check(10.4, 0.0, *state) # 400ms: stall + assert state == (10.0, True) + state = dog.check(10.9, 0.0, *state) # still stalled: no repeat + rec.last_frame = (11.2, True, ident) + state = dog.check(11.25, 0.0, *state) # a frame arrived + assert state == (None, False) + messages = [r.getMessage() for r in caplog.records] + assert len(messages) == 2 + assert messages[0].startswith("Render stall: no frame for 400ms") + assert "test_watchdog_reports_a_stall_once_and_its_end" in messages[0] + assert messages[1] == "Render stall over: no frame for 1200ms" + assert dog.stalls == 1 + + +def test_watchdog_ignores_a_scroll_that_ended(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + rec.last_frame = (10.0, True, 1) + rec.scrolling = False # the scroll handed over + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + assert dog.check(12.0, 0.0, None, False) == (None, False) + assert not caplog.records + + +def test_watchdog_names_what_the_stalled_thread_is_waiting_on(): + import threading + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec) + blocked, release = threading.Event(), threading.Event() + + def render_loop_waiting_on_a_lock(): + blocked.set() + release.wait(5) + + t = threading.Thread(target=render_loop_waiting_on_a_lock, name="render") + t.start() + try: + assert blocked.wait(5) + text = dog.describe(t.ident, 1.5, 1.4) + finally: + release.set() + t.join(5) + assert "no frame for 1500ms" in text + assert "the interpreter itself was blocked" in text + assert "-- render (presents frames):" in text + assert "render_loop_waiting_on_a_lock" in text + + +def test_watchdog_rate_limits_its_dumps(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=30.0) + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + for start in (10.0, 20.0): # two stalls 10s apart + rec.last_frame = (start, True, 1) + state = dog.check(start + 0.5, 0.0, None, False) + rec.last_frame = (start + 0.6, True, 1) + dog.check(start + 0.65, 0.0, *state) + dumps = [r for r in caplog.records if r.getMessage().startswith("Render stall:")] + assert len(dumps) == 1 + assert dog.stalls == 2 From d56ec2ab3aa6ec064ee273315bcb9a27869e3e83 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Wed, 23 Sep 2026 22:05:15 -0400 Subject: [PATCH 5/8] feat(bench): measure a rig against the refresh it actually holds There was no way to answer "does this hardware present every frame on time?" other than watching the panel. `scripts/render_bench.py` drives the production path -- a real DisplayManager and ScrollHelper, configured through the same `scroll_config` resolver every ticker uses -- and grades the run with a new `src.common.frame_pacing`, exiting non-zero when more than 0.1% of frames slipped a refresh. Exit 2 when the run could not be set up at all, so a rig that was never measured cannot pass by accident. A missed frame is defined exactly: an interval that rounds up to at least one more refresh than its frame hold asked for. The half-refresh rounding boundary keeps a frame that ran 1ms long on a 10ms refresh out of the count, because it still presented on the refresh it was meant to. The verdict that matters more is NOT LOCKED. A loop that never blocked on vsync reports a perfect zero misses while presenting nothing -- 8ms frames on a 100Hz panel all land in the one-refresh bucket while running 25% too fast -- so the report also checks the typical frame is not shorter than the panel could physically present. That is what caught the first version of this benchmark announcing its scrolling state once instead of per frame: the state expires on an inactivity threshold, the dirty-tracking skip then fires mid-scroll, and the loop free-ran at 827fps. And the refresh is read back out of the frames rather than taken from an idle measurement. Driving the matrix is bit-banging on the same machine, so pushing frames slows the refresh: a Pi 4 on 512x64 measures 100.4Hz idle and holds 96.3Hz while scrolling. Both are real, and grading against the idle figure reports a locked loop as 4% slow -- or, once the gap passes half a refresh, as missing every frame. The gap between the two is itself worth watching: a rise in it is a render-cost regression even when nothing is missed. Measured on hdpi (Pi 4, 512x64, pwm_bits 8), two minutes each: plain 95.44 fps, 8 missed of 11,449 (0.070%) PASS --busy 2 95.41 fps, 3 missed of 11,445 (0.026%) PASS Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_014RRtqXDCnvnY6EQwhT5CV9 --- CHANGELOG.md | 11 ++ docs/SCROLL_PERFORMANCE.md | 108 +++++++++++ scripts/render_bench.py | 371 +++++++++++++++++++++++++++++++++++++ scripts/scroll_speeds.py | 19 +- src/common/__init__.py | 6 +- src/common/frame_pacing.py | 331 +++++++++++++++++++++++++++++++++ test/test_frame_pacing.py | 251 +++++++++++++++++++++++++ 7 files changed, 1083 insertions(+), 14 deletions(-) create mode 100755 scripts/render_bench.py create mode 100644 src/common/frame_pacing.py create mode 100644 test/test_frame_pacing.py diff --git a/CHANGELOG.md b/CHANGELOG.md index f136d44a..54b80985 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,17 @@ accepts both, but the store flags the old spelling as deprecated ## Unreleased +- `src.common.frame_pacing` — grades a run of presented frames against the + panel's real refresh rate: how many slipped a whole refresh, and whether the + loop was locked to the panel at all. `scripts/render_bench.py` drives a real + `DisplayManager`/`ScrollHelper` scroll through it and exits non-zero when a + rig misses more than 0.1% of frames, so a rig can be measured before a + release rather than eyeballed. The panel's refresh is read back out of the + frames rather than taken from the idle measurement: a Pi 4 driving 512x64 + holds 100.4Hz idle and 96.3Hz while rendering, and grading against the idle + figure reports misses a perfectly locked loop never had. See + `docs/SCROLL_PERFORMANCE.md`, "Measuring a rig". + - `FontManager.get_font()` returns a BDF font at its native size when asked for a size the file doesn't contain (5x7.bdf at 8 or 10px, say). It used to return PIL's default font, a different typeface, so a plugin that relied on diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 50044443..f379b5fc 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -374,6 +374,114 @@ GIL-releasing binding. Vegas mode with live content, 8-minute soaks with - These soaks were taken before the recorder counted 1–2 s stalls as freezes, so a stall of that length would be missing from these rows. +## Measuring a rig + +The journal lines above tell you how one scroller behaved while everything else +was also happening. `scripts/render_bench.py` answers the narrower question a +release has to answer per rig: *with nothing else in the way, can this hardware +present every frame on time?* It drives the production path -- a real +`DisplayManager`, a real `ScrollHelper`, the same `scroll_config` resolver every +ticker uses -- so a regression in any of them shows up here. + +```bash +sudo systemctl stop ledmatrix # the service owns the GPIO + +sudo python3 scripts/render_bench.py # 60s at one pixel per refresh +sudo python3 scripts/render_bench.py --seconds 600 # the shipping gate +sudo python3 scripts/render_bench.py --speed 50 # a held (frame_hold 2) speed +sudo python3 scripts/render_bench.py --busy 2 # with threads imitating plugin updates +sudo python3 scripts/render_bench.py --json /tmp/pi4-512x64.json + +sudo systemctl start ledmatrix +``` + +It never starts or stops the service itself, for the same reason +`scroll_speeds.py` does not: a crash in a script must not be able to leave the +panel dark. Exit status is 0 for a pass, 1 for a fail, and **2 when the run +could not be set up at all** -- no root, no panel, a fallback display -- so a +rig that was never measured can never be mistaken for one that passed. + +### Reading the report + +A two-minute run on a Pi 4 driving 512x64 at `pwm_bits` 8: + +``` +measuring the panel for 4s... +panel refreshes at 100.4Hz (cap is 120Hz) +asked for 100.4 px/s -> 100.4 px/s (1px every 1 refresh = 100.4 fps, smooth) +scrolling 512x64 for 120s ... + +panel held 96.3Hz while rendering (4.1% below its 100.4Hz idle rate) + 95.44 fps presented over 11449 frames in 120.0s (expected 96.30 fps = 1 refresh of 96.3Hz) + frame time median 10.46ms p95 10.55ms p99 11.10ms max 22.16ms min 7.36ms (target 10.38ms) + missed 8 (0.070%) gate 0.100% + refreshes 1x:11441 2x:8 + PASS + restarts 5 (the strip was scrolled through 5 times) +``` + +The same rig with `--busy 2` -- two threads parsing JSON, resizing images and +compressing bytes throughout, to imitate plugins updating -- held the same +95.4 fps and missed 3 frames in 11,445 (0.026%). Competing for the GIL did not +cost this loop its pacing. + +A **missed** frame is one whose interval rounds up to at least one more refresh +than its frame hold asked for: the panel showed the previous frame again. The +half-refresh rounding boundary is deliberate -- a frame 1 ms late on a 10 ms +refresh still presented on the refresh it was meant to, and counting it would +fail every rig for nothing. + +**NOT LOCKED** is the verdict that matters more than the miss count. A loop +that never blocked on vsync -- an emulator, a fallback display, or the +dirty-tracking skip firing mid-scroll -- can report a beautiful zero misses +while presenting nothing at all. The check is that the typical frame is not +*shorter* than the panel could physically present, which a bucket count alone +cannot see: 8 ms frames on a 100 Hz panel all land in the one-refresh bucket +while running 25% too fast. A run that is not locked always fails. + +### The panel is slower while you are rendering into it + +The benchmark measures the refresh **twice**, and the two numbers differ: + +| | Pi 4, 512x64, `pwm_bits` 8 | +|---|---| +| idle, timing bare swaps | 100.4 Hz | +| while scrolling | 96.3 Hz | + +Both are real. Driving an LED matrix is bit-banging on the same machine, so +`SetImage` over a 512x64 chain contends with the refresh itself and slows it. +Grading a soak against the idle number reports 96.3 fps against an expected +100.4 and looks broken; once the gap passes half a refresh period, every single +frame is counted as a miss. The give-away that nothing is actually being missed +is that the intervals cluster tightly around 10.46 ms instead of splitting +between 9.96 ms and 19.92 ms, which is what missing every twenty-fifth vsync +would look like. + +So `frame_pacing.refresh_from_intervals()` reads the period back out of the +frames -- swaps that block on vsync can only return on a refresh boundary, so +the low end of `interval / frame_hold` *is* the period -- and the run is graded +against that. The idle figure is still printed, because the gap between the two +is itself the measure of how expensive a frame is: **a rise in that gap is a +render-cost regression even when the miss count stays at zero.** + +The practical consequence for config: set `limit_refresh_rate_hz` near the rate +the panel holds *while rendering*, not the idle rate and certainly not a cap it +can never reach. A cap well above the real rate makes `scroll_config` solve +speeds against a refresh that does not exist, which is where "3px every 4 +refreshes" comes from. + +### Other counters + +| line | meaning | +|---|---| +| `duplicate` | frames that advanced no pixels. A crisp fixed-step scroll should show none; any at all means the loop is presenting faster than the strip is moving. | +| `blank` | frames with no visible slice to draw -- the helper had no content. Should be zero. | +| `restarts` | how many times the strip was scrolled through end to end. Informational: the benchmark restarts the strip where a plugin would hand over to the next one. | + +`--json` writes all of it, plus the panel geometry and the speed that was +solved, so two rigs (or one rig before and after a change) can be compared +without re-reading a terminal. + ## Rebuilding the binding ```bash diff --git a/scripts/render_bench.py b/scripts/render_bench.py new file mode 100755 index 00000000..4bfffa91 --- /dev/null +++ b/scripts/render_bench.py @@ -0,0 +1,371 @@ +#!/usr/bin/env python3 +"""Benchmark the render loop against the panel's real refresh rate. + +The question this answers is the one that decides whether a rig ships: *does +every frame present on the refresh it was meant to?* It drives the production +path -- a real ``DisplayManager`` and ``ScrollHelper``, the same crisp speed +resolver every ticker uses -- scrolls for a while, and grades the result with +``src.common.frame_pacing``. A run passes when the loop was genuinely locked to +the panel and fewer than ``--max-missed`` percent of frames slipped a refresh. + + # stop the service first; it owns the GPIO + sudo systemctl stop ledmatrix + + sudo python3 scripts/render_bench.py # 60s, default speed + sudo python3 scripts/render_bench.py --seconds 600 # the 10-minute gate + sudo python3 scripts/render_bench.py --speed 50 # a slower, held speed + sudo python3 scripts/render_bench.py --busy 2 # with background load + sudo python3 scripts/render_bench.py --json /tmp/pi4.json + + sudo systemctl start ledmatrix + +Like scripts/scroll_speeds.py, this never starts or stops the service itself, +so a crash here can never leave the panel dark. + +Exit status is 0 when the run clears the gate, 1 when it does not, and 2 when +the run could not be set up (no hardware, no root, unusable config) -- so a rig +that cannot be measured is never mistaken for a rig that passed. +""" +from __future__ import annotations + +import argparse +import json +import logging +import os +import sys +import threading +import time +import zlib +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common import frame_pacing, scroll_config # noqa: E402 + +REPO = Path(__file__).resolve().parent.parent +CONFIG = REPO / "config" / "config.json" + +#: Long enough to average out a scheduler hiccup, short enough that nobody +#: skips running it. The shipping gate is --seconds 600. +DEFAULT_SECONDS = 60.0 + +#: Seconds spent timing bare swaps before the scroll starts. The measurement +#: has to settle, but every second here is a second not scrolling. +MEASURE_SECONDS = 4.0 + + +def load_config() -> dict: + """The config the display service would run with.""" + try: + from src.config_manager import ConfigManager + + config = ConfigManager().config + if isinstance(config, dict) and config: + return config + except Exception: + pass + # ConfigManager pulls in a lot; a plain read is enough to drive the panel + # and keeps the benchmark usable on a half-installed machine. + try: + with open(CONFIG, encoding="utf-8") as handle: + config = json.load(handle) + except (OSError, ValueError) as exc: + sys.exit(f"could not read {CONFIG}: {exc}") + if not isinstance(config, dict): + sys.exit(f"{CONFIG} is not a config object") + return config + + +def build_strip(width: int, height: int, label: str): + """A marquee strip a few screens wide, with text and colour. + + Deliberately not plain white text on black: how long ``SetImage`` takes + depends on how many subpixels are lit, so a strip that is mostly dark + flatters the panel and hides exactly the regression this benchmark exists + to catch. + """ + from PIL import Image, ImageDraw, ImageFont + + from src.common.font_layout import load_truetype + + font = None + for path, size in ( + (str(REPO / "assets/fonts/PressStart2P-Regular.ttf"), max(8, height // 4)), + ("/usr/share/fonts/truetype/dejavu/DejaVuSansMono-Bold.ttf", max(10, height // 2)), + ): + try: + font = load_truetype(path, size) + break + except OSError: + continue + if font is None: + font = ImageFont.load_default() + + text = f" {label} *** THE QUICK BROWN FOX JUMPS OVER THE LAZY DOG *** " + probe = ImageDraw.Draw(Image.new("RGB", (8, 8))) + box = probe.textbbox((0, 0), text, font=font) + text_width = max(1, box[2] - box[0]) + text_height = box[3] - box[1] + + reps = max(2, (width * 4) // text_width + 1) + strip = Image.new("RGB", (text_width * reps, height), (0, 0, 0)) + draw = ImageDraw.Draw(strip) + draw.fontmode = "1" # the panel has no partial brightness; see DisplayManager + palette = [(255, 210, 60), (80, 200, 255), (255, 90, 90), (140, 255, 140)] + for i in range(reps): + left = i * text_width + # A filled block per repeat, so a meaningful share of the strip is lit. + draw.rectangle( + [left + 4, height - 4, left + text_width - 4, height - 2], + fill=palette[i % len(palette)], + ) + draw.text((left, (height - text_height) // 2 - box[1]), text, + font=font, fill=palette[(i + 1) % len(palette)]) + return strip + + +class BackgroundLoad: + """Threads that imitate plugins updating while the panel scrolls. + + Not a simulation of any particular plugin -- it is the shape of the work + that competes with the render loop for the GIL: decoding JSON, resizing an + image, compressing bytes. A render loop that only holds its pacing on an + idle machine is not shippable, and this is how that shows up. + """ + + def __init__(self, workers: int) -> None: + self.workers = max(0, workers) + self._stop = threading.Event() + self._threads: list = [] + + def __enter__(self) -> "BackgroundLoad": + for index in range(self.workers): + thread = threading.Thread( + target=self._run, args=(index,), name=f"bench-load-{index}", daemon=True) + thread.start() + self._threads.append(thread) + return self + + def __exit__(self, *exc_info) -> None: + self._stop.set() + for thread in self._threads: + thread.join(timeout=2.0) + + def _run(self, index: int) -> None: + from PIL import Image + + payload = json.dumps({"games": [{"id": n, "score": [n, n + 1], + "name": f"team {n}"} for n in range(200)]}) + image = Image.new("RGB", (256, 64), (12, 34, 56)) + while not self._stop.wait(0.25 + 0.05 * index): + json.loads(payload) + image.resize((128, 32), Image.LANCZOS) + zlib.compress(image.tobytes(), 1) + + +def main(argv=None) -> int: + parser = argparse.ArgumentParser( + description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("--seconds", type=float, default=DEFAULT_SECONDS, + help=f"how long to scroll for (default {DEFAULT_SECONDS:.0f}; " + "the shipping gate is 600)") + parser.add_argument("--speed", type=float, default=None, + help="requested px/s; snapped to the nearest speed the " + "panel can show in whole pixels (default: one pixel " + "per refresh)") + parser.add_argument("--hz", type=float, default=None, + help="skip the measurement and grade against this refresh " + "rate instead (for reproducing a rig's numbers)") + parser.add_argument("--busy", type=int, default=0, metavar="N", + help="run N background workers imitating plugin updates") + parser.add_argument("--max-missed", type=float, + default=frame_pacing.DEFAULT_MAX_MISSED_PERCENT, + metavar="PCT", + help="percent of frames allowed to slip a refresh " + f"(default {frame_pacing.DEFAULT_MAX_MISSED_PERCENT})") + parser.add_argument("--json", dest="json_path", default=None, metavar="PATH", + help="also write the report as JSON, for comparing rigs") + parser.add_argument("--label", default=None, + help="name for this run in the JSON report (default: hostname)") + args = parser.parse_args(argv) + + # Everything the display service logs would otherwise land in the middle of + # the report; the benchmark's own output is the point. + logging.basicConfig(level=logging.ERROR, stream=sys.stderr) + + if hasattr(os, "geteuid") and os.geteuid() != 0: + print("this needs root for GPIO access - rerun with sudo", file=sys.stderr) + return 2 + + config = load_config() + + from src.common.scroll_helper import ScrollHelper + from src.display_manager import DisplayManager + + try: + display = DisplayManager(config, suppress_test_pattern=True) + except Exception as exc: + print(f"could not open the display ({exc}).\n" + "If the display service is running it owns the GPIO - stop it " + "first:\n sudo systemctl stop ledmatrix", file=sys.stderr) + return 2 + + if getattr(display, "matrix", None) is None: + print("the display came up in fallback mode - there is no panel here to " + "measure, and a software loop's frame times say nothing about " + "vsync. Run this on a rig.", file=sys.stderr) + return 2 + + width, height = display.width, display.height + + if args.hz is not None: + refresh_hz = float(args.hz) + print(f"grading against {refresh_hz:.1f}Hz (given, not measured)") + else: + print(f"measuring the panel for {MEASURE_SECONDS:.0f}s...", flush=True) + refresh_hz = frame_pacing.measure_refresh_hz(display.matrix, MEASURE_SECONDS) + if refresh_hz <= 0: + print("the panel did not answer a swap; cannot measure it", + file=sys.stderr) + return 2 + cap = scroll_config.refresh_hz_from_config(config) + note = (f" (cap is {cap:.0f}Hz)" if refresh_hz < cap * 0.98 + else " (at its configured cap)") + print(f"panel refreshes at {refresh_hz:.1f}Hz{note}") + + requested = args.speed if args.speed else refresh_hz + + # Configured through the shared resolver rather than by setting the helper + # up by hand, so the benchmark measures the engine every ticker runs on. A + # speed the bench reached some other way would be measuring something no + # plugin does. + helper = ScrollHelper(width, height) + settings = scroll_config.configure( + helper, + plugin_config={"scroll_pixels_per_second": requested}, + global_config=config, + refresh_hz=refresh_hz, + display_manager=display, + ) + choice = settings.crisp + if choice is None: + print("the resolver did not snap to a whole-pixel speed; nothing to " + "grade against", file=sys.stderr) + return 2 + print(f"asked for {requested:.1f} px/s -> {choice.describe()}") + + helper.set_sub_pixel_scrolling(False) + helper.set_scrolling_image( + build_strip(width, height, f"{choice.pixels_per_second:.0f} px/s")) + + print(f"scrolling {width}x{height} for {args.seconds:.0f}s" + + (f" with {args.busy} background worker(s)" if args.busy else "") + + " ...", flush=True) + + intervals: list = [] + duplicates = 0 + blanks = 0 + restarts = 0 + last_column = None + started = time.perf_counter() + previous = None + try: + with BackgroundLoad(args.busy): + while time.perf_counter() - started < args.seconds: + helper.update_scroll_position() + if helper.is_scroll_complete(): + # The helper parks at the end of the strip and stops + # advancing, exactly as it does under a plugin -- which + # then hands over to the next one. Here there is nothing + # to hand over to, so start the strip again. Without this + # the benchmark measures a still image for the rest of the + # run and reports a smoothness it never demonstrated. + helper.reset_scroll() + restarts += 1 + visible = helper.get_visible_portion() + column = int(helper.scroll_position) + if column == last_column: + duplicates += 1 + last_column = column + if visible is None: + blanks += 1 + else: + display.image.paste(visible, (0, 0)) + # Every frame, not once before the loop. The scrolling state + # expires on its own inactivity threshold and takes the frame + # hold with it, so a scroll that announces itself once is + # presented at the wrong rate for all but its first moments -- + # and its unchanged frames start taking the dirty-tracking + # skip, which returns without waiting for the panel at all. + # Every ticker re-announces per frame; so does this. + display.set_scrolling_state(True, frame_hold=choice.frame_hold) + display.update_display() + now = time.perf_counter() + if previous is not None: + intervals.append(now - previous) + previous = now + except KeyboardInterrupt: + print("\ninterrupted - reporting what was measured so far") + finally: + elapsed = time.perf_counter() - started + display.set_scrolling_state(False) + try: + display.clear() + except Exception: + pass + + # The panel does not refresh at its idle rate while the Pi is also pushing + # frames into it; see frame_pacing.refresh_from_intervals. Grading against + # the idle number reports misses a locked loop never had, so the rate the + # panel actually held during the scroll is read back from the frames. + idle_hz = refresh_hz + loaded_hz = frame_pacing.refresh_from_intervals(intervals, choice.frame_hold) + graded_hz = loaded_hz if 0 < loaded_hz <= idle_hz * 1.02 else idle_hz + + report = frame_pacing.analyze(intervals, graded_hz, choice.frame_hold, + seconds=elapsed) + print() + if loaded_hz > 0: + drop = 100.0 * (idle_hz - loaded_hz) / idle_hz + print(f"panel held {loaded_hz:.1f}Hz while rendering " + f"({drop:.1f}% below its {idle_hz:.1f}Hz idle rate)") + print(report.describe(args.max_missed)) + if duplicates: + # A frame that shows the same columns as the one before it is work the + # panel did not need. It is not a miss -- the frame arrived on time -- + # but it means the loop is presenting faster than the strip is moving. + print(f" duplicate {duplicates} frames advanced no pixels " + f"({100.0 * duplicates / max(1, len(intervals)):.2f}%)") + if blanks: + print(f" blank {blanks} frames had no visible slice to draw") + if restarts: + print(f" restarts {restarts} (the strip was scrolled through " + f"{restarts} time{'s' if restarts != 1 else ''})") + + if args.json_path: + payload = report.as_dict() + payload.update({ + "label": args.label or os.uname().nodename, + "width": width, + "height": height, + "requested_pixels_per_second": requested, + "pixels_per_second": choice.pixels_per_second, + "pixels_per_frame": choice.pixels_per_frame, + "busy_workers": args.busy, + "duplicate_frames": duplicates, + "blank_frames": blanks, + "strip_restarts": restarts, + "idle_refresh_hz": idle_hz, + "loaded_refresh_hz": loaded_hz, + "max_missed_percent": args.max_missed, + "passed": report.passed(args.max_missed), + }) + Path(args.json_path).write_text(json.dumps(payload, indent=2) + "\n", + encoding="utf-8") + print(f"\nwrote {args.json_path}") + + return 0 if report.passed(args.max_missed) else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/scroll_speeds.py b/scripts/scroll_speeds.py index bdabf023..2a6f2916 100644 --- a/scripts/scroll_speeds.py +++ b/scripts/scroll_speeds.py @@ -42,7 +42,7 @@ from pathlib import Path sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) -from src.common import scroll_config # noqa: E402 +from src.common import frame_pacing, scroll_config # noqa: E402 CONFIG = Path(__file__).resolve().parent.parent / "config" / "config.json" @@ -99,20 +99,13 @@ def open_matrix(config, refresh_override=None): def measure_refresh(config, seconds=6.0): """Actual refresh rate, by running uncapped and timing the swaps. - SwapOnVSync blocks until the panel's next refresh, so an unthrottled loop - runs at exactly the panel's rate. This is what an older Pi or a longer - chain will really give you, as opposed to whatever limit_refresh_rate_hz - optimistically asks for. + What an older Pi or a longer chain will really give you, as opposed to + whatever limit_refresh_rate_hz optimistically asks for. The timing loop + itself lives in src.common.frame_pacing so the benchmark grades a soak + against the same measurement this ladder is built from. """ matrix = open_matrix(config, refresh_override=0) - canvas = matrix.CreateFrameCanvas() - canvas = matrix.SwapOnVSync(canvas) # discard the first, it includes setup - frames = 0 - started = time.perf_counter() - while time.perf_counter() - started < seconds: - canvas = matrix.SwapOnVSync(canvas) - frames += 1 - measured = frames / (time.perf_counter() - started) + measured = frame_pacing.measure_refresh_hz(matrix, seconds) matrix.Clear() return measured diff --git a/src/common/__init__.py b/src/common/__init__.py index 9b3a8925..2454265e 100644 --- a/src/common/__init__.py +++ b/src/common/__init__.py @@ -11,13 +11,14 @@ This package provides reusable functionality for plugins and core modules: # Export commonly used utilities from src.common.api_helper import APIHelper from src.common.scroll_helper import ScrollHelper -from src.common import scroll_config +from src.common import frame_pacing, scroll_config from src.common.scroll_config import ( ScrollSettings, configure as configure_scroll, resolve as resolve_scroll_settings, refresh_hz_from_config, ) +from src.common.frame_pacing import PacingReport, analyze as analyze_frame_pacing from src.common.logo_helper import LogoHelper from src.common.text_helper import TextHelper @@ -50,6 +51,9 @@ __all__ = [ 'APIHelper', 'ScrollHelper', 'scroll_config', + 'frame_pacing', + 'PacingReport', + 'analyze_frame_pacing', 'ScrollSettings', 'configure_scroll', 'resolve_scroll_settings', diff --git a/src/common/frame_pacing.py b/src/common/frame_pacing.py new file mode 100644 index 00000000..822c9495 --- /dev/null +++ b/src/common/frame_pacing.py @@ -0,0 +1,331 @@ +"""Judge a run of presented frames against the panel's real refresh. + +The rule the display obeys is in docs/SCROLL_PERFORMANCE.md: motion is smooth +when the strip advances a whole number of pixels per panel refresh, with each +frame held for a whole number of refreshes. That makes "is this scroll smooth?" +a question with an exact answer rather than a matter of taste -- + + every presented frame should last ``frame_hold / refresh_hz`` seconds + +-- and it makes a *missed* frame exactly one thing: an interval long enough to +round up to at least one more refresh than the hold asked for. That is a +dropped vsync, and it is what the eye reads as a hitch. + +This module is only the arithmetic. It takes a list of intervals between +successive panel pushes (seconds, as ``time.perf_counter`` deltas) and reports +how many of them slipped. Nothing here touches hardware, so the thresholds a +soak is graded against are testable on any machine; ``scripts/render_bench.py`` +is the driver that collects the intervals on a real panel. + +Two failure modes are counted separately, because they mean opposite things: + +* **missed** -- the interval is at least one refresh longer than it should be. + Something (a slow ``SetImage``, a plugin fetch, the preview encoder, the GIL) + held the render loop past the panel's deadline. +* **early** -- the interval is at least one refresh *shorter* than it should be. + The swap returned without waiting, so the frame was never presented as a + distinct image. A run with early frames is not measuring a vsync-locked loop + at all, and its missed-frame percentage means nothing; the driver says so + rather than reporting a flattering number. +""" + +from __future__ import annotations + +import math +import time +from dataclasses import dataclass, field +from typing import Any, Dict, List, Optional, Sequence + +#: The ship gate from the rendering goal: under a tenth of a percent of frames +#: may miss a refresh over a soak. +DEFAULT_MAX_MISSED_PERCENT = 0.1 + +#: How far an interval may sit from its target before it counts as a different +#: number of refreshes. Half a refresh period is the rounding boundary, so this +#: is not a tunable fudge factor -- it is where "held for N refreshes" stops +#: being the nearest whole answer and "N+1" starts. +_ROUNDING = 0.5 + +#: How far the typical frame may fall short of its target period before the run +#: is judged not to have been paced by the panel at all. A vsync-locked loop +#: physically cannot present faster than ``refresh_hz / frame_hold``, so a +#: median below that means the swaps were not blocking -- the emulator, the +#: fallback display, or hardware that returned early. The margin only covers +#: error in the measured refresh rate itself. +_LOCK_TOLERANCE = 0.05 + + +def _percentile(sorted_values: Sequence[float], fraction: float) -> float: + """Nearest-rank percentile, as ``scroll_helper.frame_stats`` does for p95.""" + if not sorted_values: + return 0.0 + rank = max(0, math.ceil(fraction * len(sorted_values)) - 1) + return sorted_values[min(rank, len(sorted_values) - 1)] + + +@dataclass(frozen=True) +class PacingReport: + """What a run of frame intervals says about the loop that produced it.""" + + #: Intervals measured. One fewer than the frames pushed: the first push has + #: no predecessor to time against. + frames: int + seconds: float + refresh_hz: float + frame_hold: int + presented_fps: float + expected_fps: float + median: float + p95: float + p99: float + maximum: float + minimum: float + missed: int + early: int + #: How many refreshes each frame actually lasted, rounded, as + #: ``{refreshes: count}``. A vsync-locked loop puts nearly everything on + #: ``frame_hold``; a spread across several buckets is judder even when the + #: average fps looks right. + histogram: Dict[int, int] = field(default_factory=dict) + + @property + def expected_period(self) -> float: + """Seconds a correctly paced frame lasts.""" + return self.frame_hold / self.refresh_hz if self.refresh_hz > 0 else 0.0 + + @property + def missed_percent(self) -> float: + return 100.0 * self.missed / self.frames if self.frames else 0.0 + + @property + def early_percent(self) -> float: + return 100.0 * self.early / self.frames if self.frames else 0.0 + + @property + def locked(self) -> bool: + """True when the loop really was paced by the panel. + + Every frame landing on some whole number of refreshes is not enough -- + a loop that free-runs at half the refresh also does that. Two things + have to hold: the hold asked for is the hold observed, and the typical + frame is not *shorter* than the panel could possibly present. The + second is what catches a swap that returned without blocking, which a + whole-refresh bucket count cannot see -- 8ms frames on a 100Hz panel + all land in the 1-refresh bucket while running 25% too fast. + """ + if not self.frames: + return False + modal = max(self.histogram, key=lambda k: self.histogram[k]) + if modal != self.frame_hold or self.early: + return False + return self.median >= self.expected_period * (1.0 - _LOCK_TOLERANCE) + + def passed(self, max_missed_percent: float = DEFAULT_MAX_MISSED_PERCENT) -> bool: + """Whether this run clears the gate. An unlocked run never does.""" + return self.locked and self.missed_percent <= max_missed_percent + + def as_dict(self) -> Dict[str, Any]: + """JSON-safe form, for a soak that writes its result to a file.""" + return { + "frames": self.frames, + "seconds": self.seconds, + "refresh_hz": self.refresh_hz, + "frame_hold": self.frame_hold, + "expected_period_ms": self.expected_period * 1000.0, + "presented_fps": self.presented_fps, + "expected_fps": self.expected_fps, + "median_ms": self.median * 1000.0, + "p95_ms": self.p95 * 1000.0, + "p99_ms": self.p99 * 1000.0, + "max_ms": self.maximum * 1000.0, + "min_ms": self.minimum * 1000.0, + "missed": self.missed, + "missed_percent": self.missed_percent, + "early": self.early, + "early_percent": self.early_percent, + "locked": self.locked, + "histogram": {str(k): v for k, v in sorted(self.histogram.items())}, + } + + def describe(self, max_missed_percent: float = DEFAULT_MAX_MISSED_PERCENT) -> str: + """The human report: several lines, no trailing newline.""" + if not self.frames: + return "no frames measured" + lines = [ + f"{self.presented_fps:6.2f} fps presented over {self.frames} frames " + f"in {self.seconds:.1f}s " + f"(expected {self.expected_fps:.2f} fps = " + f"{self.frame_hold} refresh{'es' if self.frame_hold != 1 else ''} " + f"of {self.refresh_hz:.1f}Hz)", + f" frame time median {self.median * 1000:6.2f}ms " + f"p95 {self.p95 * 1000:6.2f}ms p99 {self.p99 * 1000:6.2f}ms " + f"max {self.maximum * 1000:6.2f}ms min {self.minimum * 1000:6.2f}ms " + f"(target {self.expected_period * 1000:.2f}ms)", + f" missed {self.missed} ({self.missed_percent:.3f}%) " + f"gate {max_missed_percent:.3f}%", + ] + if self.early: + lines.append( + f" early {self.early} ({self.early_percent:.3f}%) " + "- swaps returned a whole refresh early" + ) + buckets = " ".join( + f"{refreshes}x:{count}" for refreshes, count in sorted(self.histogram.items()) + ) + lines.append(f" refreshes {buckets}") + if not self.locked: + lines.append( + " NOT LOCKED - the loop was not paced by the panel, so the " + "missed count above means nothing. Either the swap did not " + "block (emulator or fallback display) or the frame hold in " + "effect was not the one this run was graded against." + ) + verdict = "PASS" if self.passed(max_missed_percent) else "FAIL" + lines.append(f" {verdict}") + return "\n".join(lines) + + +def analyze( + intervals: Sequence[float], + refresh_hz: float, + frame_hold: int = 1, + seconds: Optional[float] = None, +) -> PacingReport: + """Grade a list of frame intervals against a panel refresh. + + :param intervals: seconds between successive panel pushes. + :param refresh_hz: the panel's *measured* refresh, not its configured cap. + Grading against a cap the panel cannot reach reports misses that are + really just the panel being slower than asked -- which is why + ``render_bench`` measures first and passes the result in here. + :param frame_hold: refreshes each frame was held for (``SwapOnVSync``'s + ``framerate_fraction``), so the target period is ``hold / refresh_hz``. + :param seconds: wall time the run covered. Defaults to the sum of the + intervals, which is the same thing for a contiguous run. + """ + samples: List[float] = [float(i) for i in intervals if i is not None and i > 0] + hold = max(1, int(frame_hold)) + hz = float(refresh_hz) + if not samples or hz <= 0: + return PacingReport( + frames=0, seconds=float(seconds or 0.0), refresh_hz=max(0.0, hz), + frame_hold=hold, presented_fps=0.0, expected_fps=0.0, + median=0.0, p95=0.0, p99=0.0, maximum=0.0, minimum=0.0, + missed=0, early=0, histogram={}, + ) + + refresh_period = 1.0 / hz + ordered = sorted(samples) + total = float(seconds) if seconds is not None else sum(samples) + mean = sum(samples) / len(samples) + + histogram: Dict[int, int] = {} + missed = 0 + early = 0 + for interval in samples: + # How many refreshes this frame actually occupied. Rounding at the + # halfway point is what makes a "miss" a whole dropped vsync rather + # than any interval that ran a little long -- a frame 1ms late on a + # 10ms refresh still presented on the refresh it was meant to. + refreshes = max(1, int(math.floor(interval / refresh_period + _ROUNDING))) + histogram[refreshes] = histogram.get(refreshes, 0) + 1 + if refreshes > hold: + missed += 1 + elif refreshes < hold: + early += 1 + + return PacingReport( + frames=len(samples), + seconds=total, + refresh_hz=hz, + frame_hold=hold, + presented_fps=(1.0 / mean) if mean > 0 else 0.0, + expected_fps=hz / hold, + median=_percentile(ordered, 0.5), + p95=_percentile(ordered, 0.95), + p99=_percentile(ordered, 0.99), + maximum=ordered[-1], + minimum=ordered[0], + missed=missed, + early=early, + histogram=histogram, + ) + + +def measure_refresh_hz(matrix: Any, seconds: float = 4.0) -> float: + """The panel's real refresh rate, by timing unthrottled swaps. + + ``SwapOnVSync`` blocks until the panel's next refresh, so a loop that does + nothing else runs at exactly the panel's rate. This is the number every + pacing decision has to be made against: ``limit_refresh_rate_hz`` is a + *cap*, and a long chain, a high ``pwm_bits`` or an older Pi will sit well + under it. Solving scroll speeds against a cap the panel cannot reach is + what produces "3px every 4 refreshes" and the judder that comes with it. + + Pass the matrix the display is already running on rather than opening a + second one -- the GPIO has a single owner, and the options in force change + the answer. + + :returns: measured Hz, or 0.0 if the matrix cannot be swapped (no + hardware, a stub, a mock). + """ + try: + canvas = matrix.CreateFrameCanvas() + # Discard the first swap: it carries construction and first-touch costs + # that have nothing to do with the steady-state refresh. + canvas = matrix.SwapOnVSync(canvas) + except Exception: + return 0.0 + + frames = 0 + started = time.perf_counter() + while time.perf_counter() - started < seconds: + canvas = matrix.SwapOnVSync(canvas) + frames += 1 + elapsed = time.perf_counter() - started + if elapsed <= 0 or frames <= 0: + return 0.0 + return frames / elapsed + + +#: Samples needed before an interval list can be asked what the refresh was. +_MIN_SAMPLES_FOR_ESTIMATE = 30 + +#: Where in the sorted intervals the refresh period is read from. Not the +#: minimum: one anomalously short sample (a skipped swap, a clock wobble) would +#: set the period for the whole run and turn every honest frame into a miss. +_REFRESH_QUANTILE = 0.1 + + +def refresh_from_intervals( + intervals: Sequence[float], + frame_hold: int = 1, +) -> float: + """The refresh the panel actually ran at *while rendering*, from the frames. + + A panel does not refresh at one fixed rate regardless of what the Pi is + doing. Driving an LED matrix is bit-banging on the same machine, so the + work of pushing a frame -- ``SetImage`` over a 512x64 chain at 8 PWM bits + is milliseconds -- contends with the refresh itself and slows it. Measured + on a Pi 4 with a 512x64 chain: 100.4Hz idle, 96.3Hz while scrolling. + + That makes the idle measurement the wrong thing to grade a soak against. + Graded against 100.4Hz, a loop perfectly locked to the panel's real 96.3Hz + reports 96.3 fps against an expected 100.4 and looks broken; once the drop + passes half a refresh period every frame is counted as a miss outright. + The give-away that nothing is actually being missed is that the intervals + cluster tightly around 10.46ms rather than splitting between 9.96ms and + 19.92ms, which is what missing every twenty-fifth vsync would look like. + + So the period is read back from the frames themselves. Swaps that block on + vsync can only return on a refresh boundary, so the low end of + ``interval / frame_hold`` is the period -- the frames that waited out one + whole refresh and no more. + + :returns: Hz, or 0.0 when there are too few samples to say. + """ + samples = sorted(float(i) for i in intervals if i is not None and i > 0) + if len(samples) < _MIN_SAMPLES_FOR_ESTIMATE: + return 0.0 + period = _percentile(samples, _REFRESH_QUANTILE) / max(1, int(frame_hold)) + return (1.0 / period) if period > 0 else 0.0 diff --git a/test/test_frame_pacing.py b/test/test_frame_pacing.py new file mode 100644 index 00000000..7d4c6ade --- /dev/null +++ b/test/test_frame_pacing.py @@ -0,0 +1,251 @@ +"""Tests for grading a run of presented frames against the panel refresh. + +The arithmetic here decides whether a rig ships, so it is pinned down without +hardware: every case below is a list of frame intervals with a known verdict. +""" + +import json +import sys +import time +from pathlib import Path + +import pytest + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common.frame_pacing import ( # noqa: E402 + DEFAULT_MAX_MISSED_PERCENT, + analyze, + measure_refresh_hz, + refresh_from_intervals, +) + +HZ = 100.0 +PERIOD = 1.0 / HZ + + +class TestAPerfectlyPacedRun: + def test_reports_the_panel_rate(self): + report = analyze([PERIOD] * 1000, HZ, 1) + assert report.presented_fps == pytest.approx(100.0) + assert report.expected_fps == pytest.approx(100.0) + assert report.missed == 0 + assert report.locked + assert report.passed() + + def test_counts_intervals_not_frames(self): + # Ten pushes give nine intervals: the first push has no predecessor. + assert analyze([PERIOD] * 9, HZ, 1).frames == 9 + + def test_a_held_frame_is_paced_at_the_fraction(self): + report = analyze([2 * PERIOD] * 500, HZ, 2) + assert report.expected_fps == pytest.approx(50.0) + assert report.presented_fps == pytest.approx(50.0) + assert report.missed == 0 + assert report.early == 0 + assert report.locked + + +class TestWhatCountsAsMissed: + def test_a_frame_that_slips_a_whole_refresh(self): + report = analyze([PERIOD] * 99 + [2 * PERIOD], HZ, 1) + assert report.missed == 1 + assert report.histogram == {1: 99, 2: 1} + + def test_running_a_little_long_is_not_a_miss(self): + # 11ms on a 10ms refresh still presented on the refresh it was meant + # to. Counting it would make every run fail for no visible reason. + assert analyze([0.011] * 100, HZ, 1).missed == 0 + + def test_past_the_halfway_point_is_a_miss(self): + assert analyze([0.0151] * 100, HZ, 1).missed == 100 + + def test_two_refreshes_late_still_counts_once(self): + # The metric is "frames that slipped", not "refreshes lost". + report = analyze([PERIOD] * 99 + [3 * PERIOD], HZ, 1) + assert report.missed == 1 + assert report.histogram[3] == 1 + + def test_the_hold_moves_the_target(self): + # 20ms frames are perfect at hold 2 and a miss at hold 1. Grading a run + # against the wrong hold is the easiest way to report a false pass. + assert analyze([2 * PERIOD] * 100, HZ, 2).missed == 0 + assert analyze([2 * PERIOD] * 100, HZ, 1).missed == 100 + + +class TestTheGate: + def test_one_in_a_thousand_sits_exactly_on_it(self): + report = analyze([PERIOD] * 999 + [2 * PERIOD], HZ, 1) + assert report.missed_percent == pytest.approx(0.1) + assert report.passed(DEFAULT_MAX_MISSED_PERCENT) + + def test_two_in_a_thousand_does_not(self): + report = analyze([PERIOD] * 998 + [2 * PERIOD] * 2, HZ, 1) + assert not report.passed(DEFAULT_MAX_MISSED_PERCENT) + + def test_a_looser_gate_can_be_asked_for(self): + report = analyze([PERIOD] * 990 + [2 * PERIOD] * 10, HZ, 1) + assert not report.passed(0.1) + assert report.passed(1.0) + + +class TestAnUnlockedRunNeverPasses: + def test_a_loop_faster_than_the_panel_is_not_locked(self): + # 8ms frames on a 100Hz panel: every one lands in the 1-refresh bucket, + # so the miss count is zero, but 125fps is not something a panel at + # 100Hz can present. The swap did not block. + report = analyze([0.008] * 1000, HZ, 1) + assert report.missed == 0 + assert not report.locked + assert not report.passed() + + def test_a_whole_refresh_early_is_counted(self): + report = analyze([PERIOD] * 100, HZ, 2) + assert report.early == 100 + assert not report.locked + + def test_a_loop_stuck_at_half_rate_is_not_locked(self): + # Every frame lands on a whole number of refreshes and the timing is + # perfectly even -- but it is not the hold that was asked for. + report = analyze([2 * PERIOD] * 1000, HZ, 1) + assert not report.locked + assert not report.passed() + + def test_the_verdict_says_so(self): + text = analyze([0.008] * 100, HZ, 1).describe() + assert "NOT LOCKED" in text + assert text.rstrip().endswith("FAIL") + + +class TestDegenerateInput: + def test_no_intervals(self): + report = analyze([], HZ, 1) + assert report.frames == 0 + assert report.missed_percent == 0.0 + assert not report.locked + assert not report.passed() + assert report.describe() == "no frames measured" + + def test_a_refresh_rate_of_zero(self): + report = analyze([PERIOD] * 10, 0.0, 1) + assert report.frames == 0 + assert report.expected_period == 0.0 + assert not report.passed() + + def test_unusable_samples_are_dropped(self): + # A clock that went backwards, or a caller that padded the list. + report = analyze([PERIOD, 0.0, -1.0, None, PERIOD], HZ, 1) + assert report.frames == 2 + + def test_a_hold_below_one_is_treated_as_one(self): + assert analyze([PERIOD] * 10, HZ, 0).frame_hold == 1 + + +class TestTheNumbersReported: + def test_percentiles_are_nearest_rank(self): + samples = [0.001 * n for n in range(1, 101)] + report = analyze(samples, HZ, 1) + assert report.p95 == pytest.approx(0.095) + assert report.p99 == pytest.approx(0.099) + assert report.maximum == pytest.approx(0.100) + assert report.minimum == pytest.approx(0.001) + + def test_seconds_defaults_to_the_span_of_the_run(self): + assert analyze([PERIOD] * 100, HZ, 1).seconds == pytest.approx(1.0) + + def test_seconds_can_be_given_for_a_run_with_gaps(self): + assert analyze([PERIOD] * 100, HZ, 1, seconds=12.5).seconds == 12.5 + + def test_the_report_survives_json(self): + payload = analyze([PERIOD] * 99 + [2 * PERIOD], HZ, 1).as_dict() + restored = json.loads(json.dumps(payload)) + assert restored["missed"] == 1 + assert restored["locked"] is True + assert restored["histogram"] == {"1": 99, "2": 1} + + +class FakePanel: + """A matrix whose swaps block for a fixed period, like real vsync.""" + + def __init__(self, period, fail=False): + self.period = period + self.fail = fail + self.swaps = 0 + + def CreateFrameCanvas(self): + if self.fail: + raise RuntimeError("no hardware here") + return object() + + def SwapOnVSync(self, canvas, framerate_fraction=1): + self.swaps += 1 + time.sleep(self.period) + return canvas + + +class TestMeasuringTheRefreshRate: + def test_times_the_swaps_and_not_the_loop(self): + # The upper bound is the half that carries the meaning: a loop that + # spun without waiting for each swap would report far more than the + # 200Hz a 5ms swap allows. The lower bound is loose on purpose -- + # sleep() under a loaded test runner overshoots, and a slow answer + # here is the runner, not a bug. + measured = measure_refresh_hz(FakePanel(0.005), seconds=0.2) + assert 0 < measured <= 210.0 + + def test_the_first_swap_is_discarded(self): + panel = FakePanel(0.005) + measure_refresh_hz(panel, seconds=0.05) + assert panel.swaps >= 2 + + def test_a_matrix_without_hardware_reports_nothing(self): + assert measure_refresh_hz(FakePanel(0.0, fail=True), seconds=0.1) == 0.0 + + def test_an_object_that_is_not_a_matrix_reports_nothing(self): + assert measure_refresh_hz(object(), seconds=0.1) == 0.0 + + +class TestReadingTheRefreshBackFromTheFrames: + """The panel is slower while the Pi is pushing frames into it. + + Measured on a Pi 4 with a 512x64 chain: 100.4Hz idle, 96.3Hz mid-scroll. + Grading against the idle number is what these tests exist to prevent. + """ + + def test_a_locked_run_reports_its_own_rate(self): + # Intervals clustered just above a 10.38ms period, as a locked loop on + # a panel holding 96.3Hz actually looks. + samples = [0.01038 + 0.00002 * (n % 20) for n in range(500)] + assert refresh_from_intervals(samples, 1) == pytest.approx(96.3, abs=0.5) + + def test_the_hold_is_divided_out(self): + assert refresh_from_intervals([2 * PERIOD] * 500, 2) == pytest.approx(HZ) + + def test_one_short_sample_does_not_set_the_period(self): + # A single 5ms outlier among 10ms frames would, if the minimum were + # used, claim a 200Hz panel and make every real frame a miss. + samples = [0.005] + [PERIOD] * 499 + assert refresh_from_intervals(samples, 1) == pytest.approx(HZ, abs=1.0) + + def test_too_few_samples_to_say(self): + assert refresh_from_intervals([PERIOD] * 5, 1) == 0.0 + assert refresh_from_intervals([], 1) == 0.0 + + def test_the_idle_rate_makes_a_locked_run_look_slow(self): + samples = [0.01038] * 1000 + idle = analyze(samples, 100.4, 1) + assert idle.presented_fps == pytest.approx(96.3, abs=0.1) + assert idle.expected_fps == pytest.approx(100.4) + + loaded = analyze(samples, refresh_from_intervals(samples, 1), 1) + assert loaded.presented_fps == pytest.approx(loaded.expected_fps) + assert loaded.missed == 0 + assert loaded.locked + + def test_a_big_enough_drop_becomes_a_miss_on_every_frame(self): + # Half the idle rate: each frame spans two idle refreshes, so grading + # against idle calls all of them late. Against the rate the panel held, + # none of them are. + samples = [2 * PERIOD] * 1000 + assert analyze(samples, HZ, 1).missed == 1000 + assert analyze(samples, refresh_from_intervals(samples, 1), 1).missed == 0 From f79618d4f729f76ef94f6e54c506360b8ae50700 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 11:56:44 -0400 Subject: [PATCH 6/8] refactor(bench): grade render_bench with the shared frame-timing recorder render_bench.py (from the parallel perf/render-bench work) had its own grading module, frame_pacing, with its own definition of a missed frame and its own refresh estimate. The soak already had both in frame_timing, so the two could have drifted apart on what "late" means. The bench now gives the display manager a fresh FrameTimingRecorder, drains it synchronously at the start and end of the graded run, and prints frame_soak's report with frame_soak's verdict. Its workload is unchanged: the synthetic strip, --busy load, the shared speed resolver, the per-frame scrolling announcement. frame_pacing, its tests and its src.common exports are removed; measure_refresh_hz moves to frame_timing, where scroll_speeds.py now finds it. Two ideas from frame_pacing carry over. The bench seeds the recorder with the idle refresh it measures, so a loop that free-runs (the 827fps bug the first bench caught) shows as early frames and one stuck at half rate as late frames, where an estimate taken from their own intervals finds both self-consistent. And the soak, which has no idle measurement, now calls a run NOT LOCKED when its refresh estimate beats the configured cap. The report also gives the rate held while rendering. Docs: the bench becomes "Without the service" under "Soaking a rig", keeping its hdpi numbers and the idle-vs-rendering refresh finding. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 18 +- docs/SCROLL_PERFORMANCE.md | 113 ++++++------- scripts/frame_soak.py | 58 ++++++- scripts/render_bench.py | 144 +++++++++------- scripts/scroll_speeds.py | 8 +- src/common/__init__.py | 6 +- src/common/frame_pacing.py | 331 ------------------------------------- src/common/frame_timing.py | 68 +++++++- test/test_frame_pacing.py | 251 ---------------------------- test/test_frame_timing.py | 111 +++++++++++++ 10 files changed, 377 insertions(+), 731 deletions(-) delete mode 100644 src/common/frame_pacing.py delete mode 100644 test/test_frame_pacing.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 54b80985..2c1cd70d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,16 +19,14 @@ accepts both, but the store flags the old spelling as deprecated ## Unreleased -- `src.common.frame_pacing` — grades a run of presented frames against the - panel's real refresh rate: how many slipped a whole refresh, and whether the - loop was locked to the panel at all. `scripts/render_bench.py` drives a real - `DisplayManager`/`ScrollHelper` scroll through it and exits non-zero when a - rig misses more than 0.1% of frames, so a rig can be measured before a - release rather than eyeballed. The panel's refresh is read back out of the - frames rather than taken from the idle measurement: a Pi 4 driving 512x64 - holds 100.4Hz idle and 96.3Hz while rendering, and grading against the idle - figure reports misses a perfectly locked loop never had. See - `docs/SCROLL_PERFORMANCE.md`, "Measuring a rig". +- `src.common.frame_timing` -- times every frame the display presents, whoever + drew it, and writes cumulative counters to `/dev/shm`. Two tools read it: + `scripts/frame_soak.py` judges a running service (late frames, freezes, + where the time goes), and `scripts/render_bench.py` judges the hardware and + render path alone on a synthetic strip. Both fail a run above 0.1% late + frames, and both call a loop that never waited for the panel NOT LOCKED. A + stall watchdog logs the stack of whatever holds a scroll up for 250 ms or + more. See `docs/SCROLL_PERFORMANCE.md`, "Soaking a rig". - `FontManager.get_font()` returns a BDF font at its native size when asked for a size the file doesn't contain (5x7.bdf at 8 or 10px, say). It used to diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index f379b5fc..904191df 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -374,14 +374,16 @@ GIL-releasing binding. Vegas mode with live content, 8-minute soaks with - These soaks were taken before the recorder counted 1–2 s stalls as freezes, so a stall of that length would be missing from these rows. -## Measuring a rig +### Without the service: `render_bench.py` -The journal lines above tell you how one scroller behaved while everything else -was also happening. `scripts/render_bench.py` answers the narrower question a -release has to answer per rig: *with nothing else in the way, can this hardware -present every frame on time?* It drives the production path -- a real -`DisplayManager`, a real `ScrollHelper`, the same `scroll_config` resolver every -ticker uses -- so a regression in any of them shows up here. +The soak measures the service as it really runs: live content, plugin +updates, the web preview. `scripts/render_bench.py` answers the narrower +question underneath: *with nothing else in the way, can this hardware present +every frame on time?* It scrolls a synthetic strip through the production path +-- a real `DisplayManager`, a real `ScrollHelper`, the same `scroll_config` +resolver every ticker uses -- on content that is identical every run, which +makes it the tool for comparing rigs (a Pi 3 against a Pi 4, one HAT against +another) and for A/B testing a change to the render path. ```bash sudo systemctl stop ledmatrix # the service owns the GPIO @@ -395,53 +397,37 @@ sudo python3 scripts/render_bench.py --json /tmp/pi4-512x64.json sudo systemctl start ledmatrix ``` -It never starts or stops the service itself, for the same reason -`scroll_speeds.py` does not: a crash in a script must not be able to leave the -panel dark. Exit status is 0 for a pass, 1 for a fail, and **2 when the run -could not be set up at all** -- no root, no panel, a fallback display -- so a -rig that was never measured can never be mistaken for one that passed. +It never starts or stops the service itself, so a crash in it cannot leave +the panel dark. It grades with the same recorder as the soak and prints the +same report, with the same exit status, except that **2** also means the run +could not be set up at all (no root, no panel, a fallback display), so a rig +that was never measured cannot pass by accident. -### Reading the report +Two differences from the soak matter: -A two-minute run on a Pi 4 driving 512x64 at `pwm_bits` 8: +- **It measures the panel first.** Before scrolling it times bare swaps for a + few seconds to get the idle refresh rate, and seeds the recorder with it. + That is what catches a loop that never locked to the panel at all. The first + version of the bench announced its scrolling state once instead of every + frame; the state expired, the dirty-tracking skip fired mid-scroll, and the + loop free-ran at 827 fps. Graded against its own frames that looks perfectly + steady; graded against the panel's measured rate every frame is early, and + the run fails as NOT LOCKED. (The soak has no idle measurement, so it checks + the rate against `limit_refresh_rate_hz` instead: a "refresh" faster than + the cap cannot have been waiting for the panel.) +- **The stall watchdog prints to the terminal.** A frame held up for more than + 250 ms prints the stack of what held it up, in the middle of the run. -``` -measuring the panel for 4s... -panel refreshes at 100.4Hz (cap is 120Hz) -asked for 100.4 px/s -> 100.4 px/s (1px every 1 refresh = 100.4 fps, smooth) -scrolling 512x64 for 120s ... - -panel held 96.3Hz while rendering (4.1% below its 100.4Hz idle rate) - 95.44 fps presented over 11449 frames in 120.0s (expected 96.30 fps = 1 refresh of 96.3Hz) - frame time median 10.46ms p95 10.55ms p99 11.10ms max 22.16ms min 7.36ms (target 10.38ms) - missed 8 (0.070%) gate 0.100% - refreshes 1x:11441 2x:8 - PASS - restarts 5 (the strip was scrolled through 5 times) -``` - -The same rig with `--busy 2` -- two threads parsing JSON, resizing images and -compressing bytes throughout, to imitate plugins updating -- held the same -95.4 fps and missed 3 frames in 11,445 (0.026%). Competing for the GIL did not -cost this loop its pacing. - -A **missed** frame is one whose interval rounds up to at least one more refresh -than its frame hold asked for: the panel showed the previous frame again. The -half-refresh rounding boundary is deliberate -- a frame 1 ms late on a 10 ms -refresh still presented on the refresh it was meant to, and counting it would -fail every rig for nothing. - -**NOT LOCKED** is the verdict that matters more than the miss count. A loop -that never blocked on vsync -- an emulator, a fallback display, or the -dirty-tracking skip firing mid-scroll -- can report a beautiful zero misses -while presenting nothing at all. The check is that the typical frame is not -*shorter* than the panel could physically present, which a bucket count alone -cannot see: 8 ms frames on a 100 Hz panel all land in the one-refresh bucket -while running 25% too fast. A run that is not locked always fails. +Measured with the first version of the bench on hdpi (Pi 4, 512x64, +`pwm_bits` 8), two-minute runs at one pixel per refresh: 8 of 11,449 frames +late (0.070%), and with `--busy 2` 3 of 11,445 (0.026%). The render path and +the hardware pass on their own. Compare the soak results above, from the same +rig with the service running, for how much of the late rate comes from +everything else. ### The panel is slower while you are rendering into it -The benchmark measures the refresh **twice**, and the two numbers differ: +The bench prints two refresh rates, and they differ: | | Pi 4, 512x64, `pwm_bits` 8 | |---|---| @@ -450,19 +436,12 @@ The benchmark measures the refresh **twice**, and the two numbers differ: Both are real. Driving an LED matrix is bit-banging on the same machine, so `SetImage` over a 512x64 chain contends with the refresh itself and slows it. -Grading a soak against the idle number reports 96.3 fps against an expected -100.4 and looks broken; once the gap passes half a refresh period, every single -frame is counted as a miss. The give-away that nothing is actually being missed -is that the intervals cluster tightly around 10.46 ms instead of splitting -between 9.96 ms and 19.92 ms, which is what missing every twenty-fifth vsync -would look like. - -So `frame_pacing.refresh_from_intervals()` reads the period back out of the -frames -- swaps that block on vsync can only return on a refresh boundary, so -the low end of `interval / frame_hold` *is* the period -- and the run is graded -against that. The idle figure is still printed, because the gap between the two -is itself the measure of how expensive a frame is: **a rise in that gap is a -render-cost regression even when the miss count stays at zero.** +The recorder therefore reads the rendering rate back from the frames: swaps +that block on vsync can only return on a refresh boundary, so the low end of +`interval / frame_hold` is the period. The idle figure is still printed, +because the gap between the two is itself a measure of how expensive a frame +is: **a rise in that gap is a render-cost regression even when nothing is +late.** The practical consequence for config: set `limit_refresh_rate_hz` near the rate the panel holds *while rendering*, not the idle rate and certainly not a cap it @@ -470,17 +449,17 @@ can never reach. A cap well above the real rate makes `scroll_config` solve speeds against a refresh that does not exist, which is where "3px every 4 refreshes" comes from. -### Other counters +### Bench-only counters | line | meaning | |---|---| | `duplicate` | frames that advanced no pixels. A crisp fixed-step scroll should show none; any at all means the loop is presenting faster than the strip is moving. | -| `blank` | frames with no visible slice to draw -- the helper had no content. Should be zero. | -| `restarts` | how many times the strip was scrolled through end to end. Informational: the benchmark restarts the strip where a plugin would hand over to the next one. | +| `blank` | frames with no visible slice to draw: the helper had no content. Should be zero. | +| `restarts` | how many times the strip was scrolled through end to end. Informational: the bench restarts the strip where a plugin would hand over to the next one. | -`--json` writes all of it, plus the panel geometry and the speed that was -solved, so two rigs (or one rig before and after a change) can be compared -without re-reading a terminal. +`--json` writes the full report plus the panel geometry, the solved speed and +these counters, so two rigs (or one rig before and after a change) can be +compared without re-reading a terminal. ## Rebuilding the binding diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index 24a8857e..11921ae6 100644 --- a/scripts/frame_soak.py +++ b/scripts/frame_soak.py @@ -132,7 +132,7 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]: frames = totals["scroll_frames"] hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0 bucket_ms = after.get("bucket_ms", 0.25) - return { + report = { "seconds": round(delta["seconds"], 1), "preview": preview, "info": after.get("info"), @@ -156,6 +156,14 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]: "timing_ms": {name: percentiles(h, bucket_ms) for name, h in delta["histograms"].items()}, } + # The rate the panel held while rendering: the typical frame's interval + # per refresh held. A few percent under the idle rate is normal (the Pi is + # 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) + return report def print_report(report: Dict[str, Any], limit: float) -> None: @@ -202,18 +210,56 @@ def print_report(report: Dict[str, Any], limit: float) -> None: if report["late_pct"] is None: print("RESULT nothing scrolled - no verdict") elif not locked(report, limit): - print(f"RESULT FAIL NOT LOCKED: {report['early_pct']}% of frames came a " - "refresh early, so the swaps were not waiting for the panel and " - "the late count means nothing") + ceiling = refresh_ceiling(report) + if (report.get("early_pct") or 0.0) > limit: + why = (f"{report['early_pct']}% of frames came a refresh early, so the " + "swaps were not waiting for the panel") + else: + why = (f"frames arrived at {report['measured_refresh_hz']}Hz, faster than " + f"the panel can refresh ({ceiling:g}Hz)") + print(f"RESULT FAIL NOT LOCKED: {why}, and the late count means nothing") elif report["late_pct"] <= limit: print(f"RESULT PASS {report['late_pct']}% late <= {limit}%") else: print(f"RESULT FAIL {report['late_pct']}% late > {limit}%") +#: How far over the panel's rate frames may arrive before the loop cannot have +#: been waiting for it. The margin covers the refresh wandering a little. +CEILING_MARGIN = 1.05 + + +def refresh_ceiling(report: Dict[str, Any]) -> Optional[float]: + """The fastest the panel can refresh, as far as this run knows. + + The benchmark measures it (``idle_refresh_hz``); the service only knows its + cap. With neither, there is no ceiling to check against. + """ + idle = report.get("idle_refresh_hz") + if idle: + return float(idle) + cap = (report.get("info") or {}).get("limit_refresh_rate_hz") + try: + cap = float(cap) + except (TypeError, ValueError): + return None + return cap if cap > 0 else None + + def locked(report: Dict[str, Any], limit: float) -> bool: - """Whether the loop was paced by the panel at all.""" - return (report.get("early_pct") or 0.0) <= limit + """Whether the loop was paced by the panel at all. + + Two ways it is not. Frames a whole refresh early mean some swaps did not + wait. And a loop that never waited at all -- the dirty-tracking skip firing + mid-scroll let one free-run at 827fps -- looks self-consistent to a refresh + estimate taken from its own frames, so nothing registers as early; what + gives it away is a "refresh" faster than the panel can physically do. + """ + if (report.get("early_pct") or 0.0) > limit: + return False + ceiling = refresh_ceiling(report) + measured = report.get("measured_refresh_hz") + return not (ceiling and measured and measured > ceiling * CEILING_MARGIN) def passed(report: Dict[str, Any], limit: float) -> bool: diff --git a/scripts/render_bench.py b/scripts/render_bench.py index 4bfffa91..c289546d 100755 --- a/scripts/render_bench.py +++ b/scripts/render_bench.py @@ -4,9 +4,17 @@ The question this answers is the one that decides whether a rig ships: *does every frame present on the refresh it was meant to?* It drives the production path -- a real ``DisplayManager`` and ``ScrollHelper``, the same crisp speed -resolver every ticker uses -- scrolls for a while, and grades the result with -``src.common.frame_pacing``. A run passes when the loop was genuinely locked to -the panel and fewer than ``--max-missed`` percent of frames slipped a refresh. +resolver every ticker uses -- scrolls a synthetic strip for a while, and grades +it with the same frame-timing recorder the display service uses +(``src.common.frame_timing``), printing the same report as +``scripts/frame_soak.py``. A run passes when the loop was genuinely locked to +the panel and no more than ``--max-late-pct`` percent of frames were late. + +Where frame_soak.py measures the service as it runs -- live content, plugin +updates, the web preview -- this measures the hardware and the render path +with nothing else in the way, on content that is identical every run. That is +what makes it the tool for comparing rigs (a Pi 3 against a Pi 4, one HAT +against another) and for A/B testing a change to the render path. # stop the service first; it owns the GPIO sudo systemctl stop ledmatrix @@ -40,7 +48,10 @@ from pathlib import Path sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) -from src.common import frame_pacing, scroll_config # noqa: E402 +from src.common import frame_timing, scroll_config # noqa: E402 + +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import frame_soak # noqa: E402 (same report, same verdict as the soak) REPO = Path(__file__).resolve().parent.parent CONFIG = REPO / "config" / "config.json" @@ -53,6 +64,10 @@ DEFAULT_SECONDS = 60.0 #: has to settle, but every second here is a second not scrolling. MEASURE_SECONDS = 4.0 +#: Scrolling discarded before the graded run starts: the first frames carry +#: first-touch costs and the scrolling state settling. +WARMUP_SECONDS = 2.0 + def load_config() -> dict: """The config the display service would run with.""" @@ -163,6 +178,7 @@ class BackgroundLoad: zlib.compress(image.tobytes(), 1) + def main(argv=None) -> int: parser = argparse.ArgumentParser( description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) @@ -174,15 +190,13 @@ def main(argv=None) -> int: "panel can show in whole pixels (default: one pixel " "per refresh)") parser.add_argument("--hz", type=float, default=None, - help="skip the measurement and grade against this refresh " - "rate instead (for reproducing a rig's numbers)") + help="skip the idle measurement and take this as the " + "panel's rate (for reproducing a rig's numbers)") parser.add_argument("--busy", type=int, default=0, metavar="N", help="run N background workers imitating plugin updates") - parser.add_argument("--max-missed", type=float, - default=frame_pacing.DEFAULT_MAX_MISSED_PERCENT, - metavar="PCT", - help="percent of frames allowed to slip a refresh " - f"(default {frame_pacing.DEFAULT_MAX_MISSED_PERCENT})") + parser.add_argument("--max-late-pct", "--max-missed", dest="max_late_pct", + type=float, default=0.1, metavar="PCT", + help="fail above this percentage of late frames (default 0.1)") parser.add_argument("--json", dest="json_path", default=None, metavar="PATH", help="also write the report as JSON, for comparing rigs") parser.add_argument("--label", default=None, @@ -190,8 +204,10 @@ def main(argv=None) -> int: args = parser.parse_args(argv) # Everything the display service logs would otherwise land in the middle of - # the report; the benchmark's own output is the point. + # the report; the benchmark's own output is the point. The stall watchdog + # is the exception: a stack dump naming what held a frame up belongs here. logging.basicConfig(level=logging.ERROR, stream=sys.stderr) + logging.getLogger("src.common.frame_timing").setLevel(logging.WARNING) if hasattr(os, "geteuid") and os.geteuid() != 0: print("this needs root for GPIO access - rerun with sudo", file=sys.stderr) @@ -219,21 +235,21 @@ def main(argv=None) -> int: width, height = display.width, display.height if args.hz is not None: - refresh_hz = float(args.hz) - print(f"grading against {refresh_hz:.1f}Hz (given, not measured)") + idle_hz = float(args.hz) + print(f"taking the panel's rate as {idle_hz:.1f}Hz (given, not measured)") else: print(f"measuring the panel for {MEASURE_SECONDS:.0f}s...", flush=True) - refresh_hz = frame_pacing.measure_refresh_hz(display.matrix, MEASURE_SECONDS) - if refresh_hz <= 0: + idle_hz = frame_timing.measure_refresh_hz(display.matrix, MEASURE_SECONDS) + if idle_hz <= 0: print("the panel did not answer a swap; cannot measure it", file=sys.stderr) return 2 cap = scroll_config.refresh_hz_from_config(config) - note = (f" (cap is {cap:.0f}Hz)" if refresh_hz < cap * 0.98 + note = (f" (cap is {cap:.0f}Hz)" if idle_hz < cap * 0.98 else " (at its configured cap)") - print(f"panel refreshes at {refresh_hz:.1f}Hz{note}") + print(f"panel refreshes at {idle_hz:.1f}Hz{note}") - requested = args.speed if args.speed else refresh_hz + requested = args.speed if args.speed else idle_hz # Configured through the shared resolver rather than by setting the helper # up by hand, so the benchmark measures the engine every ticker runs on. A @@ -244,7 +260,7 @@ def main(argv=None) -> int: helper, plugin_config={"scroll_pixels_per_second": requested}, global_config=config, - refresh_hz=refresh_hz, + refresh_hz=idle_hz, display_manager=display, ) choice = settings.crisp @@ -258,20 +274,42 @@ def main(argv=None) -> int: helper.set_scrolling_image( build_strip(width, height, f"{choice.pixels_per_second:.0f} px/s")) + # The display service's own recorder, owned outright here: never flushed to + # the service's stats file, drained exactly at the start and end of the + # graded run, and seeded with the idle rate so a loop that never locked + # (free-running, or stuck at a fraction of the refresh) shows as early or + # late frames instead of looking self-consistent. + recorder = frame_timing.FrameTimingRecorder( + flush_interval=float("inf"), + info=display._frame_timing_info(), # pylint: disable=protected-access + refresh_hz=idle_hz, + ) + recorder.scrolling_now = display._scrolling_now # pylint: disable=protected-access + display.frame_timing = recorder + print(f"scrolling {width}x{height} for {args.seconds:.0f}s" + (f" with {args.busy} background worker(s)" if args.busy else "") + " ...", flush=True) - intervals: list = [] + frames = 0 duplicates = 0 blanks = 0 restarts = 0 last_column = None + before = None started = time.perf_counter() - previous = None + run_started = None try: with BackgroundLoad(args.busy): - while time.perf_counter() - started < args.seconds: + while True: + now = time.perf_counter() + if run_started is None and now - started >= WARMUP_SECONDS: + recorder.drain() + before = recorder.snapshot() + run_started = now + frames = duplicates = blanks = restarts = 0 + if run_started is not None and now - run_started >= args.seconds: + break helper.update_scroll_position() if helper.is_scroll_complete(): # The helper parks at the end of the strip and stops @@ -300,71 +338,65 @@ def main(argv=None) -> int: # Every ticker re-announces per frame; so does this. display.set_scrolling_state(True, frame_hold=choice.frame_hold) display.update_display() - now = time.perf_counter() - if previous is not None: - intervals.append(now - previous) - previous = now + frames += 1 except KeyboardInterrupt: print("\ninterrupted - reporting what was measured so far") finally: - elapsed = time.perf_counter() - started display.set_scrolling_state(False) try: display.clear() except Exception: pass - # The panel does not refresh at its idle rate while the Pi is also pushing - # frames into it; see frame_pacing.refresh_from_intervals. Grading against - # the idle number reports misses a locked loop never had, so the rate the - # panel actually held during the scroll is read back from the frames. - idle_hz = refresh_hz - loaded_hz = frame_pacing.refresh_from_intervals(intervals, choice.frame_hold) - graded_hz = loaded_hz if 0 < loaded_hz <= idle_hz * 1.02 else idle_hz + if before is None: + print("interrupted during warm-up; nothing was graded", file=sys.stderr) + return 2 + recorder.drain() + report = frame_soak.build_report(before, recorder.snapshot(), preview=False) + report["idle_refresh_hz"] = round(idle_hz, 2) - report = frame_pacing.analyze(intervals, graded_hz, choice.frame_hold, - seconds=elapsed) print() - if loaded_hz > 0: - drop = 100.0 * (idle_hz - loaded_hz) / idle_hz - print(f"panel held {loaded_hz:.1f}Hz while rendering " - f"({drop:.1f}% below its {idle_hz:.1f}Hz idle rate)") - print(report.describe(args.max_missed)) + frame_soak.print_report(report, args.max_late_pct) + held = report.get("held_refresh_hz") + if held: + drop = 100.0 * (idle_hz - held) / idle_hz + print(f"\npanel held ~{held:.1f}Hz while rendering, {drop:.1f}% below its " + f"{idle_hz:.1f}Hz idle rate (a widening gap is a render-cost " + "regression even with nothing late)") if duplicates: # A frame that shows the same columns as the one before it is work the # panel did not need. It is not a miss -- the frame arrived on time -- # but it means the loop is presenting faster than the strip is moving. - print(f" duplicate {duplicates} frames advanced no pixels " - f"({100.0 * duplicates / max(1, len(intervals)):.2f}%)") + print(f"duplicate {duplicates} frames advanced no pixels " + f"({100.0 * duplicates / max(1, frames):.2f}%)") if blanks: - print(f" blank {blanks} frames had no visible slice to draw") + print(f"blank {blanks} frames had no visible slice to draw") if restarts: - print(f" restarts {restarts} (the strip was scrolled through " + print(f"restarts {restarts} (the strip was scrolled through " f"{restarts} time{'s' if restarts != 1 else ''})") if args.json_path: - payload = report.as_dict() - payload.update({ + report.update({ "label": args.label or os.uname().nodename, - "width": width, - "height": height, + "bench": True, "requested_pixels_per_second": requested, "pixels_per_second": choice.pixels_per_second, "pixels_per_frame": choice.pixels_per_frame, + "frame_hold": choice.frame_hold, "busy_workers": args.busy, "duplicate_frames": duplicates, "blank_frames": blanks, "strip_restarts": restarts, - "idle_refresh_hz": idle_hz, - "loaded_refresh_hz": loaded_hz, - "max_missed_percent": args.max_missed, - "passed": report.passed(args.max_missed), + "max_late_pct": args.max_late_pct, + "passed": frame_soak.passed(report, args.max_late_pct), }) - Path(args.json_path).write_text(json.dumps(payload, indent=2) + "\n", + Path(args.json_path).write_text(json.dumps(report, indent=2) + "\n", encoding="utf-8") print(f"\nwrote {args.json_path}") - return 0 if report.passed(args.max_missed) else 1 + if report["late_pct"] is None: + return 2 + return 0 if frame_soak.passed(report, args.max_late_pct) else 1 if __name__ == "__main__": diff --git a/scripts/scroll_speeds.py b/scripts/scroll_speeds.py index 2a6f2916..7b9d192b 100644 --- a/scripts/scroll_speeds.py +++ b/scripts/scroll_speeds.py @@ -42,7 +42,7 @@ from pathlib import Path sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) -from src.common import frame_pacing, scroll_config # noqa: E402 +from src.common import frame_timing, scroll_config # noqa: E402 CONFIG = Path(__file__).resolve().parent.parent / "config" / "config.json" @@ -101,11 +101,11 @@ def measure_refresh(config, seconds=6.0): What an older Pi or a longer chain will really give you, as opposed to whatever limit_refresh_rate_hz optimistically asks for. The timing loop - itself lives in src.common.frame_pacing so the benchmark grades a soak - against the same measurement this ladder is built from. + itself lives in src.common.frame_timing so the benchmark grades against + the same measurement this ladder is built from. """ matrix = open_matrix(config, refresh_override=0) - measured = frame_pacing.measure_refresh_hz(matrix, seconds) + measured = frame_timing.measure_refresh_hz(matrix, seconds) matrix.Clear() return measured diff --git a/src/common/__init__.py b/src/common/__init__.py index 2454265e..9b3a8925 100644 --- a/src/common/__init__.py +++ b/src/common/__init__.py @@ -11,14 +11,13 @@ This package provides reusable functionality for plugins and core modules: # Export commonly used utilities from src.common.api_helper import APIHelper from src.common.scroll_helper import ScrollHelper -from src.common import frame_pacing, scroll_config +from src.common import scroll_config from src.common.scroll_config import ( ScrollSettings, configure as configure_scroll, resolve as resolve_scroll_settings, refresh_hz_from_config, ) -from src.common.frame_pacing import PacingReport, analyze as analyze_frame_pacing from src.common.logo_helper import LogoHelper from src.common.text_helper import TextHelper @@ -51,9 +50,6 @@ __all__ = [ 'APIHelper', 'ScrollHelper', 'scroll_config', - 'frame_pacing', - 'PacingReport', - 'analyze_frame_pacing', 'ScrollSettings', 'configure_scroll', 'resolve_scroll_settings', diff --git a/src/common/frame_pacing.py b/src/common/frame_pacing.py deleted file mode 100644 index 822c9495..00000000 --- a/src/common/frame_pacing.py +++ /dev/null @@ -1,331 +0,0 @@ -"""Judge a run of presented frames against the panel's real refresh. - -The rule the display obeys is in docs/SCROLL_PERFORMANCE.md: motion is smooth -when the strip advances a whole number of pixels per panel refresh, with each -frame held for a whole number of refreshes. That makes "is this scroll smooth?" -a question with an exact answer rather than a matter of taste -- - - every presented frame should last ``frame_hold / refresh_hz`` seconds - --- and it makes a *missed* frame exactly one thing: an interval long enough to -round up to at least one more refresh than the hold asked for. That is a -dropped vsync, and it is what the eye reads as a hitch. - -This module is only the arithmetic. It takes a list of intervals between -successive panel pushes (seconds, as ``time.perf_counter`` deltas) and reports -how many of them slipped. Nothing here touches hardware, so the thresholds a -soak is graded against are testable on any machine; ``scripts/render_bench.py`` -is the driver that collects the intervals on a real panel. - -Two failure modes are counted separately, because they mean opposite things: - -* **missed** -- the interval is at least one refresh longer than it should be. - Something (a slow ``SetImage``, a plugin fetch, the preview encoder, the GIL) - held the render loop past the panel's deadline. -* **early** -- the interval is at least one refresh *shorter* than it should be. - The swap returned without waiting, so the frame was never presented as a - distinct image. A run with early frames is not measuring a vsync-locked loop - at all, and its missed-frame percentage means nothing; the driver says so - rather than reporting a flattering number. -""" - -from __future__ import annotations - -import math -import time -from dataclasses import dataclass, field -from typing import Any, Dict, List, Optional, Sequence - -#: The ship gate from the rendering goal: under a tenth of a percent of frames -#: may miss a refresh over a soak. -DEFAULT_MAX_MISSED_PERCENT = 0.1 - -#: How far an interval may sit from its target before it counts as a different -#: number of refreshes. Half a refresh period is the rounding boundary, so this -#: is not a tunable fudge factor -- it is where "held for N refreshes" stops -#: being the nearest whole answer and "N+1" starts. -_ROUNDING = 0.5 - -#: How far the typical frame may fall short of its target period before the run -#: is judged not to have been paced by the panel at all. A vsync-locked loop -#: physically cannot present faster than ``refresh_hz / frame_hold``, so a -#: median below that means the swaps were not blocking -- the emulator, the -#: fallback display, or hardware that returned early. The margin only covers -#: error in the measured refresh rate itself. -_LOCK_TOLERANCE = 0.05 - - -def _percentile(sorted_values: Sequence[float], fraction: float) -> float: - """Nearest-rank percentile, as ``scroll_helper.frame_stats`` does for p95.""" - if not sorted_values: - return 0.0 - rank = max(0, math.ceil(fraction * len(sorted_values)) - 1) - return sorted_values[min(rank, len(sorted_values) - 1)] - - -@dataclass(frozen=True) -class PacingReport: - """What a run of frame intervals says about the loop that produced it.""" - - #: Intervals measured. One fewer than the frames pushed: the first push has - #: no predecessor to time against. - frames: int - seconds: float - refresh_hz: float - frame_hold: int - presented_fps: float - expected_fps: float - median: float - p95: float - p99: float - maximum: float - minimum: float - missed: int - early: int - #: How many refreshes each frame actually lasted, rounded, as - #: ``{refreshes: count}``. A vsync-locked loop puts nearly everything on - #: ``frame_hold``; a spread across several buckets is judder even when the - #: average fps looks right. - histogram: Dict[int, int] = field(default_factory=dict) - - @property - def expected_period(self) -> float: - """Seconds a correctly paced frame lasts.""" - return self.frame_hold / self.refresh_hz if self.refresh_hz > 0 else 0.0 - - @property - def missed_percent(self) -> float: - return 100.0 * self.missed / self.frames if self.frames else 0.0 - - @property - def early_percent(self) -> float: - return 100.0 * self.early / self.frames if self.frames else 0.0 - - @property - def locked(self) -> bool: - """True when the loop really was paced by the panel. - - Every frame landing on some whole number of refreshes is not enough -- - a loop that free-runs at half the refresh also does that. Two things - have to hold: the hold asked for is the hold observed, and the typical - frame is not *shorter* than the panel could possibly present. The - second is what catches a swap that returned without blocking, which a - whole-refresh bucket count cannot see -- 8ms frames on a 100Hz panel - all land in the 1-refresh bucket while running 25% too fast. - """ - if not self.frames: - return False - modal = max(self.histogram, key=lambda k: self.histogram[k]) - if modal != self.frame_hold or self.early: - return False - return self.median >= self.expected_period * (1.0 - _LOCK_TOLERANCE) - - def passed(self, max_missed_percent: float = DEFAULT_MAX_MISSED_PERCENT) -> bool: - """Whether this run clears the gate. An unlocked run never does.""" - return self.locked and self.missed_percent <= max_missed_percent - - def as_dict(self) -> Dict[str, Any]: - """JSON-safe form, for a soak that writes its result to a file.""" - return { - "frames": self.frames, - "seconds": self.seconds, - "refresh_hz": self.refresh_hz, - "frame_hold": self.frame_hold, - "expected_period_ms": self.expected_period * 1000.0, - "presented_fps": self.presented_fps, - "expected_fps": self.expected_fps, - "median_ms": self.median * 1000.0, - "p95_ms": self.p95 * 1000.0, - "p99_ms": self.p99 * 1000.0, - "max_ms": self.maximum * 1000.0, - "min_ms": self.minimum * 1000.0, - "missed": self.missed, - "missed_percent": self.missed_percent, - "early": self.early, - "early_percent": self.early_percent, - "locked": self.locked, - "histogram": {str(k): v for k, v in sorted(self.histogram.items())}, - } - - def describe(self, max_missed_percent: float = DEFAULT_MAX_MISSED_PERCENT) -> str: - """The human report: several lines, no trailing newline.""" - if not self.frames: - return "no frames measured" - lines = [ - f"{self.presented_fps:6.2f} fps presented over {self.frames} frames " - f"in {self.seconds:.1f}s " - f"(expected {self.expected_fps:.2f} fps = " - f"{self.frame_hold} refresh{'es' if self.frame_hold != 1 else ''} " - f"of {self.refresh_hz:.1f}Hz)", - f" frame time median {self.median * 1000:6.2f}ms " - f"p95 {self.p95 * 1000:6.2f}ms p99 {self.p99 * 1000:6.2f}ms " - f"max {self.maximum * 1000:6.2f}ms min {self.minimum * 1000:6.2f}ms " - f"(target {self.expected_period * 1000:.2f}ms)", - f" missed {self.missed} ({self.missed_percent:.3f}%) " - f"gate {max_missed_percent:.3f}%", - ] - if self.early: - lines.append( - f" early {self.early} ({self.early_percent:.3f}%) " - "- swaps returned a whole refresh early" - ) - buckets = " ".join( - f"{refreshes}x:{count}" for refreshes, count in sorted(self.histogram.items()) - ) - lines.append(f" refreshes {buckets}") - if not self.locked: - lines.append( - " NOT LOCKED - the loop was not paced by the panel, so the " - "missed count above means nothing. Either the swap did not " - "block (emulator or fallback display) or the frame hold in " - "effect was not the one this run was graded against." - ) - verdict = "PASS" if self.passed(max_missed_percent) else "FAIL" - lines.append(f" {verdict}") - return "\n".join(lines) - - -def analyze( - intervals: Sequence[float], - refresh_hz: float, - frame_hold: int = 1, - seconds: Optional[float] = None, -) -> PacingReport: - """Grade a list of frame intervals against a panel refresh. - - :param intervals: seconds between successive panel pushes. - :param refresh_hz: the panel's *measured* refresh, not its configured cap. - Grading against a cap the panel cannot reach reports misses that are - really just the panel being slower than asked -- which is why - ``render_bench`` measures first and passes the result in here. - :param frame_hold: refreshes each frame was held for (``SwapOnVSync``'s - ``framerate_fraction``), so the target period is ``hold / refresh_hz``. - :param seconds: wall time the run covered. Defaults to the sum of the - intervals, which is the same thing for a contiguous run. - """ - samples: List[float] = [float(i) for i in intervals if i is not None and i > 0] - hold = max(1, int(frame_hold)) - hz = float(refresh_hz) - if not samples or hz <= 0: - return PacingReport( - frames=0, seconds=float(seconds or 0.0), refresh_hz=max(0.0, hz), - frame_hold=hold, presented_fps=0.0, expected_fps=0.0, - median=0.0, p95=0.0, p99=0.0, maximum=0.0, minimum=0.0, - missed=0, early=0, histogram={}, - ) - - refresh_period = 1.0 / hz - ordered = sorted(samples) - total = float(seconds) if seconds is not None else sum(samples) - mean = sum(samples) / len(samples) - - histogram: Dict[int, int] = {} - missed = 0 - early = 0 - for interval in samples: - # How many refreshes this frame actually occupied. Rounding at the - # halfway point is what makes a "miss" a whole dropped vsync rather - # than any interval that ran a little long -- a frame 1ms late on a - # 10ms refresh still presented on the refresh it was meant to. - refreshes = max(1, int(math.floor(interval / refresh_period + _ROUNDING))) - histogram[refreshes] = histogram.get(refreshes, 0) + 1 - if refreshes > hold: - missed += 1 - elif refreshes < hold: - early += 1 - - return PacingReport( - frames=len(samples), - seconds=total, - refresh_hz=hz, - frame_hold=hold, - presented_fps=(1.0 / mean) if mean > 0 else 0.0, - expected_fps=hz / hold, - median=_percentile(ordered, 0.5), - p95=_percentile(ordered, 0.95), - p99=_percentile(ordered, 0.99), - maximum=ordered[-1], - minimum=ordered[0], - missed=missed, - early=early, - histogram=histogram, - ) - - -def measure_refresh_hz(matrix: Any, seconds: float = 4.0) -> float: - """The panel's real refresh rate, by timing unthrottled swaps. - - ``SwapOnVSync`` blocks until the panel's next refresh, so a loop that does - nothing else runs at exactly the panel's rate. This is the number every - pacing decision has to be made against: ``limit_refresh_rate_hz`` is a - *cap*, and a long chain, a high ``pwm_bits`` or an older Pi will sit well - under it. Solving scroll speeds against a cap the panel cannot reach is - what produces "3px every 4 refreshes" and the judder that comes with it. - - Pass the matrix the display is already running on rather than opening a - second one -- the GPIO has a single owner, and the options in force change - the answer. - - :returns: measured Hz, or 0.0 if the matrix cannot be swapped (no - hardware, a stub, a mock). - """ - try: - canvas = matrix.CreateFrameCanvas() - # Discard the first swap: it carries construction and first-touch costs - # that have nothing to do with the steady-state refresh. - canvas = matrix.SwapOnVSync(canvas) - except Exception: - return 0.0 - - frames = 0 - started = time.perf_counter() - while time.perf_counter() - started < seconds: - canvas = matrix.SwapOnVSync(canvas) - frames += 1 - elapsed = time.perf_counter() - started - if elapsed <= 0 or frames <= 0: - return 0.0 - return frames / elapsed - - -#: Samples needed before an interval list can be asked what the refresh was. -_MIN_SAMPLES_FOR_ESTIMATE = 30 - -#: Where in the sorted intervals the refresh period is read from. Not the -#: minimum: one anomalously short sample (a skipped swap, a clock wobble) would -#: set the period for the whole run and turn every honest frame into a miss. -_REFRESH_QUANTILE = 0.1 - - -def refresh_from_intervals( - intervals: Sequence[float], - frame_hold: int = 1, -) -> float: - """The refresh the panel actually ran at *while rendering*, from the frames. - - A panel does not refresh at one fixed rate regardless of what the Pi is - doing. Driving an LED matrix is bit-banging on the same machine, so the - work of pushing a frame -- ``SetImage`` over a 512x64 chain at 8 PWM bits - is milliseconds -- contends with the refresh itself and slows it. Measured - on a Pi 4 with a 512x64 chain: 100.4Hz idle, 96.3Hz while scrolling. - - That makes the idle measurement the wrong thing to grade a soak against. - Graded against 100.4Hz, a loop perfectly locked to the panel's real 96.3Hz - reports 96.3 fps against an expected 100.4 and looks broken; once the drop - passes half a refresh period every frame is counted as a miss outright. - The give-away that nothing is actually being missed is that the intervals - cluster tightly around 10.46ms rather than splitting between 9.96ms and - 19.92ms, which is what missing every twenty-fifth vsync would look like. - - So the period is read back from the frames themselves. Swaps that block on - vsync can only return on a refresh boundary, so the low end of - ``interval / frame_hold`` is the period -- the frames that waited out one - whole refresh and no more. - - :returns: Hz, or 0.0 when there are too few samples to say. - """ - samples = sorted(float(i) for i in intervals if i is not None and i > 0) - if len(samples) < _MIN_SAMPLES_FOR_ESTIMATE: - return 0.0 - period = _percentile(samples, _REFRESH_QUANTILE) / max(1, int(frame_hold)) - return (1.0 / period) if period > 0 else 0.0 diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 9cd56e31..3e94b6fe 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -45,6 +45,14 @@ cutting it by more than ``MAX_REFRESH_DROP`` is ignored. A panel's refresh does not jump like that; swaps that stopped blocking do, and adopting their period would make every early frame look on time. +A caller that has measured the panel independently -- ``scripts/render_bench.py`` +times bare swaps first with :func:`measure_refresh_hz` -- passes that rate in +as ``refresh_hz``. The estimate then starts from it instead of from the frames, +which is what catches a loop that never locked at all: one that free-runs +faster than the panel (every frame early) or sits at half its rate (every +frame late), both of which look self-consistent to an estimate taken from +their own intervals. + Stall watchdog -------------- Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the @@ -155,6 +163,45 @@ def _pi_model() -> Optional[str]: return None +def measure_refresh_hz(matrix: Any, seconds: float = 4.0) -> float: + """The panel's refresh rate with nothing else running, by timing bare swaps. + + ``SwapOnVSync`` blocks until the panel's next refresh, so a loop that does + nothing else runs at exactly the panel's rate. ``limit_refresh_rate_hz`` is + a *cap*, and a long chain, a high ``pwm_bits`` or an older Pi will sit well + under it. Solving scroll speeds against a cap the panel cannot reach is + what produces "3px every 4 refreshes" and the judder that comes with it. + + This is the idle rate. The panel refreshes a few percent slower while the + Pi is also pushing frames into it (100.4Hz idle against 96.3Hz scrolling on + a Pi 4 driving 512x64), which is why the recorder reads the rendering rate + back from the frames rather than trusting this. + + Pass the matrix the display is already running on rather than opening a + second one: the GPIO has a single owner, and the options in force change + the answer. + + :returns: measured Hz, or 0.0 if the matrix cannot be swapped (no + hardware, a stub, a mock). + """ + try: + canvas = matrix.CreateFrameCanvas() + # Discard the first swap: it carries construction and first-touch costs + # that have nothing to do with the steady-state refresh. + canvas = matrix.SwapOnVSync(canvas) + except Exception: # pylint: disable=broad-except + return 0.0 + + frames = 0 + started = time.perf_counter() + while time.perf_counter() - started < seconds: + canvas = matrix.SwapOnVSync(canvas) + frames += 1 + elapsed = time.perf_counter() - started + if elapsed <= 0 or frames <= 0: + return 0.0 + return frames / elapsed + class FrameTimingRecorder: """Collects per-frame timings on the render thread; aggregates elsewhere. @@ -167,7 +214,13 @@ class FrameTimingRecorder: path: Optional[str] = None, flush_interval: float = FLUSH_INTERVAL, info: Optional[Dict[str, Any]] = None, + refresh_hz: Optional[float] = None, ): + """ + :param refresh_hz: the panel's rate, measured independently (see the + module docstring). Omit it to estimate from the frames alone, as + the display service does. + """ self.path = path or default_stats_path() self.flush_interval = flush_interval self.info = dict(info or {}) @@ -182,7 +235,8 @@ class FrameTimingRecorder: # Worker-thread state. Nothing on the render thread reads these. self.started = time.time() - self.refresh_period: Optional[float] = None + self.refresh_period: Optional[float] = ( + 1.0 / refresh_hz if refresh_hz and refresh_hz > 0 else None) self.totals: Dict[str, Any] = { "static_frames": 0, "scroll_frames": 0, @@ -251,6 +305,18 @@ class FrameTimingRecorder: target=self._run, daemon=True, name="frame-timing") self._worker.start() + def drain(self) -> None: + """Aggregate everything recorded so far, on the calling thread. + + For a caller that owns the recorder outright and wants exact numbers at + a moment of its choosing -- the benchmark, between warm-up and run and + at the end. Construct it with ``flush_interval=float('inf')`` so the + worker never runs; the two must not aggregate at once. + """ + batch, self._pending = self._pending, [] + static, self._static_frames = self._static_frames, 0 + self.aggregate(batch, static) + # -- worker thread ------------------------------------------------------ def _run(self) -> None: diff --git a/test/test_frame_pacing.py b/test/test_frame_pacing.py deleted file mode 100644 index 7d4c6ade..00000000 --- a/test/test_frame_pacing.py +++ /dev/null @@ -1,251 +0,0 @@ -"""Tests for grading a run of presented frames against the panel refresh. - -The arithmetic here decides whether a rig ships, so it is pinned down without -hardware: every case below is a list of frame intervals with a known verdict. -""" - -import json -import sys -import time -from pathlib import Path - -import pytest - -sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) - -from src.common.frame_pacing import ( # noqa: E402 - DEFAULT_MAX_MISSED_PERCENT, - analyze, - measure_refresh_hz, - refresh_from_intervals, -) - -HZ = 100.0 -PERIOD = 1.0 / HZ - - -class TestAPerfectlyPacedRun: - def test_reports_the_panel_rate(self): - report = analyze([PERIOD] * 1000, HZ, 1) - assert report.presented_fps == pytest.approx(100.0) - assert report.expected_fps == pytest.approx(100.0) - assert report.missed == 0 - assert report.locked - assert report.passed() - - def test_counts_intervals_not_frames(self): - # Ten pushes give nine intervals: the first push has no predecessor. - assert analyze([PERIOD] * 9, HZ, 1).frames == 9 - - def test_a_held_frame_is_paced_at_the_fraction(self): - report = analyze([2 * PERIOD] * 500, HZ, 2) - assert report.expected_fps == pytest.approx(50.0) - assert report.presented_fps == pytest.approx(50.0) - assert report.missed == 0 - assert report.early == 0 - assert report.locked - - -class TestWhatCountsAsMissed: - def test_a_frame_that_slips_a_whole_refresh(self): - report = analyze([PERIOD] * 99 + [2 * PERIOD], HZ, 1) - assert report.missed == 1 - assert report.histogram == {1: 99, 2: 1} - - def test_running_a_little_long_is_not_a_miss(self): - # 11ms on a 10ms refresh still presented on the refresh it was meant - # to. Counting it would make every run fail for no visible reason. - assert analyze([0.011] * 100, HZ, 1).missed == 0 - - def test_past_the_halfway_point_is_a_miss(self): - assert analyze([0.0151] * 100, HZ, 1).missed == 100 - - def test_two_refreshes_late_still_counts_once(self): - # The metric is "frames that slipped", not "refreshes lost". - report = analyze([PERIOD] * 99 + [3 * PERIOD], HZ, 1) - assert report.missed == 1 - assert report.histogram[3] == 1 - - def test_the_hold_moves_the_target(self): - # 20ms frames are perfect at hold 2 and a miss at hold 1. Grading a run - # against the wrong hold is the easiest way to report a false pass. - assert analyze([2 * PERIOD] * 100, HZ, 2).missed == 0 - assert analyze([2 * PERIOD] * 100, HZ, 1).missed == 100 - - -class TestTheGate: - def test_one_in_a_thousand_sits_exactly_on_it(self): - report = analyze([PERIOD] * 999 + [2 * PERIOD], HZ, 1) - assert report.missed_percent == pytest.approx(0.1) - assert report.passed(DEFAULT_MAX_MISSED_PERCENT) - - def test_two_in_a_thousand_does_not(self): - report = analyze([PERIOD] * 998 + [2 * PERIOD] * 2, HZ, 1) - assert not report.passed(DEFAULT_MAX_MISSED_PERCENT) - - def test_a_looser_gate_can_be_asked_for(self): - report = analyze([PERIOD] * 990 + [2 * PERIOD] * 10, HZ, 1) - assert not report.passed(0.1) - assert report.passed(1.0) - - -class TestAnUnlockedRunNeverPasses: - def test_a_loop_faster_than_the_panel_is_not_locked(self): - # 8ms frames on a 100Hz panel: every one lands in the 1-refresh bucket, - # so the miss count is zero, but 125fps is not something a panel at - # 100Hz can present. The swap did not block. - report = analyze([0.008] * 1000, HZ, 1) - assert report.missed == 0 - assert not report.locked - assert not report.passed() - - def test_a_whole_refresh_early_is_counted(self): - report = analyze([PERIOD] * 100, HZ, 2) - assert report.early == 100 - assert not report.locked - - def test_a_loop_stuck_at_half_rate_is_not_locked(self): - # Every frame lands on a whole number of refreshes and the timing is - # perfectly even -- but it is not the hold that was asked for. - report = analyze([2 * PERIOD] * 1000, HZ, 1) - assert not report.locked - assert not report.passed() - - def test_the_verdict_says_so(self): - text = analyze([0.008] * 100, HZ, 1).describe() - assert "NOT LOCKED" in text - assert text.rstrip().endswith("FAIL") - - -class TestDegenerateInput: - def test_no_intervals(self): - report = analyze([], HZ, 1) - assert report.frames == 0 - assert report.missed_percent == 0.0 - assert not report.locked - assert not report.passed() - assert report.describe() == "no frames measured" - - def test_a_refresh_rate_of_zero(self): - report = analyze([PERIOD] * 10, 0.0, 1) - assert report.frames == 0 - assert report.expected_period == 0.0 - assert not report.passed() - - def test_unusable_samples_are_dropped(self): - # A clock that went backwards, or a caller that padded the list. - report = analyze([PERIOD, 0.0, -1.0, None, PERIOD], HZ, 1) - assert report.frames == 2 - - def test_a_hold_below_one_is_treated_as_one(self): - assert analyze([PERIOD] * 10, HZ, 0).frame_hold == 1 - - -class TestTheNumbersReported: - def test_percentiles_are_nearest_rank(self): - samples = [0.001 * n for n in range(1, 101)] - report = analyze(samples, HZ, 1) - assert report.p95 == pytest.approx(0.095) - assert report.p99 == pytest.approx(0.099) - assert report.maximum == pytest.approx(0.100) - assert report.minimum == pytest.approx(0.001) - - def test_seconds_defaults_to_the_span_of_the_run(self): - assert analyze([PERIOD] * 100, HZ, 1).seconds == pytest.approx(1.0) - - def test_seconds_can_be_given_for_a_run_with_gaps(self): - assert analyze([PERIOD] * 100, HZ, 1, seconds=12.5).seconds == 12.5 - - def test_the_report_survives_json(self): - payload = analyze([PERIOD] * 99 + [2 * PERIOD], HZ, 1).as_dict() - restored = json.loads(json.dumps(payload)) - assert restored["missed"] == 1 - assert restored["locked"] is True - assert restored["histogram"] == {"1": 99, "2": 1} - - -class FakePanel: - """A matrix whose swaps block for a fixed period, like real vsync.""" - - def __init__(self, period, fail=False): - self.period = period - self.fail = fail - self.swaps = 0 - - def CreateFrameCanvas(self): - if self.fail: - raise RuntimeError("no hardware here") - return object() - - def SwapOnVSync(self, canvas, framerate_fraction=1): - self.swaps += 1 - time.sleep(self.period) - return canvas - - -class TestMeasuringTheRefreshRate: - def test_times_the_swaps_and_not_the_loop(self): - # The upper bound is the half that carries the meaning: a loop that - # spun without waiting for each swap would report far more than the - # 200Hz a 5ms swap allows. The lower bound is loose on purpose -- - # sleep() under a loaded test runner overshoots, and a slow answer - # here is the runner, not a bug. - measured = measure_refresh_hz(FakePanel(0.005), seconds=0.2) - assert 0 < measured <= 210.0 - - def test_the_first_swap_is_discarded(self): - panel = FakePanel(0.005) - measure_refresh_hz(panel, seconds=0.05) - assert panel.swaps >= 2 - - def test_a_matrix_without_hardware_reports_nothing(self): - assert measure_refresh_hz(FakePanel(0.0, fail=True), seconds=0.1) == 0.0 - - def test_an_object_that_is_not_a_matrix_reports_nothing(self): - assert measure_refresh_hz(object(), seconds=0.1) == 0.0 - - -class TestReadingTheRefreshBackFromTheFrames: - """The panel is slower while the Pi is pushing frames into it. - - Measured on a Pi 4 with a 512x64 chain: 100.4Hz idle, 96.3Hz mid-scroll. - Grading against the idle number is what these tests exist to prevent. - """ - - def test_a_locked_run_reports_its_own_rate(self): - # Intervals clustered just above a 10.38ms period, as a locked loop on - # a panel holding 96.3Hz actually looks. - samples = [0.01038 + 0.00002 * (n % 20) for n in range(500)] - assert refresh_from_intervals(samples, 1) == pytest.approx(96.3, abs=0.5) - - def test_the_hold_is_divided_out(self): - assert refresh_from_intervals([2 * PERIOD] * 500, 2) == pytest.approx(HZ) - - def test_one_short_sample_does_not_set_the_period(self): - # A single 5ms outlier among 10ms frames would, if the minimum were - # used, claim a 200Hz panel and make every real frame a miss. - samples = [0.005] + [PERIOD] * 499 - assert refresh_from_intervals(samples, 1) == pytest.approx(HZ, abs=1.0) - - def test_too_few_samples_to_say(self): - assert refresh_from_intervals([PERIOD] * 5, 1) == 0.0 - assert refresh_from_intervals([], 1) == 0.0 - - def test_the_idle_rate_makes_a_locked_run_look_slow(self): - samples = [0.01038] * 1000 - idle = analyze(samples, 100.4, 1) - assert idle.presented_fps == pytest.approx(96.3, abs=0.1) - assert idle.expected_fps == pytest.approx(100.4) - - loaded = analyze(samples, refresh_from_intervals(samples, 1), 1) - assert loaded.presented_fps == pytest.approx(loaded.expected_fps) - assert loaded.missed == 0 - assert loaded.locked - - def test_a_big_enough_drop_becomes_a_miss_on_every_frame(self): - # Half the idle rate: each frame spans two idle refreshes, so grading - # against idle calls all of them late. Against the rate the panel held, - # none of them are. - samples = [2 * PERIOD] * 1000 - assert analyze(samples, HZ, 1).missed == 1000 - assert analyze(samples, refresh_from_intervals(samples, 1), 1).missed == 0 diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index e45707c3..274bf029 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -301,3 +301,114 @@ def test_watchdog_rate_limits_its_dumps(caplog): dumps = [r for r in caplog.records if r.getMessage().startswith("Render stall:")] assert len(dumps) == 1 assert dog.stalls == 2 + + +# --- measuring the panel, and runs that never locked ------------------------- +# The refresh measurement and the "not locked" cases came from the first +# version of scripts/render_bench.py, which graded runs with its own module. + +class FakePanel: + """A matrix whose swaps block for a fixed period, like real vsync.""" + + def __init__(self, period, fail=False): + self.period = period + self.fail = fail + self.swaps = 0 + + def CreateFrameCanvas(self): # noqa: N802 - mirrors rgbmatrix + if self.fail: + raise RuntimeError("no hardware here") + return object() + + def SwapOnVSync(self, canvas, framerate_fraction=1): # noqa: N802 + self.swaps += 1 + time.sleep(self.period) + return canvas + + +def test_measure_refresh_times_the_swaps_not_the_loop(): + # A loop that spun without waiting for each swap would report far more + # than the 200Hz a 5ms swap allows; the lower bound is loose because + # sleep() on a loaded runner overshoots. + measured = frame_timing.measure_refresh_hz(FakePanel(0.005), seconds=0.2) + assert 0 < measured <= 210.0 + + +def test_measure_refresh_discards_the_first_swap(): + panel = FakePanel(0.005) + frame_timing.measure_refresh_hz(panel, seconds=0.05) + assert panel.swaps >= 2 + + +def test_measure_refresh_without_hardware_reports_nothing(): + assert frame_timing.measure_refresh_hz(FakePanel(0.0, fail=True), seconds=0.1) == 0.0 + assert frame_timing.measure_refresh_hz(object(), seconds=0.1) == 0.0 + + +def _seeded(tmp_path, hz=100.0): + return FrameTimingRecorder(path=str(tmp_path / "s.json"), + flush_interval=float("inf"), refresh_hz=hz) + + +def test_a_seeded_recorder_catches_a_loop_that_never_waited(tmp_path): + # The first bench build free-ran at 827fps once the dirty-tracking skip + # fired mid-scroll. Estimated from its own frames that looks fine; against + # the measured panel rate every frame is early. + r = _seeded(tmp_path) + _feed(r, [0.0012] * 500) + r.drain() + assert r.totals["early_frames"] == 500 + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + + +def test_a_seeded_recorder_catches_a_loop_stuck_at_half_rate(tmp_path): + # Hold 1, but every frame takes two refreshes: self-consistent at 50Hz, + # late on every frame against the panel's 100Hz. + r = _seeded(tmp_path) + _feed(r, [2 * PERIOD] * 500) + r.drain() + assert r.totals["late_frames"] == 500 + + +def test_a_seeded_recorder_still_passes_a_panel_a_little_slower_than_idle(tmp_path): + # 100.4Hz idle, 96.3Hz while rendering: not a single frame is late. + r = _seeded(tmp_path, hz=100.4) + _feed(r, [1 / 96.3] * 500) + r.drain() + assert r.totals["late_frames"] == r.totals["early_frames"] == 0 + + +def test_soak_calls_a_rate_faster_than_the_panel_not_locked(tmp_path): + r = _recorder(tmp_path) + r.info = {"limit_refresh_rate_hz": 100} + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [0.0012] * 500) # unseeded: nothing looks early... + r.drain() + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert report["early_pct"] == 0.0 + assert report["measured_refresh_hz"] > 800 + assert not frame_soak.locked(report, 0.1) # ...but 833Hz beats a 100Hz cap + assert not frame_soak.passed(report, 0.1) + + +def test_soak_reports_the_rate_held_while_rendering(tmp_path): + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [1 / 96.3] * 500) + r.drain() + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert 95.0 <= report["held_refresh_hz"] <= 97.0 + + +def test_render_bench_strip_lights_a_real_share_of_pixels(): + # How long SetImage takes depends on how many subpixels are lit; a mostly + # dark strip would flatter the panel. + import render_bench + strip = render_bench.build_strip(128, 32, "test") + assert strip.width >= 128 * 4 + lit = sum(1 for px in strip.getdata() if px != (0, 0, 0)) + assert lit / (strip.width * strip.height) > 0.05 From b67818d5c5d2a63e32d84b488c3fdceb58386f27 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 14:26:04 -0400 Subject: [PATCH 7/8] feat(perf): LEDMATRIX_STALL_WATCHDOG_MS lowers the stall watchdog's threshold 250ms catches freezes; the hitches left on hdpi are frames 2-5 refreshes late, which look like the render thread waiting for the GIL. At 30ms the watchdog dumps those too, naming what the other threads were running when the frame missed. It polls at a third of the threshold so a stall one poll long is still seen, which costs some GIL time of its own: a diagnostic setting, not one to soak with. Co-Authored-By: Claude Opus 5.5 --- docs/SCROLL_PERFORMANCE.md | 9 +++++++++ src/common/frame_timing.py | 24 ++++++++++++++++++++++-- test/test_frame_timing.py | 20 ++++++++++++++++++++ 3 files changed, 51 insertions(+), 2 deletions(-) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 904191df..67788396 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -349,6 +349,15 @@ A soak is only meaningful against a fixed workload. Compare runs with the same content and `--preview` setting, and alternate which build goes first when you A/B two of them. A live-API workload drifts over time. +The soak says how often; the service's log says why. A scroll that presents no +frame for 250 ms logs `Render stall:` with the stack of the render thread and +the top of every other thread's, and whether the whole interpreter was blocked +(C code holding the GIL) rather than one thread. To see what is behind the +shorter hitches, run the service with `LEDMATRIX_STALL_WATCHDOG_MS=30`, which +dumps at three refreshes late instead: its extra polling costs a little GIL +time of its own, so do that on a diagnostic run, not a soak you are grading. +`LEDMATRIX_STALL_WATCHDOG=0` turns it off. + ### Results: hdpi, 2026-09-24 Pi 4, 4×128×64 on one chain (512×64), `gpio_slowdown` 3, cap 120 Hz, the diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 3e94b6fe..2c151f3a 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -62,7 +62,10 @@ top of every other thread's, so the log names what the render thread was waiting on. It also measures how late its own wake-up was: if the watchdog was held up as long as the render thread, the whole interpreter was blocked (C code holding the GIL, or the process not scheduled), not one thread on a lock. -Set ``LEDMATRIX_STALL_WATCHDOG=0`` to turn it off. +Set ``LEDMATRIX_STALL_WATCHDOG=0`` to turn it off, or +``LEDMATRIX_STALL_WATCHDOG_MS`` to dump at a lower threshold -- 30 catches +frames three refreshes late, which is where GIL contention shows. It polls +three times per threshold, so keep it to diagnostic runs, not soaks. """ from __future__ import annotations @@ -283,7 +286,7 @@ class FrameTimingRecorder: self._static_frames += 1 elif self.watchdog is None and self.scrolling_now is not None \ and os.environ.get("LEDMATRIX_STALL_WATCHDOG", "1") != "0": - self.watchdog = StallWatchdog(self) + self.watchdog = StallWatchdog(self, **watchdog_settings()) self.watchdog.start() elif previous is not None and previous[1]: interval = presented_at - previous[0] @@ -417,6 +420,23 @@ class FrameTimingRecorder: raise +def watchdog_settings() -> Dict[str, float]: + """StallWatchdog arguments from ``LEDMATRIX_STALL_WATCHDOG_MS``, if set. + + The poll comes down with the threshold, or a stall shorter than one poll + would go unseen. + """ + try: + ms = float(os.environ.get("LEDMATRIX_STALL_WATCHDOG_MS") or 0) + except ValueError: + ms = 0.0 + if ms <= 0: + return {} + threshold = ms / 1000.0 + return {"threshold": threshold, + "poll": min(WATCHDOG_POLL_SECONDS, threshold / 3)} + + class StallWatchdog: """Log what the render thread is doing when a scroll stops presenting. diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index 274bf029..c2f27b62 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -9,6 +9,8 @@ import sys import time from pathlib import Path +import pytest + sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) from src.common import frame_timing # noqa: E402 @@ -303,6 +305,24 @@ def test_watchdog_rate_limits_its_dumps(caplog): assert dog.stalls == 2 +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() == {} + monkeypatch.setenv("LEDMATRIX_STALL_WATCHDOG_MS", "nonsense") + assert frame_timing.watchdog_settings() == {} + monkeypatch.setenv("LEDMATRIX_STALL_WATCHDOG_MS", "30") + settings = frame_timing.watchdog_settings() + assert settings["threshold"] == pytest.approx(0.030) + assert settings["poll"] == pytest.approx(0.010) # sees a stall one poll long + + # ...and the recorder starts its watchdog with them. + rec = frame_timing.FrameTimingRecorder(path=None) + rec.scrolling_now = lambda: True + monkeypatch.setattr(frame_timing.StallWatchdog, "start", lambda self: None) + rec.record(0.001, 0.009, 1, True, 1.0) + assert rec.watchdog.threshold == pytest.approx(0.030) + + # --- measuring the panel, and runs that never locked ------------------------- # The refresh measurement and the "not locked" cases came from the first # version of scripts/render_bench.py, which graded runs with its own module. From 14c38a3189b6100a2f9eaf5d347261c138d619d2 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 24 Sep 2026 15:23:18 -0400 Subject: [PATCH 8/8] fix(perf): count a stall even when the scroll state went missing across it On hdpi the stall watchdog logged a 1.9s stall during the hourly sports refresh that the soak report never had: its worst gap was 655ms. The frame that ended the stall was recorded as static, so its interval was dropped. "Scrolling" is DisplayManager's scroll state at the moment a frame is presented, and it goes missing mid-scroll: it expires after 2s without activity, and any thread can clear it. Plugins call set_scrolling_state(False) from their own display() (news, stocks, the odds ticker's fallback), and Vegas captures some of those on the render thread between two of its own frames. Vegas sets the state again only after its next frame, so that frame is recorded as static -- along with the capture or stall it followed. One static frame between two scrolling frames, with the scroll resuming within RESUME_SECONDS (1s), is now a frame of the scroll and both of its intervals count, the first at the scroll's own hold (clearing the state drops the hold to 1 too). Two static frames in a row still end the scroll. Co-Authored-By: Claude Opus 5.5 --- docs/SCROLL_PERFORMANCE.md | 2 +- src/common/frame_timing.py | 47 +++++++++++++++++++++++---- test/test_frame_timing.py | 66 ++++++++++++++++++++++++++++++++++++++ 3 files changed, 108 insertions(+), 7 deletions(-) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 67788396..a35d642c 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. | +| **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. | | **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/src/common/frame_timing.py b/src/common/frame_timing.py index 2c151f3a..9a39290b 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -19,6 +19,19 @@ Only intervals between two consecutive *scrolling* frames count: a static screen that changes once a second has no timing to get wrong, and the first frame of a scroll has no predecessor worth measuring against. +"Scrolling" is DisplayManager's scroll state when the frame is presented, and +that state can go missing in the middle of a scroll. It expires after 2s +without scroll activity, which a long enough stall outlasts, and any thread can +clear it: plugins call ``set_scrolling_state(False)`` from their own +``display()``, and Vegas captures some of those on the render thread between +two of its frames. The frame after that is recorded as static, and the interval +it ends -- the stall, or the capture -- would vanish from the report. So a +single static frame between two scrolling ones, with the scroll picking up +again within ``RESUME_SECONDS``, is treated as a frame of the scroll: both of +its intervals count. A second static frame in a row means the scroll really +ended. (On hdpi on 2026-09-24 the watchdog logged a 1.9s stall that the soak +report did not have; this is how.) + A frame held for ``hold`` refreshes should arrive ``hold`` refresh periods after the one before it. One that arrives a whole refresh or more after that is **late**: the panel showed the previous frame again, which on a moving strip is @@ -94,12 +107,16 @@ BUCKET_COUNT = 256 #: See the module docstring. FREEZE_SECONDS = 0.25 -#: Two frames that are both "scrolling" can be at most DisplayManager's -#: scroll_inactivity_threshold (2s) apart: after that the second is recorded -#: as static. This used to be 1s, which silently dropped every 1-2s stall -#: inside a scroll. It is now only a sanity bound. +#: Intervals this long are not frames of one scroll. This used to be 1s, +#: which silently dropped every 1-2s stall inside a scroll. It is now only a +#: sanity bound. GAP_SECONDS = 5.0 +#: A frame recorded as static between two scrolling frames is a frame of the +#: scroll whose state went missing, if the scroll resumes within this long. +#: See "What is counted". +RESUME_SECONDS = 1.0 + #: Buckets for freeze length, as cumulative counters a soak can difference. FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"), (float("inf"), "2s+")) @@ -232,6 +249,9 @@ class FrameTimingRecorder: self._pending: List[Tuple[float, float, float, int]] = [] self._static_frames = 0 self._previous: Optional[Tuple[float, bool, int]] = None + # The interval ended by a static frame that followed a scrolling one, + # until the next frame shows whether the scroll went on. + self._unsure: Optional[Tuple[float, float, float, int]] = None self._last_flush: Optional[float] = None self._queue: "queue.SimpleQueue" = queue.SimpleQueue() self._worker: Optional[threading.Thread] = None @@ -284,13 +304,28 @@ class FrameTimingRecorder: self.last_frame = (presented_at, scrolling, threading.get_ident()) if not scrolling: self._static_frames += 1 + # The scroll ended, or its state went missing for this frame: the + # next frame says which. Its hold may have been dropped with the + # state, so the interval is due at the scroll's own. + self._unsure = None + if previous is not None and previous[1]: + self._unsure = (presented_at - previous[0], blit, wait, previous[2]) elif self.watchdog is None and self.scrolling_now is not None \ and os.environ.get("LEDMATRIX_STALL_WATCHDOG", "1") != "0": self.watchdog = StallWatchdog(self, **watchdog_settings()) self.watchdog.start() - elif previous is not None and previous[1]: + elif previous is not None: interval = presented_at - previous[0] - if interval < GAP_SECONDS: + unsure, self._unsure = self._unsure, None + if previous[1]: + if interval < GAP_SECONDS: + self._pending.append((interval, blit, wait, hold)) + elif unsure is not None and interval < RESUME_SECONDS: + # One static frame between two scrolling ones: the scroll never + # stopped, only its state did. Both intervals were motion. + self._static_frames -= 1 + if unsure[0] < GAP_SECONDS: + self._pending.append(unsure) self._pending.append((interval, blit, wait, hold)) if self._last_flush is None: diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index c2f27b62..f3238212 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -121,6 +121,72 @@ def test_a_stall_between_one_and_two_seconds_is_not_lost(tmp_path): assert _aggregate(r)["freezes"] == 1 +def test_a_stall_whose_scroll_state_went_missing_still_counts(tmp_path): + # hdpi, 14:48: the watchdog logged a 1.9s stall the soak never reported. + # A plugin captured between two Vegas frames cleared the scroll state, so + # the frame that ended the stall was recorded as static and its interval + # dropped. Vegas set the state again right after, as it does every frame. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t += 1.911 + r.record(0.002, 0.004, 1, False, t) # state missing: "static" + _feed(r, [PERIOD] * 100, start=t + PERIOD) # the scroll carries on + totals = _aggregate(r) + assert totals["freezes"] == 1 + assert totals["freeze_by"]["1-2s"] == 1 + assert totals["static_frames"] == 0 + # 100 before, the step back into the scroll, 100 after: all but the freeze. + assert totals["scroll_frames"] == 100 + 1 + 100 + + +def test_a_frame_with_its_scroll_state_missing_is_still_timed(tmp_path): + # No stall at all -- the state was cleared and the frame went out on + # time. Nothing is late and no interval is lost. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + PERIOD) + _feed(r, [PERIOD] * 100, start=t + 2 * PERIOD) + totals = _aggregate(r) + assert totals["scroll_frames"] == 202 + assert totals["late_frames"] == totals["freezes"] == totals["static_frames"] == 0 + + +def test_a_scroll_that_really_ended_is_not_a_freeze(tmp_path): + # Two static frames in a row, then a new scroll: the gaps between them + # were a static screen, not a stall. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t = _feed(r, [0.5], scrolling=False, start=t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.4) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 2 + assert totals["scroll_frames"] == 200 + + +def test_one_static_frame_then_a_scroll_much_later_is_a_new_scroll(tmp_path): + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.3 + frame_timing.RESUME_SECONDS + 0.1) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 1 + assert totals["scroll_frames"] == 200 + + +def test_a_missing_state_interval_is_due_at_the_scrolls_own_hold(tmp_path): + # Clearing the state drops the hold to 1 as well, so the "static" frame + # reports hold 1. Its interval is still due two refreshes after the last. + r = _recorder(tmp_path) + t = _feed(r, [2 * PERIOD] * 100, hold=2) + r.record(0.002, 0.004, 1, False, t + 2 * PERIOD) + _feed(r, [2 * PERIOD] * 100, hold=2, start=t + 4 * PERIOD) + totals = _aggregate(r) + assert totals["late_frames"] == totals["early_frames"] == 0 + assert totals["scroll_frames"] == 202 + + def test_early_frames_are_counted(tmp_path): # Hold 2 on a 100Hz panel: frames are due every 20ms. A swap that returns # after 10ms did not wait out the hold.