mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-10-04 22:35:08 +00:00
feat(perf): frame timing for every presented frame, a soak tool, a render bench and a stall watchdog (#629)
src/common/frame_timing.py times every frame the display presents, whoever drew it, and writes cumulative counters to /dev/shm. scripts/frame_soak.py grades a running service (late frames, freezes, where the time goes) and scripts/render_bench.py the hardware and render path alone. A stall watchdog logs the stacks behind any scroll held up for 250 ms or more (LEDMATRIX_STALL_WATCHDOG_MS lowers that). See docs/SCROLL_PERFORMANCE.md, "Soaking a rig". Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Chuck
@@ -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())
|
||||
Reference in New Issue
Block a user