diff --git a/CHANGELOG.md b/CHANGELOG.md index 761676fc..5a828b38 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -257,6 +257,15 @@ floor on the release that ships them): `api_extractors`). No known plugin imports it. A plugin that does must use `src.common` or its own copy of the code. +- `src.common.frame_timing` -- times every frame the display presents, whoever + drew it, and writes cumulative counters to `/dev/shm`. Two tools read it: + `scripts/frame_soak.py` judges a running service (late frames, freezes, + where the time goes), and `scripts/render_bench.py` judges the hardware and + render path alone on a synthetic strip. Both fail a run above 0.1% late + frames, and both call a loop that never waited for the panel NOT LOCKED. A + stall watchdog logs the stack of whatever holds a scroll up for 250 ms or + more. See `docs/SCROLL_PERFORMANCE.md`, "Soaking a rig". + ## 3.5.0 New modules a plugin may import via `src.*` (floor on 3.5.0): diff --git a/CLAUDE.md b/CLAUDE.md index e5bb33b0..c0805ca1 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -37,6 +37,7 @@ - Browser preview without the display loop: `python3 scripts/dev_server.py` → http://localhost:5001 - Full display in emulator mode: `python3 run.py -e` (or `EMULATOR=true python3 run.py`) - Validate one plugin headlessly: `python3 scripts/check_plugin.py --plugin ` +- Soak a rig for frame timing (on the Pi, service running): `python3 scripts/frame_soak.py --preview` — late-frame rate across every scroller; see `docs/SCROLL_PERFORMANCE.md` ## Plugin Store Architecture - Official plugins live in the `ledmatrix-plugins` monorepo (not individual repos) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 5f40b408..2447f72f 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -234,6 +234,9 @@ advances by elapsed time at `scroll_speed / scroll_delay` px/s. ## Diagnosing a juddery scroller +To check a whole rig rather than one scroller, soak it -- see *Soaking a rig* +below. + **An average will lie to you.** A 2 ms duplicate frame and a 21 ms double-wait mean exactly 10 ms, so a ticker stalling on half its frames still averages to a healthy 100 fps. The stats line reports the tail for that reason — read the @@ -306,6 +309,170 @@ journalctl -u ledmatrix --since "-5min" --no-pager | grep -iE "px/s|px/frame" If a plugin logs its scroll config **twice** with different modes, the second line is what is running. +## Soaking a rig + +The per-scroller lines above tell you *which* scroller misbehaves. The soak +answers the question a release has to answer for each rig: **over a long run, +how often did a moving frame reach the panel late?** + +Every frame reaches the panel through `DisplayManager.update_display`, so it is +timed there once, whoever drew it -- Vegas, a ticker plugin, anything. The +render thread only appends a tuple; a worker thread aggregates and rewrites +`/dev/shm/ledmatrix_frame_stats.json` every 10 seconds (RAM, so no SD-card +wear). `src/common/frame_timing.py` has the details. + +```bash +python3 scripts/frame_soak.py # 10 minutes, as the display is now +python3 scripts/frame_soak.py --preview # with the web preview open +python3 scripts/frame_soak.py --show # totals since the service started +python3 scripts/frame_soak.py --json a.json # keep the report to compare later +``` + +It runs as any user next to the display service and stops nothing. It needs +something to *scroll* during the run: a live game holding a static scoreboard +on screen gives no verdict. `--preview` keeps the web preview's viewer marker +fresh, which puts the preview's PNG encoding at full rate -- run it as the web +service's user. + +| line | what it tells you | +|---|---| +| **Late frames** | Frames presented one or more refreshes after they were due: the panel showed the previous frame again, a visible hitch. **The pass/fail number**, 0.1% by default (`--max-late-pct`). Only intervals between two scrolling frames count, and a frame held for `frame_hold` refreshes is due `frame_hold` refreshes after the last. | +| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers, blocking calls on the render thread. Reported but not failed on, because some are handovers between plugins rather than faults. A gap still counts when the display's scroll state went missing for one frame across it, as long as scrolling resumes within 1 s: both of that frame's intervals count. Two static frames in a row end the scroll. (The state expires after 2 s without scroll activity, and plugins can clear it from their own `display()`.) The late and early rates are over frames judged against a known refresh period, which the recorder adopts once two windows in a row agree on it. | +| **blit** | Copying the frame into the matrix canvas (`SetImage`). It grows with width × height × `pwm_bits`: ~5.5 ms at 512×64 with 8 bits on a Pi 4. It is the biggest fixed cost, and it sets the refresh rates a rig can hold one pixel per refresh at. | +| **wait** | Time blocked in `SwapOnVSync`, i.e. the slack left in each refresh. A p50 near zero means the rig has no headroom and anything extra lands a frame late. | +| **work** | Everything else between two frames: drawing, scrolling, and waiting for the GIL. A wide gap between its p50 and p99 is another thread getting in the way. | +| **Binding** | `STOCK` means the rgbmatrix binding holds the GIL through the vsync wait, which starves every other thread. See *Rebuilding the binding*. | + +The refresh rate is estimated from the frames themselves (swaps that block on +vsync can only land on refresh boundaries). Cross-check it with +`scroll_speeds.py --measure` if it looks wrong. It can read high on a rig where +nothing ever presented at the full refresh rate. + +A soak is only meaningful against a fixed workload. Compare runs with the same +content and `--preview` setting, and alternate which build goes first when you +A/B two of them. A live-API workload drifts over time. + +The soak says how often; the service's log says why. A scroll that presents no +frame for 250 ms logs `Render stall:` with the stack of the render thread and +the top of every other thread's, and whether the whole interpreter was blocked +(C code holding the GIL) rather than one thread. To see what is behind the +shorter hitches, run the service with `LEDMATRIX_STALL_WATCHDOG_MS=30`, which +dumps at three refreshes late instead: its extra polling costs a little GIL +time of its own, so do that on a diagnostic run, not a soak you are grading. +`LEDMATRIX_STALL_WATCHDOG=0` turns it off. + +### Results: hdpi, 2026-09-24 + +Pi 4, 4×128×64 on one chain (512×64), `gpio_slowdown` 3, cap 120 Hz, the +GIL-releasing binding. Vegas mode with live content, 8-minute soaks with +`--preview`, run in the order shown so each build went both first and last. + +| run | build | pacing | pwm_bits | refresh | late | 1 | 2 | 3–5 | 6+ | freezes | +|---|---|---|---|---|---|---|---|---|---|---| +| 1 | main | time-based, blended, 90 px/s | 8 | 94.5 Hz | 6.33% | 2,542 | 74 | 19 | 4 | 0 | +| 2 | #628 | 1 px / refresh | 8 | 100.2 Hz | 0.66% | 238 | 32 | 30 | 5 | 2 | +| 3 | #628 | 1 px / refresh | 8 | 100.3 Hz | 0.70% | 252 | 38 | 26 | 6 | 2 | +| 4 | main | time-based, blended, 90 px/s | 8 | 94.5 Hz | 6.46% | 2,659 | 90 | 10 | 4 | 0 | +| 5 | #628 | 1 px / 2 refreshes (53 px/s) | **7** | 107.2 Hz | 0.32% | 68 | 7 | 4 | 2 | 1 | + +- Blending cost the panel refresh rate as well as frames: 94.5 Hz against + ~100 Hz for the same hardware under whole-pixel pacing. +- The freezes and the 3+ rows in the #628 runs line up with canvas-bound + plugins fetched on the render thread (`drain_deferred`): `news` took ~320 ms + and `hockey-scoreboard` ~660 ms there. Moving those + fetches off the render thread is proposed separately (offscreen rendering). +- Run 5 changed two things at once: the speed, and `pwm_bits` (changed on the + rig between runs). Its lower late rate cannot be credited to either alone. +- 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. + +### Without the service: `render_bench.py` + +The soak measures the service as it really runs: live content, plugin +updates, the web preview. `scripts/render_bench.py` answers the narrower +question underneath: *with nothing else in the way, can this hardware present +every frame on time?* It scrolls a synthetic strip through the production path +-- a real `DisplayManager`, a real `ScrollHelper`, the same `scroll_config` +resolver every ticker uses -- on content that is identical every run, which +makes it the tool for comparing rigs (a Pi 3 against a Pi 4, one HAT against +another) and for A/B testing a change to the render path. + +```bash +sudo systemctl stop ledmatrix # the service owns the GPIO + +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, so a crash in it cannot leave +the panel dark. It grades with the same recorder as the soak and prints the +same report, with the same exit status, except that **2** also means the run +could not be set up at all (no root, no panel, a fallback display), so a rig +that was never measured cannot pass by accident. + +Two differences from the soak matter: + +- **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, +`pwm_bits` 8), two-minute runs at one pixel per refresh: 8 of 11,449 frames +late (0.070%), and with `--busy 2` 3 of 11,445 (0.026%). The render path and +the hardware pass on their own. Compare the soak results above, from the same +rig with the service running, for how much of the late rate comes from +everything else. + +### The panel is slower while you are rendering into it + +The bench prints two refresh rates, and they 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. +The recorder therefore reads the rendering rate back from the frames: swaps +that block on vsync can only return on a refresh boundary, so the low end of +`interval / frame_hold` is the period. The idle figure is still printed, +because the gap between the two is itself a measure of how expensive a frame +is: **a rise in that gap is a render-cost regression even when nothing is +late.** + +The practical consequence for config: set `limit_refresh_rate_hz` near the rate +the panel holds *while rendering*, not the idle rate and certainly not a cap it +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. + +### Bench-only counters + +| line | meaning | +|---|---| +| `duplicate` | frames that advanced no pixels. A crisp fixed-step scroll should show none; any at all means the loop is presenting faster than the strip is moving. | +| `blank` | frames with no visible slice to draw: the helper had no content. Should be zero. | +| `restarts` | how many times the strip was scrolled through end to end. Informational: the bench restarts the strip where a plugin would hand over to the next one. | + +`--json` writes the full report plus the panel geometry, the solved speed and +these counters, so two rigs (or one rig before and after a change) can be +compared without re-reading a terminal. + --- ## A tear across the middle on fast scrolls diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py new file mode 100644 index 00000000..da233da7 --- /dev/null +++ b/scripts/frame_soak.py @@ -0,0 +1,389 @@ +#!/usr/bin/env python3 +"""Soak a running display and report how often moving frames reached the panel late. + +Runs NEXT TO the display service, as any user: it only reads the stats file the +service writes (src/common/frame_timing.py) at the start and end of the run and +reports the difference. Nothing is stopped, restarted or drawn. + + # 10 minutes, as the display is now + python3 scripts/frame_soak.py + + # the same with the web preview open (the preview's PNG encodes are one of + # the things that used to make the render loop miss refreshes) + python3 scripts/frame_soak.py --preview + + # quick look at the totals since the service started + python3 scripts/frame_soak.py --show + + # keep the report for a before/after comparison + python3 scripts/frame_soak.py --duration 600 --json soak-before.json + +Exit status: 0 when the late-frame rate is within ``--max-late-pct``, 1 when it +is not, 2 when there was nothing to measure (no stats file, the service +restarted mid-run, or nothing scrolled). + +What the numbers mean +--------------------- +late frames frames that reached the panel one or more refreshes after they + were due -- the panel showed the previous frame again, which on + a moving strip is a visible hitch. This is the pass/fail number. +freezes gaps of 250ms+ inside a scroll: recomposes, plugin handovers, + blocking calls on the render thread. Reported, not failed on, + since some are handovers between plugins rather than faults. +blit copying the frame into the matrix canvas (rgbmatrix SetImage). + Grows with width x height x pwm_bits. +wait blocked in SwapOnVSync, i.e. slack before the refresh. +work everything else between two frames: drawing, scrolling, and + waiting for the GIL. +""" +from __future__ import annotations + +import argparse +import json +import os +import sys +import time +from pathlib import Path +from typing import Any, Dict, Optional + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common.frame_timing import ( # noqa: E402 + BUCKET_COUNT, + SCHEMA_VERSION, + default_stats_path, +) + +#: Touched by the web UI while someone has the preview open; a fresh marker +#: puts the display service's snapshot writer at full rate. Same path as +#: DisplayManager._viewer_marker_path. +VIEWER_MARKER = "/tmp/led_matrix_preview_viewer" # nosec B108 - fixed path shared with the service + +#: A stats file not rewritten for this long means nothing is being presented. +STALE_SECONDS = 30.0 + + +def load(path: str) -> Optional[Dict[str, Any]]: + try: + with open(path, encoding="utf-8") as handle: + stats = json.load(handle) + except (OSError, ValueError): + return None + if not isinstance(stats, dict) or stats.get("version") != SCHEMA_VERSION: + return None + return stats + + +def _histogram(stats: Dict[str, Any], name: str) -> Dict[int, int]: + raw = (stats.get("histograms") or {}).get(name) or {} + return {int(k): int(v) for k, v in raw.items()} + + +def diff(before: Dict[str, Any], after: Dict[str, Any]) -> Dict[str, Any]: + """What happened between two snapshots of the same process.""" + tb, ta = before["totals"], after["totals"] + totals = {} + for key, value in ta.items(): + if isinstance(value, dict): + totals[key] = {k: v - tb.get(key, {}).get(k, 0) + for k, v in value.items()} + elif key == "worst_interval_ms": + # A running maximum can't be differenced; it is reported as the + # worst since the service started. + totals[key] = value + else: + totals[key] = value - tb.get(key, 0) + histograms = {} + for name in (after.get("histograms") or {}): + hb, ha = _histogram(before, name), _histogram(after, name) + histograms[name] = {k: v - hb.get(k, 0) for k, v in ha.items() + if v - hb.get(k, 0) > 0} + return {"totals": totals, "histograms": histograms, + "seconds": after["updated"] - before["updated"]} + + +def percentiles(histogram: Dict[int, int], bucket_ms: float) -> Dict[str, Any]: + """p50/p95/p99/max from a sparse histogram, as each bucket's upper edge.""" + count = sum(histogram.values()) + if not count: + return {} + out = {} + targets = {"p50": 0.50, "p95": 0.95, "p99": 0.99} + running = 0 + for index in sorted(histogram): + running += histogram[index] + for name, fraction in list(targets.items()): + if running >= fraction * count: + out[name] = _edge(index, bucket_ms) + del targets[name] + out["max"] = _edge(max(histogram), bucket_ms) + return out + + +def _edge(index: int, bucket_ms: float): + if index >= BUCKET_COUNT - 1: + return f">={index * bucket_ms:g}" + return round((index + 1) * bucket_ms, 2) + + +def build_report(before, after, preview: bool) -> Dict[str, Any]: + delta = diff(before, after) + totals = delta["totals"] + frames = totals["scroll_frames"] + # The rates are over frames judged against a known refresh period. Stats + # from a recorder that predates the count fall back to every frame. + timed = totals.get("timed_frames", frames) if "timed_frames" in totals else frames + hours = delta["seconds"] / 3600.0 if delta["seconds"] > 0 else 0.0 + bucket_ms = after.get("bucket_ms", 0.25) + report = { + "seconds": round(delta["seconds"], 1), + "preview": preview, + "info": after.get("info"), + "binding_releases_gil": after.get("binding_releases_gil"), + "measured_refresh_hz": after.get("measured_refresh_hz"), + "scroll_frames": frames, + "static_frames": totals["static_frames"], + "late_frames": totals["late_frames"], + "timed_frames": timed, + "late_pct": round(100.0 * totals["late_frames"] / timed, 3) if timed else None, + "missed_refreshes": totals["missed_refreshes"], + "late_by": totals["late_by"], + "early_frames": totals.get("early_frames", 0), + "early_pct": (round(100.0 * totals.get("early_frames", 0) / timed, 3) + if timed else None), + "freeze_by": totals.get("freeze_by", {}), + "freezes": totals["freezes"], + "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None, + "freeze_seconds": round(totals["freeze_seconds"], 2), + "worst_interval_ms": (round(totals["worst_interval_ms"], 1) + if totals["worst_interval_ms"] else None), + "timing_ms": {name: percentiles(h, bucket_ms) + for name, h in delta["histograms"].items()}, + } + # 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") + # percentiles() reports a bucket's upper edge; the midpoint is the better + # estimate, and half a 0.25ms bucket is already ~1% at 100Hz -- the size + # of the idle-vs-held gap this number exists to show. + if isinstance(typical, (int, float)) and typical > bucket_ms / 2: + report["held_refresh_hz"] = round(1000.0 / (typical - bucket_ms / 2), 1) + else: + report["held_refresh_hz"] = None + return report + + +def print_report(report: Dict[str, Any], limit: float) -> None: + info = report.get("info") or {} + size = "{}x{}".format( + (info.get("cols") or 0) * (info.get("chain_length") or 1), + (info.get("rows") or 0) * (info.get("parallel") or 1)) + gil = {True: "releases the GIL", False: "STOCK (holds the GIL in SwapOnVSync)", + None: "unknown"}[report.get("binding_releases_gil")] + print(f"Rig {info.get('pi_model') or 'unknown'}") + print(f"Panel {size} chain {info.get('chain_length')} x parallel " + f"{info.get('parallel')} pwm_bits {info.get('pwm_bits')} " + f"slowdown {info.get('gpio_slowdown')} mapping {info.get('hardware_mapping')}") + print(f"Refresh {report.get('measured_refresh_hz') or '?'} Hz measured, " + f"cap {info.get('limit_refresh_rate_hz')}") + print(f"Binding {gil}") + print(f"Run {report['seconds']:.0f}s, preview " + f"{'open (simulated)' if report['preview'] else 'as-is'}") + print() + frames = report["scroll_frames"] + print(f"Scrolling frames {frames}") + if frames: + late_by = report["late_by"] + print(f"Late frames {report['late_frames']} ({report['late_pct']}%)" + f" missed refreshes {report['missed_refreshes']}" + f" [by 1: {late_by['1']}, 2: {late_by['2']}, " + f"3-5: {late_by['3-5']}, 6+: {late_by['6+']}]") + if report["early_frames"]: + print(f"Early frames {report['early_frames']} " + f"({report['early_pct']}%) swaps returned a refresh early") + print(f"Freezes >=250ms {report['freezes']}" + f" ({report['freezes_per_hour']}/h, {report['freeze_seconds']}s total)" + f" worst gap since start {report['worst_interval_ms'] or '-'} ms") + if report["freezes"]: + print(" by length: " + ", ".join( + f"{k}: {v}" for k, v in report["freeze_by"].items())) + print() + print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}") + for name in ("blit", "wait", "work", "interval_per_hold"): + row = report["timing_ms"].get(name) or {} + print(f"{name:<18}" + "".join(f"{str(row.get(k, '-')):>8}" + for k in ("p50", "p95", "p99", "max"))) + print() + if report["late_pct"] is None: + print("RESULT nothing scrolled - no verdict") + elif not locked(report, limit): + ceiling = refresh_ceiling(report) + if (report.get("early_pct") or 0.0) > limit: + why = (f"{report['early_pct']}% of frames came a refresh early, so the " + "swaps were not waiting for the panel") + else: + why = (f"frames arrived at {report['measured_refresh_hz']}Hz, faster than " + f"the panel can refresh ({ceiling:g}Hz)") + print(f"RESULT FAIL NOT LOCKED: {why}, and the late count means nothing") + elif report["late_pct"] <= limit: + print(f"RESULT PASS {report['late_pct']}% late <= {limit}%") + else: + print(f"RESULT FAIL {report['late_pct']}% late > {limit}%") + + +#: How far over the panel's rate frames may arrive before the loop cannot have +#: been waiting for it. The margin covers the refresh wandering a little. +CEILING_MARGIN = 1.05 + + +def refresh_ceiling(report: Dict[str, Any]) -> Optional[float]: + """The fastest the panel can refresh, as far as this run knows. + + The benchmark measures it (``idle_refresh_hz``); the service only knows its + cap. With neither, there is no ceiling to check against. + """ + idle = report.get("idle_refresh_hz") + if idle: + return float(idle) + cap = (report.get("info") or {}).get("limit_refresh_rate_hz") + try: + cap = float(cap) + except (TypeError, ValueError): + return None + return cap if cap > 0 else None + + +def locked(report: Dict[str, Any], limit: float) -> bool: + """Whether the loop was paced by the panel at all. + + 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: + return (report["late_pct"] is not None and locked(report, limit) + and report["late_pct"] <= limit) + + +def touch_marker() -> bool: + try: + with open(VIEWER_MARKER, "a"): + pass + os.utime(VIEWER_MARKER, None) + return True + except OSError: + return False + + +def wait_for_fresh(path: str, timeout: float) -> Optional[Dict[str, Any]]: + """The first snapshot written after now, so both ends of the run are exact.""" + first = load(path) + deadline = time.time() + timeout + while time.time() < deadline: + current = load(path) + if current and (first is None or current["updated"] != first["updated"]): + return current + time.sleep(0.5) + return None + + +def main(argv=None) -> int: + parser = argparse.ArgumentParser(description=__doc__.split("\n")[0]) + parser.add_argument("--duration", type=float, default=600.0, + help="seconds to soak (default 600)") + parser.add_argument("--preview", action="store_true", + help="keep the web-preview viewer marker fresh, as an " + "open preview tab does") + parser.add_argument("--max-late-pct", type=float, default=0.1, + help="fail above this percentage of late frames (default 0.1)") + parser.add_argument("--stats", default=default_stats_path(), + help="stats file written by the display service") + parser.add_argument("--json", metavar="PATH", + help="also write the report as JSON") + parser.add_argument("--show", action="store_true", + help="print totals since the service started and exit") + args = parser.parse_args(argv) + + current = load(args.stats) + if current is None: + print(f"No frame stats at {args.stats}. Is the display service running a " + "build with frame timing, and has anything scrolled for ~10s?", + file=sys.stderr) + return 2 + if time.time() - current["updated"] > STALE_SECONDS: + print(f"Frame stats are {time.time() - current['updated']:.0f}s old: nothing " + "has been presented recently (static screen, or the service stopped).", + file=sys.stderr) + if not args.show: + return 2 + + if args.show: + empty = json.loads(json.dumps(current)) + for key, value in empty["totals"].items(): + empty["totals"][key] = ({k: 0 for k in value} if isinstance(value, dict) + else 0) + empty["histograms"] = {} + empty["updated"] = current["started"] + report = build_report(empty, current, preview=False) + print_report(report, args.max_late_pct) + return 0 + + if args.preview and not touch_marker(): + print(f"Cannot touch {VIEWER_MARKER}; run as the web service's user to " + "simulate an open preview.", file=sys.stderr) + return 2 + + print(f"Waiting for a fresh baseline from {args.stats} ...", flush=True) + before = wait_for_fresh(args.stats, timeout=60.0) + if before is None: + print("The stats file stopped updating.", file=sys.stderr) + return 2 + + end = time.time() + args.duration + next_progress = time.time() + 60.0 + while time.time() < end: + if args.preview: + touch_marker() + time.sleep(1.0) + if time.time() >= next_progress: + now = load(args.stats) + if now and now.get("pid") == before["pid"]: + done = now["totals"]["scroll_frames"] - before["totals"]["scroll_frames"] + late = now["totals"]["late_frames"] - before["totals"]["late_frames"] + print(f" {int(end - time.time())}s left: {done} scrolling frames, " + f"{late} late", flush=True) + next_progress += 60.0 + + after = wait_for_fresh(args.stats, timeout=60.0) + if after is None: + print("The stats file stopped updating during the run.", file=sys.stderr) + return 2 + if after.get("pid") != before.get("pid"): + print("The display service restarted during the run; results discarded.", + file=sys.stderr) + return 2 + + report = build_report(before, after, preview=args.preview) + print() + print_report(report, args.max_late_pct) + if args.json: + with open(args.json, "w", encoding="utf-8") as handle: + json.dump(report, handle, indent=2) + if report["late_pct"] is None: + return 2 + return 0 if passed(report, args.max_late_pct) else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/render_bench.py b/scripts/render_bench.py new file mode 100755 index 00000000..17f3d259 --- /dev/null +++ b/scripts/render_bench.py @@ -0,0 +1,404 @@ +#!/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 a synthetic strip for a while, and grades +it with the same frame-timing recorder the display service uses +(``src.common.frame_timing``), printing the same report as +``scripts/frame_soak.py``. A run passes when the loop was genuinely locked to +the panel and no more than ``--max-late-pct`` percent of frames were late. + +Where frame_soak.py measures the service as it runs -- live content, plugin +updates, the web preview -- this measures the hardware and the render path +with nothing else in the way, on content that is identical every run. That is +what makes it the tool for comparing rigs (a Pi 3 against a Pi 4, one HAT +against another) and for A/B testing a change to the render path. + + # stop the service first; it owns the GPIO + sudo systemctl stop ledmatrix + + 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_timing, scroll_config # noqa: E402 + +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import frame_soak # noqa: E402 (same report, same verdict as the soak) + +REPO = Path(__file__).resolve().parent.parent +CONFIG = REPO / "config" / "config.json" + +#: 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 + +#: Scrolling discarded before the graded run starts: the first frames carry +#: first-touch costs and the scrolling state settling. +WARMUP_SECONDS = 2.0 + + +def load_config() -> dict: + """The config the display service would run with.""" + try: + from src.config_manager import ConfigManager + + config = ConfigManager().config + if isinstance(config, dict) and config: + return config + except Exception as exc: # noqa: BLE001 - any failure means use the plain read + print(f"ConfigManager unavailable ({exc}); reading {CONFIG} directly", + file=sys.stderr) + # 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 idle measurement and take this as the " + "panel's rate (for reproducing a rig's numbers)") + parser.add_argument("--busy", type=int, default=0, metavar="N", + help="run N background workers imitating plugin updates") + parser.add_argument("--max-late-pct", "--max-missed", dest="max_late_pct", + type=float, default=0.1, metavar="PCT", + help="fail above this percentage of late frames (default 0.1)") + parser.add_argument("--json", dest="json_path", default=None, metavar="PATH", + help="also write the report as JSON, for comparing rigs") + parser.add_argument("--label", default=None, + 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. The stall watchdog + # is the exception: a stack dump naming what held a frame up belongs here. + logging.basicConfig(level=logging.ERROR, stream=sys.stderr) + logging.getLogger("src.common.frame_timing").setLevel(logging.WARNING) + + if hasattr(os, "geteuid") and os.geteuid() != 0: + print("this needs root for GPIO access - rerun with sudo", file=sys.stderr) + 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: + idle_hz = float(args.hz) + print(f"taking the panel's rate as {idle_hz:.1f}Hz (given, not measured)") + else: + print(f"measuring the panel for {MEASURE_SECONDS:.0f}s...", flush=True) + idle_hz = frame_timing.measure_refresh_hz(display.matrix, MEASURE_SECONDS) + if idle_hz <= 0: + print("the panel did not answer a swap; cannot measure it", + file=sys.stderr) + return 2 + cap = scroll_config.refresh_hz_from_config(config) + note = (f" (cap is {cap:.0f}Hz)" if idle_hz < cap * 0.98 + else " (at its configured cap)") + print(f"panel refreshes at {idle_hz:.1f}Hz{note}") + + requested = args.speed if args.speed else idle_hz + + # Configured through the shared resolver rather than by setting the helper + # up by hand, so the benchmark measures the engine every ticker runs on. A + # 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=idle_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")) + + # The display service's own recorder, owned outright here: never flushed to + # the service's stats file, drained exactly at the start and end of the + # graded run, and seeded with the idle rate so a loop that never locked + # (free-running, or stuck at a fraction of the refresh) shows as early or + # late frames instead of looking self-consistent. + recorder = frame_timing.FrameTimingRecorder( + flush_interval=float("inf"), + info=display._frame_timing_info(), # pylint: disable=protected-access + refresh_hz=idle_hz, + ) + recorder.scrolling_now = display._scrolling_now # pylint: disable=protected-access + display.frame_timing = recorder + + print(f"scrolling {width}x{height} for {args.seconds:.0f}s" + + (f" with {args.busy} background worker(s)" if args.busy else "") + + " ...", flush=True) + + frames = 0 + duplicates = 0 + blanks = 0 + restarts = 0 + last_column = None + before = None + started = time.perf_counter() + run_started = None + try: + with BackgroundLoad(args.busy): + while True: + now = time.perf_counter() + if run_started is None and now - started >= WARMUP_SECONDS: + recorder.drain() + before = recorder.snapshot() + run_started = now + frames = duplicates = blanks = restarts = 0 + if run_started is not None and now - run_started >= args.seconds: + break + helper.update_scroll_position() + if helper.is_scroll_complete(): + # The helper parks at the end of the strip and stops + # 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() + frames += 1 + except KeyboardInterrupt: + print("\ninterrupted - reporting what was measured so far") + finally: + display.set_scrolling_state(False) + try: + display.clear() + except Exception as exc: # noqa: BLE001 - a lit panel is harmless; say so and go on + print(f"could not blank the panel: {exc}", file=sys.stderr) + + if before is None: + print("interrupted during warm-up; nothing was graded", file=sys.stderr) + return 2 + recorder.drain() + report = frame_soak.build_report(before, recorder.snapshot(), preview=False) + report["idle_refresh_hz"] = round(idle_hz, 2) + + print() + frame_soak.print_report(report, args.max_late_pct) + held = report.get("held_refresh_hz") + if held: + drop = 100.0 * (idle_hz - held) / idle_hz + print(f"\npanel held ~{held:.1f}Hz while rendering, {drop:.1f}% below its " + f"{idle_hz:.1f}Hz idle rate (a widening gap is a render-cost " + "regression even with nothing late)") + if duplicates: + # A frame that shows the same columns as the one before it is work the + # panel did not need. It is not a miss -- the frame arrived on time -- + # but it means the loop is presenting faster than the strip is moving. + print(f"duplicate {duplicates} frames advanced no pixels " + f"({100.0 * duplicates / max(1, frames):.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: + report.update({ + "label": args.label or os.uname().nodename, + "bench": True, + "requested_pixels_per_second": requested, + "pixels_per_second": choice.pixels_per_second, + "pixels_per_frame": choice.pixels_per_frame, + "frame_hold": choice.frame_hold, + "busy_workers": args.busy, + "duplicate_frames": duplicates, + "blank_frames": blanks, + "strip_restarts": restarts, + "max_late_pct": args.max_late_pct, + "passed": frame_soak.passed(report, args.max_late_pct), + }) + Path(args.json_path).write_text(json.dumps(report, indent=2) + "\n", + encoding="utf-8") + print(f"\nwrote {args.json_path}") + + if report["late_pct"] is None: + return 2 + return 0 if frame_soak.passed(report, args.max_late_pct) else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/scroll_speeds.py b/scripts/scroll_speeds.py index bdabf023..7b9d192b 100644 --- a/scripts/scroll_speeds.py +++ b/scripts/scroll_speeds.py @@ -42,7 +42,7 @@ from pathlib import Path sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) -from src.common import scroll_config # noqa: E402 +from src.common import frame_timing, 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_timing so the benchmark grades 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_timing.measure_refresh_hz(matrix, seconds) matrix.Clear() return measured diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py new file mode 100644 index 00000000..ee554398 --- /dev/null +++ b/src/common/frame_timing.py @@ -0,0 +1,609 @@ +"""System-wide frame timing: one set of numbers for every presented frame. + +Each scroller already logs its own stats line (ScrollHelper.log_frame_rate, +the Vegas coordinator's "Vegas FPS"), but in different formats, per source, +and Vegas only logs a healthy window at DEBUG. None of that answers the +question a release has to answer on each rig: *over a long run, how often did +a moving frame reach the panel late?* + +Every frame reaches the panel through ``DisplayManager.update_display``, so it +is recorded there, once, whoever drew it. The render thread only appends a +tuple; a worker thread aggregates, and every ``flush_interval`` seconds writes +cumulative counters and histograms to a small JSON file -- in ``/dev/shm`` where +it exists, so a stats file refreshed all day costs no SD-card writes. +``scripts/frame_soak.py`` reads it twice and reports the difference. + +What is counted +--------------- +Only intervals between two consecutive *scrolling* frames count: a static +screen that changes once a second has no timing to get wrong, and the first +frame of a scroll has no predecessor worth measuring against. + +"Scrolling" is DisplayManager's scroll state when the frame is presented, and +that state can go missing in the middle of a scroll. It expires after 2s +without scroll activity, which a long enough stall outlasts, and any thread can +clear it: plugins call ``set_scrolling_state(False)`` from their own +``display()``, and Vegas captures some of those on the render thread between +two of its frames. The frame after that is recorded as static, and the interval +it ends -- the stall, or the capture -- would vanish from the report. So a +single static frame between two scrolling ones, with the scroll picking up +again within ``RESUME_SECONDS``, is treated as a frame of the scroll: both of +its intervals count. A second static frame in a row means the scroll really +ended. (On hdpi on 2026-09-24 the watchdog logged a 1.9s stall that the soak +report did not have; this is how.) + +A frame held for ``hold`` refreshes should arrive ``hold`` refresh periods +after the one before it. One that arrives a whole refresh or more after that is +**late**: the panel showed the previous frame again, which on a moving strip is +a visible hitch. ``missed_refreshes`` sums how many refreshes late. + +An interval of ``FREEZE_SECONDS`` or more is a **freeze** instead -- a +recompose, a plugin handover, a blocking call on the render thread. Those are +counted separately, both because they are a different fault and because +folding a single 400ms handover into the late count as "40 missed refreshes" +would drown the jitter the late count exists to measure. ``freeze_by`` splits +them by length. Intervals of ``GAP_SECONDS`` or more are ignored as not being +frames of one scroll at all. + +A frame that arrives a whole refresh or more *early* means the swap did not +wait for the panel: the emulator, the fallback display, or a hold that was not +the one in effect. Those are counted as **early**, and a run with more than a +trace of them was not locked to the panel, so its late count means nothing. + +The refresh period is estimated from the frames themselves: swaps that block +on vsync can only land on refresh boundaries, so the low end of +interval / hold is the period. It is the smallest per-window 10th percentile +seen so far, over windows with enough frames to trust -- except that a window +cutting it by more than ``MAX_REFRESH_DROP`` is ignored. A panel's refresh does +not jump like that; swaps that stopped blocking do, and adopting their period +would make every early frame look on time. + +A caller that has measured the panel independently -- ``scripts/render_bench.py`` +times bare swaps first with :func:`measure_refresh_hz` -- passes that rate in +as ``refresh_hz``. The estimate then starts from it instead of from the frames, +which is what catches a loop that never locked at all: one that free-runs +faster than the panel (every frame early) or sits at half its rate (every +frame late), both of which look self-consistent to an estimate taken from +their own intervals. + +Stall watchdog +-------------- +Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the +same frames from its own thread and, when a scroll's last frame is more than +``STALL_SECONDS`` old, logs the stack of the thread that presented it and the +top of every other thread's, so the log names what the render thread was +waiting on. It also measures how late its own wake-up was: if the watchdog was +held up as long as the render thread, the whole interpreter was blocked (C +code holding the GIL, or the process not scheduled), not one thread on a lock. +Set ``LEDMATRIX_STALL_WATCHDOG=0`` to turn it off, or +``LEDMATRIX_STALL_WATCHDOG_MS`` to dump at a lower threshold -- 30 catches +frames three refreshes late, which is where GIL contention shows. It polls +three times per threshold, so keep it to diagnostic runs, not soaks. +""" + +from __future__ import annotations + +import copy +import json +import logging +import os +import queue +import sys +import tempfile +import threading +import time +import traceback +from typing import Any, Callable, Dict, List, Optional, Tuple + +logger = logging.getLogger(__name__) + +#: Bumped when a field changes meaning, so a reader can refuse stale files. +SCHEMA_VERSION = 1 + +#: Histogram resolution. 64ms of range covers any frame worth drawing a +#: distribution of; everything beyond lands in the last bucket. +BUCKET_MS = 0.25 +BUCKET_COUNT = 256 + +#: See the module docstring. +FREEZE_SECONDS = 0.25 + +#: Intervals this long are not frames of one scroll. This used to be 1s, +#: which silently dropped every 1-2s stall inside a scroll. It is now only a +#: sanity bound. +GAP_SECONDS = 5.0 + +#: A frame recorded as static between two scrolling frames is a frame of the +#: scroll whose state went missing, if the scroll resumes within this long. +#: See "What is counted". +RESUME_SECONDS = 1.0 + +#: Buckets for freeze length, as cumulative counters a soak can difference. +FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"), + (float("inf"), "2s+")) + +#: A window may lower the refresh-period estimate by at most this fraction. +MAX_REFRESH_DROP = 0.2 + +#: A window needs this many scrolling frames before its refresh estimate is +#: trusted -- about a second of scrolling. +MIN_FRAMES_FOR_REFRESH = 90 + +FLUSH_INTERVAL = 10.0 + +#: A scroll's last frame older than this is a stall worth a stack dump. +STALL_SECONDS = 0.25 +#: How often the watchdog looks. Also the resolution of its starvation check. +WATCHDOG_POLL_SECONDS = 0.05 +#: At most one stack dump per this many seconds: a stall that repeats every +#: extension would otherwise write the same stacks to the SD card all day. +STALL_LOG_INTERVAL = 30.0 + +#: Written by the display service, read by scripts/frame_soak.py and anything +#: else that wants the numbers. The web UI's viewer marker lives in /tmp; this +#: goes to RAM where there is some, since it is rewritten all day. +STATS_FILENAME = "ledmatrix_frame_stats.json" + + +def default_stats_path() -> str: + # A fixed name in a shared directory is safe here: write() creates its + # temp file with mkstemp and os.replace()s it over this path, which swaps + # out whatever is there -- a planted symlink included -- without following it. + base = "/dev/shm" if os.path.isdir("/dev/shm") else tempfile.gettempdir() # nosec B108 + return os.path.join(base, STATS_FILENAME) + + +def _bucket(seconds: float) -> int: + index = int(seconds * 1000.0 / BUCKET_MS) + return min(max(index, 0), BUCKET_COUNT - 1) + + +def binding_releases_gil() -> Optional[bool]: + """Whether the loaded rgbmatrix binding releases the GIL, or None. + + The stock binding blocks in SwapOnVSync holding the GIL, which starves + every other thread for most of each frame (docs/SCROLL_PERFORMANCE.md). + scripts/build_rgbmatrix_nogil.sh rebuilds it, and the rebuilt module links + PyEval_SaveThread where the stock one never does -- a crude test, but the + only one that needs neither a probe on the panel nor the source tree the + module was built from. None when no hardware binding is loaded. + """ + module = sys.modules.get("rgbmatrix.core") + path = getattr(module, "__file__", None) + if not path: + return None + try: + with open(path, "rb") as handle: + return b"PyEval_SaveThread" in handle.read() + except OSError: + return None + + +def _pi_model() -> Optional[str]: + try: + with open("/proc/device-tree/model", "rb") as handle: + return handle.read().rstrip(b"\0").decode("ascii", "replace").strip() + except OSError: + return None + + +def measure_refresh_hz(matrix: Any, seconds: float = 4.0) -> float: + """The panel's refresh rate with nothing else running, by timing bare swaps. + + ``SwapOnVSync`` blocks until the panel's next refresh, so a loop that does + nothing else runs at exactly the panel's rate. ``limit_refresh_rate_hz`` is + a *cap*, and a long chain, a high ``pwm_bits`` or an older Pi will sit well + under it. Solving scroll speeds against a cap the panel cannot reach is + what produces "3px every 4 refreshes" and the judder that comes with it. + + This is the idle rate. The panel refreshes a few percent slower while the + Pi is also pushing frames into it (100.4Hz idle against 96.3Hz scrolling on + a Pi 4 driving 512x64), which is why the recorder reads the rendering rate + back from the frames rather than trusting this. + + Pass the matrix the display is already running on rather than opening a + second one: the GPIO has a single owner, and the options in force change + the answer. + + :returns: measured Hz, or 0.0 if the matrix cannot be swapped (no + hardware, a stub, a mock). + """ + try: + canvas = matrix.CreateFrameCanvas() + # Discard the first swap: it carries construction and first-touch costs + # that have nothing to do with the steady-state refresh. + canvas = matrix.SwapOnVSync(canvas) + except Exception: # pylint: disable=broad-except + return 0.0 + + frames = 0 + started = time.perf_counter() + while time.perf_counter() - started < seconds: + canvas = matrix.SwapOnVSync(canvas) + frames += 1 + elapsed = time.perf_counter() - started + if elapsed <= 0 or frames <= 0: + return 0.0 + return frames / elapsed + +class FrameTimingRecorder: + """Collects per-frame timings on the render thread; aggregates elsewhere. + + ``record`` is the only method the render thread calls, and it does no more + than compare two floats and append a tuple. + """ + + def __init__( + self, + path: Optional[str] = None, + flush_interval: float = FLUSH_INTERVAL, + info: Optional[Dict[str, Any]] = None, + refresh_hz: Optional[float] = None, + ): + """ + :param refresh_hz: the panel's rate, measured independently (see the + module docstring). Omit it to estimate from the frames alone, as + the display service does. + """ + self.path = path or default_stats_path() + self.flush_interval = flush_interval + self.info = dict(info or {}) + + # Render-thread state. + self._pending: List[Tuple[float, float, float, int]] = [] + self._static_frames = 0 + self._previous: Optional[Tuple[float, bool, int]] = None + # The interval ended by a static frame that followed a scrolling one, + # until the next frame shows whether the scroll went on. + self._unsure: Optional[Tuple[float, float, float, int]] = None + self._last_flush: Optional[float] = None + self._queue: "queue.SimpleQueue" = queue.SimpleQueue() + self._worker: Optional[threading.Thread] = None + + # Worker-thread state. Nothing on the render thread reads these. + self.started = time.time() + self.refresh_period: Optional[float] = ( + 1.0 / refresh_hz if refresh_hz and refresh_hz > 0 else None) + # The first estimate, until a second window agrees with it. + self._refresh_candidate: Optional[float] = None + self.totals: Dict[str, Any] = { + "static_frames": 0, + "scroll_frames": 0, + "late_frames": 0, + "missed_refreshes": 0, + "late_by": {"1": 0, "2": 0, "3-5": 0, "6+": 0}, + "early_frames": 0, + # Frames judged against a known refresh period: the denominator + # for the late and early rates. Frames before the period is known + # are neither, and must not dilute them. + "timed_frames": 0, + "freezes": 0, + "freeze_seconds": 0.0, + "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS}, + "worst_interval_ms": 0.0, + } + self.histograms: Dict[str, Dict[int, int]] = { + "blit": {}, "wait": {}, "work": {}, "interval_per_hold": {}, + } + self._binding_gil: Optional[bool] = None + self._binding_checked = False + + # Read by the stall watchdog from its own thread: one tuple assignment, + # so it always sees a consistent (time, scrolling, thread) triple. + self.last_frame: Optional[Tuple[float, bool, int]] = None + #: Whether a scroll is running *now*, supplied by the display manager. + #: The last frame's flag alone would call the end of every scroll a + #: stall. + self.scrolling_now: Optional[Callable[[], bool]] = None + self.watchdog: Optional["StallWatchdog"] = None + + def close(self) -> None: + """Stop the stall watchdog, if one was started.""" + watchdog, self.watchdog = self.watchdog, None + if watchdog is not None: + watchdog.stop() + + # -- render thread ------------------------------------------------------ + + def record(self, blit: float, wait: float, hold: int, scrolling: bool, + presented_at: float) -> None: + """One frame reached the panel. + + :param blit: seconds spent copying the frame into the canvas. + :param wait: seconds SwapOnVSync blocked. + :param hold: the refreshes this frame was held for. + :param scrolling: whether a scroll was running when it was presented. + :param presented_at: ``time.perf_counter()`` when the swap returned. + """ + previous = self._previous + self._previous = (presented_at, scrolling, hold) + self.last_frame = (presented_at, scrolling, threading.get_ident()) + if not scrolling: + self._static_frames += 1 + # The scroll ended, or its state went missing for this frame: the + # next frame says which. Its hold may have been dropped with the + # state, so the interval is due at the scroll's own. + self._unsure = None + if previous is not None and previous[1]: + self._unsure = (presented_at - previous[0], blit, wait, previous[2]) + elif self.watchdog is None and self.scrolling_now is not None \ + and os.environ.get("LEDMATRIX_STALL_WATCHDOG", "1") != "0": + self.watchdog = StallWatchdog(self, **watchdog_settings()) + self.watchdog.start() + elif previous is not None: + interval = presented_at - previous[0] + unsure, self._unsure = self._unsure, None + if previous[1]: + if interval < GAP_SECONDS: + self._pending.append((interval, blit, wait, hold)) + elif unsure is not None and interval < RESUME_SECONDS: + # One static frame between two scrolling ones: the scroll never + # stopped, only its state did. Both intervals were motion. + self._static_frames -= 1 + if unsure[0] < GAP_SECONDS: + self._pending.append(unsure) + self._pending.append((interval, blit, wait, hold)) + + if self._last_flush is None: + self._last_flush = presented_at + elif presented_at - self._last_flush >= self.flush_interval: + self._hand_off() + self._last_flush = presented_at + + def _hand_off(self) -> None: + batch, self._pending = self._pending, [] + static, self._static_frames = self._static_frames, 0 + self._queue.put((batch, static)) + if self._worker is None or not self._worker.is_alive(): + self._worker = threading.Thread( + target=self._run, daemon=True, name="frame-timing") + self._worker.start() + + def drain(self) -> None: + """Aggregate everything recorded so far, on the calling thread. + + For a caller that owns the recorder outright and wants exact numbers at + a moment of its choosing -- the benchmark, between warm-up and run and + at the end. Construct it with ``flush_interval=float('inf')`` so the + worker never runs; the two must not aggregate at once. + """ + batch, self._pending = self._pending, [] + static, self._static_frames = self._static_frames, 0 + self.aggregate(batch, static) + + # -- worker thread ------------------------------------------------------ + + def _run(self) -> None: + while True: + batch, static = self._queue.get() + try: + self.aggregate(batch, static) + self.write() + except Exception: # never let telemetry take anything down + logger.debug("Frame timing flush failed", exc_info=True) + + def aggregate(self, batch: List[Tuple[float, float, float, int]], + static: int) -> None: + """Fold one window of frames into the running totals.""" + totals = self.totals + totals["static_frames"] += static + + per_hold = sorted(interval / max(1, hold) + for interval, _, _, hold in batch + if interval < FREEZE_SECONDS) + if len(per_hold) >= MIN_FRAMES_FOR_REFRESH: + estimate = per_hold[len(per_hold) // 10] + current = self.refresh_period + if estimate <= 0: + pass + elif current is None: + # Adopt the first period only once two windows in a row agree: + # one loaded window at startup, most of its frames a refresh + # late, would otherwise fix a period twice the real one for + # the life of the process, since later windows may only lower + # it by MAX_REFRESH_DROP. + candidate = self._refresh_candidate + if candidate and abs(estimate - candidate) <= candidate * MAX_REFRESH_DROP: + self.refresh_period = min(candidate, estimate) + else: + self._refresh_candidate = estimate + elif current * (1.0 - MAX_REFRESH_DROP) <= estimate < current: + self.refresh_period = estimate + period = self.refresh_period + + histograms = self.histograms + for interval, blit, wait, hold in batch: + totals["worst_interval_ms"] = max(totals["worst_interval_ms"], + interval * 1000.0) + if interval >= FREEZE_SECONDS: + totals["freezes"] += 1 + totals["freeze_seconds"] += interval + label = next(name for limit, name in FREEZE_BUCKETS + if interval < limit) + totals["freeze_by"][label] += 1 + continue + totals["scroll_frames"] += 1 + for name, value in (("blit", blit), ("wait", wait), + ("work", max(0.0, interval - blit - wait)), + ("interval_per_hold", interval / max(1, hold))): + bucket = _bucket(value) + histogram = histograms[name] + histogram[bucket] = histogram.get(bucket, 0) + 1 + if period: + totals["timed_frames"] += 1 + missed = round(interval / period) - hold + if missed >= 1: + totals["late_frames"] += 1 + totals["missed_refreshes"] += missed + key = ("1" if missed == 1 else "2" if missed == 2 + else "3-5" if missed <= 5 else "6+") + totals["late_by"][key] += 1 + elif missed <= -1: + totals["early_frames"] += 1 + + def snapshot(self) -> Dict[str, Any]: + """The JSON document: cumulative since this process started.""" + if not self._binding_checked: + self._binding_gil = binding_releases_gil() + self._binding_checked = True + info = dict(self.info) + info.setdefault("pi_model", _pi_model()) + period = self.refresh_period + return { + "version": SCHEMA_VERSION, + "pid": os.getpid(), + "started": self.started, + "updated": time.time(), + "bucket_ms": BUCKET_MS, + "freeze_seconds": FREEZE_SECONDS, + "measured_refresh_hz": round(1.0 / period, 2) if period else None, + "binding_releases_gil": self._binding_gil, + "info": info, + "totals": copy.deepcopy(self.totals), + # JSON keys are strings; readers convert back. + "histograms": {name: {str(k): v for k, v in sorted(h.items())} + for name, h in self.histograms.items()}, + } + + def write(self) -> None: + """Replace the stats file atomically with the current snapshot.""" + directory = os.path.dirname(self.path) or "." + fd, tmp = tempfile.mkstemp(dir=directory, prefix=".frame_stats.", + suffix=".tmp") + try: + with os.fdopen(fd, "w", encoding="utf-8") as handle: + json.dump(self.snapshot(), handle) + os.chmod(tmp, 0o644) + os.replace(tmp, self.path) + except Exception: + try: + os.unlink(tmp) + except OSError: + pass + raise + + +def watchdog_settings() -> Dict[str, float]: + """StallWatchdog arguments from ``LEDMATRIX_STALL_WATCHDOG_MS``, if set. + + The poll comes down with the threshold, or a stall shorter than one poll + would go unseen. + """ + try: + ms = float(os.environ.get("LEDMATRIX_STALL_WATCHDOG_MS") or 0) + except ValueError: + ms = 0.0 + if ms <= 0: + return {} + threshold = ms / 1000.0 + return {"threshold": threshold, + "poll": min(WATCHDOG_POLL_SECONDS, threshold / 3)} + + +class StallWatchdog: + """Log what the render thread is doing when a scroll stops presenting. + + See the module docstring. Polls; never touches the render thread. + """ + + def __init__( + self, + recorder: FrameTimingRecorder, + threshold: float = STALL_SECONDS, + poll: float = WATCHDOG_POLL_SECONDS, + log_interval: float = STALL_LOG_INTERVAL, + clock: Callable[[], float] = time.perf_counter, + ): + self.recorder = recorder + self.threshold = threshold + self.poll = poll + self.log_interval = log_interval + self.clock = clock + self.stalls = 0 + self._last_dump: Optional[float] = None + self._thread: Optional[threading.Thread] = None + self._stop = threading.Event() + + def start(self) -> None: + self._thread = threading.Thread( + target=self._run, daemon=True, name="stall-watchdog") + self._thread.start() + + def stop(self, timeout: float = 1.0) -> None: + """End the polling thread (DisplayManager.cleanup calls this).""" + self._stop.set() + thread = self._thread + if thread is not None and thread is not threading.current_thread(): + thread.join(timeout) + + def _run(self) -> None: + last_wake = self.clock() + stall_from: Optional[float] = None # presented_at of the stalled frame + dumped = False + while not self._stop.wait(self.poll): + now = self.clock() + late = max(0.0, now - last_wake - self.poll) + last_wake = now + try: + stall_from, dumped = self.check(now, late, stall_from, dumped) + except Exception: # never let a diagnostic take anything down + logger.debug("Stall watchdog check failed", exc_info=True) + + def check(self, now: float, late: float, stall_from: Optional[float], + dumped: bool) -> Tuple[Optional[float], bool]: + """One look. Returns the updated (stall_from, dumped) state.""" + frame = self.recorder.last_frame + if frame is None: + return None, False + presented_at, scrolling, ident = frame + + if stall_from is not None and presented_at != stall_from: + # A frame arrived: the stall is over. + if dumped: + logger.warning( + "Render stall over: no frame for %.0fms", + (presented_at - stall_from) * 1000.0) + return None, False + + scrolling_now = self.recorder.scrolling_now + if (stall_from is not None and now - stall_from >= GAP_SECONDS + and (scrolling_now is None or not scrolling_now())): + # The scroll ended without another frame: nothing more to time. + # Only past GAP_SECONDS: the scroll state expires after 2s without + # activity, which a stall outlasts, and its end still wants saying. + return None, False + age = now - presented_at + if (stall_from is None and scrolling and age >= self.threshold + and scrolling_now is not None and scrolling_now()): + self.stalls += 1 + if self._last_dump is None or now - self._last_dump >= self.log_interval: + self._last_dump = now + logger.warning(self.describe(ident, age, late)) + return presented_at, True + return presented_at, False + return stall_from, dumped + + def describe(self, ident: int, age: float, late: float) -> str: + """The stack dump: the stalled thread in full, the rest in brief.""" + names = {t.ident: t.name for t in threading.enumerate()} + frames = sys._current_frames() + lines = [ + f"Render stall: no frame for {age * 1000.0:.0f}ms mid-scroll " + f"(watchdog woke {late * 1000.0:.0f}ms late" + + ("; the interpreter itself was blocked" if late >= age / 2 else "") + + ")", + f"-- {names.get(ident, ident)} (presents frames):", + ] + stalled = frames.get(ident) + if stalled is not None: + lines.extend(line.rstrip() for line in + traceback.format_stack(stalled, limit=12)) + for other, frame in frames.items(): + if other in (ident, threading.get_ident()): + continue + top = traceback.extract_stack(frame, limit=3) + where = " <- ".join( + f"{os.path.basename(f.filename)}:{f.lineno} {f.name}" + for f in reversed(top)) + lines.append(f"-- {names.get(other, other)}: {where}") + return "\n".join(lines) diff --git a/src/display_manager.py b/src/display_manager.py index de9708a0..2144be1d 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -51,6 +51,7 @@ import zlib import freetype from src.common import snapshot_policy +from src.common.frame_timing import FrameTimingRecorder from src.deprecation import deprecated from src.logging_config import get_logger from src.common.permission_utils import ( @@ -236,6 +237,11 @@ class DisplayManager: # See src/common/scroll_config.py and scripts/scroll_speeds.py. self._frame_hold = 1 + # Timing of every presented frame, whoever drew it, for + # scripts/frame_soak.py. See src/common/frame_timing.py. + self.frame_timing = FrameTimingRecorder(info=self._frame_timing_info()) + self.frame_timing.scrolling_now = self._scrolling_now + self._scrolling_state = { 'is_scrolling': False, 'last_scroll_activity': 0, @@ -798,15 +804,21 @@ class DisplayManager: # Copy the current image to the offscreen canvas. In double-sided # mode the logical screen is first tiled across the full chain. + blit_started = time.perf_counter() if self._double_sided is not None: self.offscreen_canvas.SetImage(self._composite_double_sided()) else: self.offscreen_canvas.SetImage(self.image) + blit_done = time.perf_counter() # Swap buffers immediately. framerate_fraction holds the frame # for N refreshes; SwapOnVSync blocks for all of them, which is # what paces the render loop to the chosen frame rate. self.matrix.SwapOnVSync(self.offscreen_canvas, self._frame_hold) + presented_at = time.perf_counter() + self.frame_timing.record( + blit_done - blit_started, presented_at - blit_done, + self._frame_hold, self.is_currently_scrolling(), presented_at) # Swap our canvas references self.offscreen_canvas, self.current_canvas = self.current_canvas, self.offscreen_canvas @@ -1295,6 +1307,9 @@ class DisplayManager: self._new_canvas(self.width, self.height) except (OSError, RuntimeError, ValueError, MemoryError): logger.debug("Canvas reset during cleanup failed", exc_info=True) + # The stall watchdog would otherwise outlive this manager. + if getattr(self, 'frame_timing', None) is not None: + self.frame_timing.close() # Reset the singleton state when cleaning up DisplayManager._instance = None @@ -1390,6 +1405,27 @@ class DisplayManager: value = 0.0 return value if value > 0 else 100.0 + def _scrolling_now(self) -> bool: + """Whether a scroll is running, without is_currently_scrolling()'s + side effect of expiring the state -- safe from the stall watchdog's + thread.""" + state = self._scrolling_state + return bool(state['is_scrolling']) and ( + time.time() - state['last_scroll_activity'] + <= state['scroll_inactivity_threshold']) + + def _frame_timing_info(self) -> Dict[str, Any]: + """What the frame-timing stats were measured on, for the soak report.""" + display = self.config.get('display') or {} + hardware = display.get('hardware') or {} + runtime = display.get('runtime') or {} + info = {key: hardware.get(key) for key in ( + 'rows', 'cols', 'chain_length', 'parallel', 'pwm_bits', + 'hardware_mapping', 'limit_refresh_rate_hz', 'pixel_mapper_config')} + info['gpio_slowdown'] = runtime.get('gpio_slowdown') + info['emulator'] = os.environ.get('EMULATOR', 'false') == 'true' + return info + def set_frame_hold(self, refreshes: int) -> None: """Hold each pushed frame for this many panel refreshes (>=1). diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py new file mode 100644 index 00000000..e3ffae68 --- /dev/null +++ b/test/test_frame_timing.py @@ -0,0 +1,596 @@ +"""System-wide frame timing (src/common/frame_timing.py) and its soak report. + +The recorder's job is to separate what a viewer sees as a hitch -- a moving +frame one or more refreshes late -- from things that are not jitter: static +screens, the first frame of a scroll, gaps between scrolls, and freezes. +""" +import json +import sys +import time +from pathlib import Path + +import pytest + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from src.common import frame_timing # noqa: E402 +from src.common.frame_timing import FrameTimingRecorder # noqa: E402 + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent / "scripts")) +import frame_soak # noqa: E402 + +PERIOD = 0.010 # a 100Hz panel + + +def _feed(recorder, intervals, hold=1, scrolling=True, start=100.0, + blit=0.002, wait=0.004): + """Present one frame, then one more per interval.""" + t = start + recorder.record(blit, wait, hold, scrolling, t) + for interval in intervals: + t += interval + recorder.record(blit, wait, hold, scrolling, t) + return t + + +def _aggregate(recorder): + batch, static = recorder._pending, recorder._static_frames + recorder._pending, recorder._static_frames = [], 0 + recorder.aggregate(batch, static) + return recorder.totals + + +def _recorder(tmp_path, **kwargs): + # A flush interval nothing in these tests reaches, so aggregation is + # driven explicitly and no worker thread starts. + return FrameTimingRecorder(path=str(tmp_path / "stats.json"), + flush_interval=1e9, **kwargs) + + +def _settle(recorder, interval=PERIOD, hold=1, start=0.0): + """Two agreeing windows: the refresh period is adopted from the second.""" + for offset in (0.0, 50.0): + _feed(recorder, [interval] * 200, hold=hold, start=start + offset) + _aggregate(recorder) + + +def test_steady_frames_are_on_time_and_give_the_refresh(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD] * 200) + _aggregate(r) + assert r.refresh_period is None # one window proves nothing yet + _feed(r, [PERIOD] * 200, start=500.0) + totals = _aggregate(r) + assert totals["scroll_frames"] == 400 + assert totals["timed_frames"] == 200 # the second window, judged + assert totals["late_frames"] == 0 + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + + +def test_a_bad_first_window_does_not_fix_the_period(tmp_path): + # Startup: nine frames in ten a refresh late, so that window's low end is + # two periods. Adopted outright, every later window (a 50% "drop") would + # be refused and one-refresh-late frames would read as on time for good. + r = _recorder(tmp_path) + _feed(r, [2 * PERIOD if i % 10 else PERIOD for i in range(200)]) + _aggregate(r) + for start in (500.0, 1000.0): + _feed(r, [PERIOD] * 200, start=start) + _aggregate(r) + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + + +def test_a_frame_a_refresh_late_is_counted(tmp_path): + r = _recorder(tmp_path, refresh_hz=100.0) + intervals = [PERIOD] * 200 + intervals[50] = 2 * PERIOD # one refresh late + intervals[120] = 4 * PERIOD # three refreshes late + _feed(r, intervals) + totals = _aggregate(r) + assert totals["late_frames"] == 2 + assert totals["missed_refreshes"] == 1 + 3 + assert totals["late_by"] == {"1": 1, "2": 0, "3-5": 1, "6+": 0} + + +def test_a_held_frame_is_not_late(tmp_path): + # 50px/s on a 100Hz panel is 1px every 2 refreshes: 20ms is on time. + r = _recorder(tmp_path) + _settle(r, 2 * PERIOD, hold=2) + assert r.totals["late_frames"] == 0 + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + + +def test_small_jitter_is_not_late(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD * (1 + 0.03 * ((i % 5) - 2)) for i in range(300)]) + assert _aggregate(r)["late_frames"] == 0 + + +def test_static_frames_and_the_start_of_a_scroll_are_not_timed(tmp_path): + r = _recorder(tmp_path) + t = _feed(r, [1.0, 1.0, 1.0], scrolling=False) + # The first scrolling frame follows a static one 300ms later: that is a + # scroll starting, not a 30-refresh stall. + _feed(r, [PERIOD] * 100, start=t + 0.3) + totals = _aggregate(r) + assert totals["static_frames"] == 4 + assert totals["scroll_frames"] == 100 + assert totals["late_frames"] == totals["freezes"] == 0 + + +def test_freezes_are_separate_from_late_frames_and_gaps_are_ignored(tmp_path): + r = _recorder(tmp_path) + intervals = [PERIOD] * 200 + intervals[80] = 0.400 # a render-thread plugin fetch: freeze + intervals[120] = 1.5 # a longer stall, still inside the scroll: freeze + intervals[150] = 6.0 # past any scroll's inactivity window: ignored + _feed(r, intervals) + totals = _aggregate(r) + assert totals["freezes"] == 2 + assert abs(totals["freeze_seconds"] - 1.9) < 1e-9 + assert totals["freeze_by"] == {"<0.5s": 1, "0.5-1s": 0, "1-2s": 1, "2s+": 0} + assert totals["late_frames"] == 0 + assert totals["scroll_frames"] == 197 + + +def test_a_stall_between_one_and_two_seconds_is_not_lost(tmp_path): + # Two "scrolling" frames can be up to DisplayManager's 2s inactivity + # threshold apart. The first version ignored everything past 1s, so a + # 1.4s render-thread stall vanished from the report. + r = _recorder(tmp_path) + intervals = [PERIOD] * 100 + intervals[40] = 1.4 + _feed(r, intervals) + assert _aggregate(r)["freezes"] == 1 + + +def test_a_stall_whose_scroll_state_went_missing_still_counts(tmp_path): + # hdpi, 14:48: the watchdog logged a 1.9s stall the soak never reported. + # A plugin captured between two Vegas frames cleared the scroll state, so + # the frame that ended the stall was recorded as static and its interval + # dropped. Vegas set the state again right after, as it does every frame. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t += 1.911 + r.record(0.002, 0.004, 1, False, t) # state missing: "static" + _feed(r, [PERIOD] * 100, start=t + PERIOD) # the scroll carries on + totals = _aggregate(r) + assert totals["freezes"] == 1 + assert totals["freeze_by"]["1-2s"] == 1 + assert totals["static_frames"] == 0 + # 100 before, the step back into the scroll, 100 after: all but the freeze. + assert totals["scroll_frames"] == 100 + 1 + 100 + + +def test_a_frame_with_its_scroll_state_missing_is_still_timed(tmp_path): + # No stall at all -- the state was cleared and the frame went out on + # time. Nothing is late and no interval is lost. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + PERIOD) + _feed(r, [PERIOD] * 100, start=t + 2 * PERIOD) + totals = _aggregate(r) + assert totals["scroll_frames"] == 202 + assert totals["late_frames"] == totals["freezes"] == totals["static_frames"] == 0 + + +def test_a_scroll_that_really_ended_is_not_a_freeze(tmp_path): + # Two static frames in a row, then a new scroll: the gaps between them + # were a static screen, not a stall. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t = _feed(r, [0.5], scrolling=False, start=t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.4) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 2 + assert totals["scroll_frames"] == 200 + + +def test_one_static_frame_then_a_scroll_much_later_is_a_new_scroll(tmp_path): + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.3 + frame_timing.RESUME_SECONDS + 0.1) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 1 + assert totals["scroll_frames"] == 200 + + +def test_a_missing_state_interval_is_due_at_the_scrolls_own_hold(tmp_path): + # Clearing the state drops the hold to 1 as well, so the "static" frame + # reports hold 1. Its interval is still due two refreshes after the last. + r = _recorder(tmp_path) + t = _feed(r, [2 * PERIOD] * 100, hold=2) + r.record(0.002, 0.004, 1, False, t + 2 * PERIOD) + _feed(r, [2 * PERIOD] * 100, hold=2, start=t + 4 * PERIOD) + totals = _aggregate(r) + assert totals["late_frames"] == totals["early_frames"] == 0 + assert totals["scroll_frames"] == 202 + + +def test_early_frames_are_counted(tmp_path): + # Hold 2 on a 100Hz panel: frames are due every 20ms. A swap that returns + # after 10ms did not wait out the hold. + r = _recorder(tmp_path) + _feed(r, [2 * PERIOD] * 200, hold=2) + _aggregate(r) + intervals = [2 * PERIOD] * 200 + for i in range(0, 200, 20): + intervals[i] = PERIOD + _feed(r, intervals, hold=2, start=1000.0) + totals = _aggregate(r) + assert totals["early_frames"] == 10 + assert totals["late_frames"] == 0 + + +def test_refresh_estimate_survives_a_window_full_of_misses(tmp_path): + r = _recorder(tmp_path) + _settle(r) + # A bad window where every frame is late must not redefine the refresh. + _feed(r, [2 * PERIOD] * 200, start=1000.0) + totals = _aggregate(r) + assert abs(1.0 / r.refresh_period - 100.0) < 0.5 + assert totals["late_frames"] == 200 + + +def test_record_hands_off_and_the_worker_writes_the_file(tmp_path): + path = tmp_path / "stats.json" + r = FrameTimingRecorder(path=str(path), flush_interval=0.5, + info={"cols": 128, "rows": 32}) + _feed(r, [PERIOD] * 120) # 1.2s of frames: at least one flush + deadline = time.time() + 5 + while not path.exists() and time.time() < deadline: + time.sleep(0.02) + stats = json.loads(path.read_text(encoding="utf-8")) + assert stats["version"] == frame_timing.SCHEMA_VERSION + assert stats["info"]["cols"] == 128 + assert stats["totals"]["scroll_frames"] > 0 + + +def test_soak_report_is_the_difference_between_snapshots(tmp_path): + r = _recorder(tmp_path) + _feed(r, [PERIOD] * 200) + _aggregate(r) + before = json.loads(json.dumps(r.snapshot())) + intervals = [PERIOD] * 1000 + intervals[500] = 0.0201 # a refresh late; off a bucket boundary + _feed(r, intervals, start=500.0) + _aggregate(r) + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + + report = frame_soak.build_report(before, after, preview=True) + assert report["scroll_frames"] == 1000 + assert report["late_frames"] == 1 + assert report["late_pct"] == 0.1 + assert report["timing_ms"]["blit"]["p50"] == 2.25 # 2ms lands in [2, 2.25) + assert report["timing_ms"]["interval_per_hold"]["max"] == 20.25 + + +def test_soak_fails_a_run_that_was_not_locked(tmp_path): + r = _recorder(tmp_path) + _settle(r, 2 * PERIOD, hold=2) + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [PERIOD] * 1000, hold=2, start=500.0) # never waited out the hold + _aggregate(r) + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert report["late_pct"] == 0.0 + assert report["early_pct"] == 100.0 + assert not frame_soak.passed(report, 0.1) + + +def test_frames_before_the_period_is_known_do_not_make_a_verdict(tmp_path): + # With no period, nothing was judged: 0 late of 200 is not a pass. + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [PERIOD] * 200) + _aggregate(r) + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert report["scroll_frames"] == 200 + assert report["timed_frames"] == 0 + assert report["late_pct"] is None + assert not frame_soak.passed(report, 0.1) + + +def test_a_snapshot_is_not_changed_by_what_comes_after_it(tmp_path): + # render_bench keeps the snapshot object itself, no JSON round trip; it + # used to share the live totals, so every graded run differenced to zero. + r = _recorder(tmp_path, refresh_hz=100.0) + _feed(r, [PERIOD] * 100) + _aggregate(r) + before = r.snapshot() + _feed(r, [PERIOD] * 300, start=500.0) + _aggregate(r) + after = r.snapshot() + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert report["scroll_frames"] == 300 + assert report["late_pct"] == 0.0 + + +def test_the_held_rate_is_read_from_the_bucket_midpoint(tmp_path): + # percentiles() gives a bucket's upper edge. At the midpoint of the + # [10.0, 10.25)ms bucket the upper edge would say 97.6Hz. + r = _recorder(tmp_path, refresh_hz=100.0) + before = json.loads(json.dumps(r.snapshot())) + _feed(r, [0.010125] * 300) + _aggregate(r) + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + report = frame_soak.build_report(before, after, preview=False) + assert report["held_refresh_hz"] == round(1000.0 / 10.125, 1) + + +def test_soak_percentiles_mark_the_overflow_bucket(): + top = frame_timing.BUCKET_COUNT - 1 + result = frame_soak.percentiles({0: 98, top: 2}, 0.25) + assert result["p50"] == 0.25 + assert str(result["max"]).startswith(">=") + + +def test_display_manager_records_every_presented_frame(monkeypatch): + """The hook sits in update_display, so every source is covered.""" + monkeypatch.setenv("EMULATOR", "true") + from src.display_manager import DisplayManager + DisplayManager._instance = None + DisplayManager._initialized = False + dm = DisplayManager({"display": { + "hardware": {"rows": 32, "cols": 64, "chain_length": 1, "parallel": 1}, + "runtime": {"gpio_slowdown": 0}}}, suppress_test_pattern=True) + try: + assert dm.frame_timing.info["cols"] == 64 + dm.set_scrolling_state(True) + for shade in (10, 20, 30): + dm.draw.rectangle([0, 0, 4, 4], fill=(shade, 0, 0)) + dm.update_display() + assert len(dm.frame_timing._pending) == 2 # 3 frames, 2 intervals + finally: + dm.set_scrolling_state(False) + DisplayManager._instance = None + DisplayManager._initialized = False + + +# --- stall watchdog ---------------------------------------------------------- + +class _FakeRecorder: + def __init__(self): + self.last_frame = None + self.scrolling = True + self.scrolling_now = lambda: self.scrolling + + +def test_watchdog_reports_a_stall_once_and_its_end(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + ident = __import__("threading").get_ident() + rec.last_frame = (10.0, True, ident) + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + state = dog.check(10.1, 0.0, None, False) # 100ms: fine + assert state == (None, False) + state = dog.check(10.4, 0.0, *state) # 400ms: stall + assert state == (10.0, True) + state = dog.check(10.9, 0.0, *state) # still stalled: no repeat + rec.last_frame = (11.2, True, ident) + state = dog.check(11.25, 0.0, *state) # a frame arrived + assert state == (None, False) + messages = [r.getMessage() for r in caplog.records] + assert len(messages) == 2 + assert messages[0].startswith("Render stall: no frame for 400ms") + assert "test_watchdog_reports_a_stall_once_and_its_end" in messages[0] + assert messages[1] == "Render stall over: no frame for 1200ms" + assert dog.stalls == 1 + + +def test_watchdog_ignores_a_scroll_that_ended(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + rec.last_frame = (10.0, True, 1) + rec.scrolling = False # the scroll handed over + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + assert dog.check(12.0, 0.0, None, False) == (None, False) + assert not caplog.records + + +def test_watchdog_names_what_the_stalled_thread_is_waiting_on(): + import threading + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec) + blocked, release = threading.Event(), threading.Event() + + def render_loop_waiting_on_a_lock(): + blocked.set() + release.wait(5) + + t = threading.Thread(target=render_loop_waiting_on_a_lock, name="render") + t.start() + try: + assert blocked.wait(5) + text = dog.describe(t.ident, 1.5, 1.4) + finally: + release.set() + t.join(5) + assert "no frame for 1500ms" in text + assert "the interpreter itself was blocked" in text + assert "-- render (presents frames):" in text + assert "render_loop_waiting_on_a_lock" in text + + +def test_watchdog_rate_limits_its_dumps(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=30.0) + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + for start in (10.0, 20.0): # two stalls 10s apart + rec.last_frame = (start, True, 1) + state = dog.check(start + 0.5, 0.0, None, False) + rec.last_frame = (start + 0.6, True, 1) + dog.check(start + 0.65, 0.0, *state) + dumps = [r for r in caplog.records if r.getMessage().startswith("Render stall:")] + assert len(dumps) == 1 + assert dog.stalls == 2 + + +def test_watchdog_reports_the_end_of_a_stall_that_outlasts_the_scroll_state(caplog): + # The scroll state expires after 2s without activity; a stall longer than + # that must still have its end reported. + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + rec.last_frame = (10.0, True, 1) + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + state = dog.check(10.3, 0.0, None, False) # dumped + rec.scrolling = False # state expired at 12.0 + state = dog.check(12.5, 0.0, *state) + rec.last_frame = (13.0, True, 1) # the frame arrives + dog.check(13.05, 0.0, *state) + over = [r.getMessage() for r in caplog.records + if r.getMessage().startswith("Render stall over")] + assert over == ["Render stall over: no frame for 3000ms"] + + +def test_closing_the_recorder_stops_its_watchdog(tmp_path, monkeypatch): + monkeypatch.delenv("LEDMATRIX_STALL_WATCHDOG", raising=False) + r = _recorder(tmp_path) + r.scrolling_now = lambda: True + r.record(0.001, 0.009, 1, True, 1.0) + thread = r.watchdog._thread + assert thread.is_alive() + r.close() + thread.join(2) + assert not thread.is_alive() + assert r.watchdog is None + + +def test_watchdog_threshold_can_be_lowered_for_a_diagnostic_run(monkeypatch): + monkeypatch.delenv("LEDMATRIX_STALL_WATCHDOG_MS", raising=False) + assert frame_timing.watchdog_settings() == {} + monkeypatch.setenv("LEDMATRIX_STALL_WATCHDOG_MS", "nonsense") + assert frame_timing.watchdog_settings() == {} + monkeypatch.setenv("LEDMATRIX_STALL_WATCHDOG_MS", "30") + settings = frame_timing.watchdog_settings() + assert settings["threshold"] == pytest.approx(0.030) + assert settings["poll"] == pytest.approx(0.010) # sees a stall one poll long + + # ...and the recorder starts its watchdog with them. + rec = frame_timing.FrameTimingRecorder(path=None) + rec.scrolling_now = lambda: True + monkeypatch.setattr(frame_timing.StallWatchdog, "start", lambda self: None) + rec.record(0.001, 0.009, 1, True, 1.0) + assert rec.watchdog.threshold == pytest.approx(0.030) + + +# --- 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() + _feed(r, [0.0012] * 500, start=500.0) + 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