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

refactor(bench): grade render_bench with the shared frame-timing recorder

Browse Source 
render_bench.py (from the parallel perf/render-bench work) had its own
grading module, frame_pacing, with its own definition of a missed frame
and its own refresh estimate. The soak already had both in frame_timing,
so the two could have drifted apart on what "late" means.

The bench now gives the display manager a fresh FrameTimingRecorder,
drains it synchronously at the start and end of the graded run, and prints
frame_soak's report with frame_soak's verdict. Its workload is unchanged:
the synthetic strip, --busy load, the shared speed resolver, the
per-frame scrolling announcement. frame_pacing, its tests and its
src.common exports are removed; measure_refresh_hz moves to frame_timing,
where scroll_speeds.py now finds it.

Two ideas from frame_pacing carry over. The bench seeds the recorder with
the idle refresh it measures, so a loop that free-runs (the 827fps bug
the first bench caught) shows as early frames and one stuck at half rate
as late frames, where an estimate taken from their own intervals finds
both self-consistent. And the soak, which has no idle measurement, now
calls a run NOT LOCKED when its refresh estimate beats the configured cap.
The report also gives the rate held while rendering.

Docs: the bench becomes "Without the service" under "Soaking a rig",
keeping its hdpi numbers and the idle-vs-rendering refresh finding.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Chuck
2026-09-24 11:56:44 -04:00
co-authored by Claude Opus 5.5
parent d56ec2ab3a
commit f79618d4f7
10 changed files with 377 additions and 731 deletions
Download Patch File Download Diff File Expand all files Collapse all files
CHANGELOG.md
+8 -10
View File
@@ -19,16 +19,14 @@ accepts both, but the store flags the old spelling as deprecated
## Unreleased ## Unreleased
- `src.common.frame_pacing` — grades a run of presented frames against the - `src.common.frame_timing` -- times every frame the display presents, whoever
panel's real refresh rate: how many slipped a whole refresh, and whether the drew it, and writes cumulative counters to `/dev/shm`. Two tools read it:
loop was locked to the panel at all. `scripts/render_bench.py` drives a real `scripts/frame_soak.py` judges a running service (late frames, freezes,
`DisplayManager`/`ScrollHelper` scroll through it and exits non-zero when a where the time goes), and `scripts/render_bench.py` judges the hardware and
rig misses more than 0.1% of frames, so a rig can be measured before a render path alone on a synthetic strip. Both fail a run above 0.1% late
release rather than eyeballed. The panel's refresh is read back out of the frames, and both call a loop that never waited for the panel NOT LOCKED. A
frames rather than taken from the idle measurement: a Pi 4 driving 512x64 stall watchdog logs the stack of whatever holds a scroll up for 250 ms or
holds 100.4Hz idle and 96.3Hz while rendering, and grading against the idle more. See `docs/SCROLL_PERFORMANCE.md`, "Soaking a rig".
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 - `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 a size the file doesn't contain (5x7.bdf at 8 or 10px, say). It used to
docs/SCROLL_PERFORMANCE.md
+46 -67
View File
@@ -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, - 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. 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 The soak measures the service as it really runs: live content, plugin
was also happening. `scripts/render_bench.py` answers the narrower question a updates, the web preview. `scripts/render_bench.py` answers the narrower
release has to answer per rig: *with nothing else in the way, can this hardware question underneath: *with nothing else in the way, can this hardware present
present every frame on time?* It drives the production path -- a real every frame on time?* It scrolls a synthetic strip through the production path
`DisplayManager`, a real `ScrollHelper`, the same `scroll_config` resolver every -- a real `DisplayManager`, a real `ScrollHelper`, the same `scroll_config`
ticker uses -- so a regression in any of them shows up here. 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 ```bash
sudo systemctl stop ledmatrix # the service owns the GPIO 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 sudo systemctl start ledmatrix
``` ```
It never starts or stops the service itself, for the same reason It never starts or stops the service itself, so a crash in it cannot leave
`scroll_speeds.py` does not: a crash in a script must not be able to leave the the panel dark. It grades with the same recorder as the soak and prints the
panel dark. Exit status is 0 for a pass, 1 for a fail, and **2 when the run 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 could not be set up at all (no root, no panel, a fallback display), so a rig
rig that was never measured can never be mistaken for one that passed. 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.
``` Measured with the first version of the bench on hdpi (Pi 4, 512x64,
measuring the panel for 4s... `pwm_bits` 8), two-minute runs at one pixel per refresh: 8 of 11,449 frames
panel refreshes at 100.4Hz (cap is 120Hz) late (0.070%), and with `--busy 2` 3 of 11,445 (0.026%). The render path and
asked for 100.4 px/s -> 100.4 px/s (1px every 1 refresh = 100.4 fps, smooth) the hardware pass on their own. Compare the soak results above, from the same
scrolling 512x64 for 120s ... rig with the service running, for how much of the late rate comes from
everything else.
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 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 | | | 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 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. `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 The recorder therefore reads the rendering rate back from the frames: swaps
100.4 and looks broken; once the gap passes half a refresh period, every single that block on vsync can only return on a refresh boundary, so the low end of
frame is counted as a miss. The give-away that nothing is actually being missed `interval / frame_hold` is the period. The idle figure is still printed,
is that the intervals cluster tightly around 10.46 ms instead of splitting because the gap between the two is itself a measure of how expensive a frame
between 9.96 ms and 19.92 ms, which is what missing every twenty-fifth vsync is: **a rise in that gap is a render-cost regression even when nothing is
would look like. late.**
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 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 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 speeds against a refresh that does not exist, which is where "3px every 4
refreshes" comes from. refreshes" comes from.
### Other counters ### Bench-only counters
| line | meaning | | 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. | | `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. | | `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. | | `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 `--json` writes the full report plus the panel geometry, the solved speed and
solved, so two rigs (or one rig before and after a change) can be compared these counters, so two rigs (or one rig before and after a change) can be
without re-reading a terminal. compared without re-reading a terminal.
## Rebuilding the binding ## Rebuilding the binding
scripts/frame_soak.py
+52 -6
View File
@@ -132,7 +132,7 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
frames = totals["scroll_frames"] frames = totals["scroll_frames"]
hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0 hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0
bucket_ms = after.get("bucket_ms", 0.25) bucket_ms = after.get("bucket_ms", 0.25)
return { report = {
"seconds": round(delta["seconds"], 1), "seconds": round(delta["seconds"], 1),
"preview": preview, "preview": preview,
"info": after.get("info"), "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) "timing_ms": {name: percentiles(h, bucket_ms)
for name, h in delta["histograms"].items()}, 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: 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: if report["late_pct"] is None:
print("RESULT nothing scrolled - no verdict") print("RESULT nothing scrolled - no verdict")
elif not locked(report, limit): elif not locked(report, limit):
print(f"RESULT FAIL NOT LOCKED: {report['early_pct']}% of frames came a " ceiling = refresh_ceiling(report)
"refresh early, so the swaps were not waiting for the panel and " if (report.get("early_pct") or 0.0) > limit:
"the late count means nothing") 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: elif report["late_pct"] <= limit:
print(f"RESULT PASS {report['late_pct']}% late <= {limit}%") print(f"RESULT PASS {report['late_pct']}% late <= {limit}%")
else: else:
print(f"RESULT FAIL {report['late_pct']}% late > {limit}%") 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: def locked(report: Dict[str, Any], limit: float) -> bool:
"""Whether the loop was paced by the panel at all.""" """Whether the loop was paced by the panel at all.
return (report.get("early_pct") or 0.0) <= limit
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: def passed(report: Dict[str, Any], limit: float) -> bool:
scripts/render_bench.py
+88 -56
View File
@@ -4,9 +4,17 @@
The question this answers is the one that decides whether a rig ships: *does 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 every frame present on the refresh it was meant to?* It drives the production
path -- a real ``DisplayManager`` and ``ScrollHelper``, the same crisp speed path -- a real ``DisplayManager`` and ``ScrollHelper``, the same crisp speed
resolver every ticker uses -- scrolls for a while, and grades the result with resolver every ticker uses -- scrolls a synthetic strip for a while, and grades
``src.common.frame_pacing``. A run passes when the loop was genuinely locked to it with the same frame-timing recorder the display service uses
the panel and fewer than ``--max-missed`` percent of frames slipped a refresh. (``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 # stop the service first; it owns the GPIO
sudo systemctl stop ledmatrix sudo systemctl stop ledmatrix
@@ -40,7 +48,10 @@ from pathlib import Path
sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) 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 REPO = Path(__file__).resolve().parent.parent
CONFIG = REPO / "config" / "config.json" 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. #: has to settle, but every second here is a second not scrolling.
MEASURE_SECONDS = 4.0 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: def load_config() -> dict:
"""The config the display service would run with.""" """The config the display service would run with."""
@@ -163,6 +178,7 @@ class BackgroundLoad:
zlib.compress(image.tobytes(), 1) zlib.compress(image.tobytes(), 1)
def main(argv=None) -> int: def main(argv=None) -> int:
parser = argparse.ArgumentParser( parser = argparse.ArgumentParser(
description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
@@ -174,15 +190,13 @@ def main(argv=None) -> int:
"panel can show in whole pixels (default: one pixel " "panel can show in whole pixels (default: one pixel "
"per refresh)") "per refresh)")
parser.add_argument("--hz", type=float, default=None, parser.add_argument("--hz", type=float, default=None,
help="skip the measurement and grade against this refresh " help="skip the idle measurement and take this as the "
"rate instead (for reproducing a rig's numbers)") "panel's rate (for reproducing a rig's numbers)")
parser.add_argument("--busy", type=int, default=0, metavar="N", parser.add_argument("--busy", type=int, default=0, metavar="N",
help="run N background workers imitating plugin updates") help="run N background workers imitating plugin updates")
parser.add_argument("--max-missed", type=float, parser.add_argument("--max-late-pct", "--max-missed", dest="max_late_pct",
default=frame_pacing.DEFAULT_MAX_MISSED_PERCENT, type=float, default=0.1, metavar="PCT",
metavar="PCT", help="fail above this percentage of late frames (default 0.1)")
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", parser.add_argument("--json", dest="json_path", default=None, metavar="PATH",
help="also write the report as JSON, for comparing rigs") help="also write the report as JSON, for comparing rigs")
parser.add_argument("--label", default=None, parser.add_argument("--label", default=None,
@@ -190,8 +204,10 @@ def main(argv=None) -> int:
args = parser.parse_args(argv) args = parser.parse_args(argv)
# Everything the display service logs would otherwise land in the middle of # 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.basicConfig(level=logging.ERROR, stream=sys.stderr)
logging.getLogger("src.common.frame_timing").setLevel(logging.WARNING)
if hasattr(os, "geteuid") and os.geteuid() != 0: if hasattr(os, "geteuid") and os.geteuid() != 0:
print("this needs root for GPIO access - rerun with sudo", file=sys.stderr) 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 width, height = display.width, display.height
if args.hz is not None: if args.hz is not None:
refresh_hz = float(args.hz) idle_hz = float(args.hz)
print(f"grading against {refresh_hz:.1f}Hz (given, not measured)") print(f"taking the panel's rate as {idle_hz:.1f}Hz (given, not measured)")
else: else:
print(f"measuring the panel for {MEASURE_SECONDS:.0f}s...", flush=True) print(f"measuring the panel for {MEASURE_SECONDS:.0f}s...", flush=True)
refresh_hz = frame_pacing.measure_refresh_hz(display.matrix, MEASURE_SECONDS) idle_hz = frame_timing.measure_refresh_hz(display.matrix, MEASURE_SECONDS)
if refresh_hz <= 0: if idle_hz <= 0:
print("the panel did not answer a swap; cannot measure it", print("the panel did not answer a swap; cannot measure it",
file=sys.stderr) file=sys.stderr)
return 2 return 2
cap = scroll_config.refresh_hz_from_config(config) 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)") 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 # 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 # up by hand, so the benchmark measures the engine every ticker runs on. A
@@ -244,7 +260,7 @@ def main(argv=None) -> int:
helper, helper,
plugin_config={"scroll_pixels_per_second": requested}, plugin_config={"scroll_pixels_per_second": requested},
global_config=config, global_config=config,
refresh_hz=refresh_hz, refresh_hz=idle_hz,
display_manager=display, display_manager=display,
) )
choice = settings.crisp choice = settings.crisp
@@ -258,20 +274,42 @@ def main(argv=None) -> int:
helper.set_scrolling_image( helper.set_scrolling_image(
build_strip(width, height, f"{choice.pixels_per_second:.0f} px/s")) 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" print(f"scrolling {width}x{height} for {args.seconds:.0f}s"
+ (f" with {args.busy} background worker(s)" if args.busy else "") + (f" with {args.busy} background worker(s)" if args.busy else "")
+ " ...", flush=True) + " ...", flush=True)
intervals: list = [] frames = 0
duplicates = 0 duplicates = 0
blanks = 0 blanks = 0
restarts = 0 restarts = 0
last_column = None last_column = None
before = None
started = time.perf_counter() started = time.perf_counter()
previous = None run_started = None
try: try:
with BackgroundLoad(args.busy): 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() helper.update_scroll_position()
if helper.is_scroll_complete(): if helper.is_scroll_complete():
# The helper parks at the end of the strip and stops # 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. # Every ticker re-announces per frame; so does this.
display.set_scrolling_state(True, frame_hold=choice.frame_hold) display.set_scrolling_state(True, frame_hold=choice.frame_hold)
display.update_display() display.update_display()
now = time.perf_counter() frames += 1
if previous is not None:
intervals.append(now - previous)
previous = now
except KeyboardInterrupt: except KeyboardInterrupt:
print("\ninterrupted - reporting what was measured so far") print("\ninterrupted - reporting what was measured so far")
finally: finally:
elapsed = time.perf_counter() - started
display.set_scrolling_state(False) display.set_scrolling_state(False)
try: try:
display.clear() display.clear()
except Exception: except Exception:
pass pass
# The panel does not refresh at its idle rate while the Pi is also pushing if before is None:
# frames into it; see frame_pacing.refresh_from_intervals. Grading against print("interrupted during warm-up; nothing was graded", file=sys.stderr)
# the idle number reports misses a locked loop never had, so the rate the return 2
# panel actually held during the scroll is read back from the frames. recorder.drain()
idle_hz = refresh_hz report = frame_soak.build_report(before, recorder.snapshot(), preview=False)
loaded_hz = frame_pacing.refresh_from_intervals(intervals, choice.frame_hold) report["idle_refresh_hz"] = round(idle_hz, 2)
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() print()
if loaded_hz > 0: frame_soak.print_report(report, args.max_late_pct)
drop = 100.0 * (idle_hz - loaded_hz) / idle_hz held = report.get("held_refresh_hz")
print(f"panel held {loaded_hz:.1f}Hz while rendering " if held:
f"({drop:.1f}% below its {idle_hz:.1f}Hz idle rate)") drop = 100.0 * (idle_hz - held) / idle_hz
print(report.describe(args.max_missed)) 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: if duplicates:
# A frame that shows the same columns as the one before it is work the # 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 -- # 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. # but it means the loop is presenting faster than the strip is moving.
print(f" duplicate {duplicates} frames advanced no pixels " print(f"duplicate {duplicates} frames advanced no pixels "
f"({100.0 * duplicates / max(1, len(intervals)):.2f}%)") f"({100.0 * duplicates / max(1, frames):.2f}%)")
if blanks: 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: 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 ''})") f"{restarts} time{'s' if restarts != 1 else ''})")
if args.json_path: if args.json_path:
payload = report.as_dict() report.update({
payload.update({
"label": args.label or os.uname().nodename, "label": args.label or os.uname().nodename,
"width": width, "bench": True,
"height": height,
"requested_pixels_per_second": requested, "requested_pixels_per_second": requested,
"pixels_per_second": choice.pixels_per_second, "pixels_per_second": choice.pixels_per_second,
"pixels_per_frame": choice.pixels_per_frame, "pixels_per_frame": choice.pixels_per_frame,
"frame_hold": choice.frame_hold,
"busy_workers": args.busy, "busy_workers": args.busy,
"duplicate_frames": duplicates, "duplicate_frames": duplicates,
"blank_frames": blanks, "blank_frames": blanks,
"strip_restarts": restarts, "strip_restarts": restarts,
"idle_refresh_hz": idle_hz, "max_late_pct": args.max_late_pct,
"loaded_refresh_hz": loaded_hz, "passed": frame_soak.passed(report, args.max_late_pct),
"max_missed_percent": args.max_missed,
"passed": report.passed(args.max_missed),
}) })
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") encoding="utf-8")
print(f"\nwrote {args.json_path}") 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__": if __name__ == "__main__":
scripts/scroll_speeds.py
+4 -4
View File
@@ -42,7 +42,7 @@ from pathlib import Path
sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) 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" 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 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 whatever limit_refresh_rate_hz optimistically asks for. The timing loop
itself lives in src.common.frame_pacing so the benchmark grades a soak itself lives in src.common.frame_timing so the benchmark grades against
against the same measurement this ladder is built from. the same measurement this ladder is built from.
""" """
matrix = open_matrix(config, refresh_override=0) 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() matrix.Clear()
return measured return measured
src/common/__init__.py
+1 -5
View File
@@ -11,14 +11,13 @@ This package provides reusable functionality for plugins and core modules:
# Export commonly used utilities # Export commonly used utilities
from src.common.api_helper import APIHelper from src.common.api_helper import APIHelper
from src.common.scroll_helper import ScrollHelper 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 ( from src.common.scroll_config import (
ScrollSettings, ScrollSettings,
configure as configure_scroll, configure as configure_scroll,
resolve as resolve_scroll_settings, resolve as resolve_scroll_settings,
refresh_hz_from_config, 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.logo_helper import LogoHelper
from src.common.text_helper import TextHelper from src.common.text_helper import TextHelper
@@ -51,9 +50,6 @@ __all__ = [
'APIHelper', 'APIHelper',
'ScrollHelper', 'ScrollHelper',
'scroll_config', 'scroll_config',
'frame_pacing',
'PacingReport',
'analyze_frame_pacing',
'ScrollSettings', 'ScrollSettings',
'configure_scroll', 'configure_scroll',
'resolve_scroll_settings', 'resolve_scroll_settings',
src/common/frame_pacing.py
-331
View File
@@ -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
src/common/frame_timing.py
+67 -1
View File
@@ -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 not jump like that; swaps that stopped blocking do, and adopting their period
would make every early frame look on time. 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 Stall watchdog
-------------- --------------
Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the
@@ -155,6 +163,45 @@ def _pi_model() -> Optional[str]:
return None 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: class FrameTimingRecorder:
"""Collects per-frame timings on the render thread; aggregates elsewhere. """Collects per-frame timings on the render thread; aggregates elsewhere.
@@ -167,7 +214,13 @@ class FrameTimingRecorder:
path: Optional[str] = None, path: Optional[str] = None,
flush_interval: float = FLUSH_INTERVAL, flush_interval: float = FLUSH_INTERVAL,
info: Optional[Dict[str, Any]] = None, 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.path = path or default_stats_path()
self.flush_interval = flush_interval self.flush_interval = flush_interval
self.info = dict(info or {}) self.info = dict(info or {})
@@ -182,7 +235,8 @@ class FrameTimingRecorder:
# Worker-thread state. Nothing on the render thread reads these. # Worker-thread state. Nothing on the render thread reads these.
self.started = time.time() 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] = { self.totals: Dict[str, Any] = {
"static_frames": 0, "static_frames": 0,
"scroll_frames": 0, "scroll_frames": 0,
@@ -251,6 +305,18 @@ class FrameTimingRecorder:
target=self._run, daemon=True, name="frame-timing") target=self._run, daemon=True, name="frame-timing")
self._worker.start() 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 ------------------------------------------------------ # -- worker thread ------------------------------------------------------
def _run(self) -> None: def _run(self) -> None:
test/test_frame_pacing.py
-251
View File
@@ -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
test/test_frame_timing.py
+111
View File
@@ -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:")] dumps = [r for r in caplog.records if r.getMessage().startswith("Render stall:")]
assert len(dumps) == 1 assert len(dumps) == 1
assert dog.stalls == 2 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