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