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