rick/LEDMatrix
1
0
Fork 0
mirror of https://github.com/ChuckBuilds/LEDMatrix.git synced 2026-10-10 17:16:36 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(bench): measure a rig against the refresh it actually holds

Browse Source 
There was no way to answer "does this hardware present every frame on
time?" other than watching the panel. `scripts/render_bench.py` drives the
production path -- a real DisplayManager and ScrollHelper, configured
through the same `scroll_config` resolver every ticker uses -- and grades
the run with a new `src.common.frame_pacing`, exiting non-zero when more
than 0.1% of frames slipped a refresh. Exit 2 when the run could not be set
up at all, so a rig that was never measured cannot pass by accident.

A missed frame is defined exactly: an interval that rounds up to at least
one more refresh than its frame hold asked for. The half-refresh rounding
boundary keeps a frame that ran 1ms long on a 10ms refresh out of the
count, because it still presented on the refresh it was meant to.

The verdict that matters more is NOT LOCKED. A loop that never blocked on
vsync reports a perfect zero misses while presenting nothing -- 8ms frames
on a 100Hz panel all land in the one-refresh bucket while running 25% too
fast -- so the report also checks the typical frame is not shorter than the
panel could physically present. That is what caught the first version of
this benchmark announcing its scrolling state once instead of per frame:
the state expires on an inactivity threshold, the dirty-tracking skip then
fires mid-scroll, and the loop free-ran at 827fps.

And the refresh is read back out of the frames rather than taken from an
idle measurement. Driving the matrix is bit-banging on the same machine, so
pushing frames slows the refresh: a Pi 4 on 512x64 measures 100.4Hz idle
and holds 96.3Hz while scrolling. Both are real, and grading against the
idle figure reports a locked loop as 4% slow -- or, once the gap passes
half a refresh, as missing every frame. The gap between the two is itself
worth watching: a rise in it is a render-cost regression even when nothing
is missed.

Measured on hdpi (Pi 4, 512x64, pwm_bits 8), two minutes each:

  plain      95.44 fps, 8 missed of 11,449 (0.070%)  PASS
  --busy 2   95.41 fps, 3 missed of 11,445 (0.026%)  PASS

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014RRtqXDCnvnY6EQwhT5CV9
This commit is contained in:
ChuckBuilds
2026-09-24 11:08:43 -04:00
committed by Chuck
co-authored by Claude Opus 5
parent c883a2fd1e
commit d56ec2ab3a
7 changed files with 1083 additions and 14 deletions
Download Patch File Download Diff File Expand all files Collapse all files
CHANGELOG.md
+11
View File
@@ -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
docs/SCROLL_PERFORMANCE.md
+108
View File
@@ -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
scripts/render_bench.py
Executable
+371
View File
@@ -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())
scripts/scroll_speeds.py
+6 -13
View File
@@ -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
src/common/__init__.py
+5 -1
View File
@@ -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',
src/common/frame_pacing.py
+331
View File
@@ -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
test/test_frame_pacing.py
+251
View File
@@ -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