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