mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-10-04 06:15:09 +00:00
ChuckandClaude Opus 5.5
5aa7a63127
A GcMonitor in src/common/frame_timing.py, installed once per process from gc.callbacks by the display manager (and render_bench), counts collections and seconds per generation, the longest, and those of 20 ms or more. A long one tags the next presented frame 'gc' in record(), so frame_soak shows its late rate under 'after work'; the stats file gains an additive 'gc' block printed as a 'Garbage collection' line; and a Render stall dump says when a long collection ran inside the stall. Diagnostic only: nothing tunes, freezes or disables the collector. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
480 lines
21 KiB
Python
480 lines
21 KiB
Python
#!/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). An open
|
|
# preview is encoded at most once a second; through 3.8.0 it was up to
|
|
# five times, so a --preview run from before that change is not comparable
|
|
# with one from after it
|
|
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
|
|
the display controller does not tag (see handover gaps),
|
|
blocking calls on the render thread. Reported, not failed on,
|
|
since some are handovers between plugins rather than faults.
|
|
handover gaps the same length of gap where the display controller had just
|
|
started a screen's turn (also the same mode's again): its
|
|
first display() drawing. Counted here instead of under
|
|
freezes. Stats from a service older than this count have no
|
|
such line, and their freezes include these, so do not
|
|
compare freeze counts across that change.
|
|
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.
|
|
after work frames presented straight after tagged render-thread work
|
|
(Vegas strip extensions, live-element patches), with their own
|
|
late rate. Shown only when something tagged its work.
|
|
"""
|
|
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 the viewer rate
|
|
#: (snapshot_policy.VIEWER_INTERVAL). 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 op_rows(totals: Dict[str, Any]) -> Dict[str, Dict[str, Any]]:
|
|
"""Per kind of noted render-thread work: how often its frame was late.
|
|
|
|
A kind's frames are the ones presented straight after that work ran (see
|
|
"Operations" in src/common/frame_timing.py). Stats from a recorder that
|
|
predates the counters have none, and give an empty table.
|
|
"""
|
|
frames = totals.get("op_frames") or {}
|
|
late = totals.get("late_op_frames") or {}
|
|
freezes = totals.get("op_freezes") or {}
|
|
moved = totals.get("op_bytes") or {}
|
|
rows = {}
|
|
for kind in sorted(set(frames) | set(freezes)):
|
|
count = frames.get(kind, 0)
|
|
if not count and not freezes.get(kind, 0):
|
|
continue
|
|
rows[kind] = {
|
|
"frames": count,
|
|
"late": late.get(kind, 0),
|
|
"late_pct": (round(100.0 * late.get(kind, 0) / count, 3)
|
|
if count else None),
|
|
"freezes": freezes.get(kind, 0),
|
|
"bytes": moved.get(kind, 0),
|
|
}
|
|
return rows
|
|
|
|
|
|
def gc_window(before: Dict[str, Any], after: Dict[str, Any]) -> Optional[Dict[str, Any]]:
|
|
"""Garbage collection over the run, or None from a service without the
|
|
monitor. The counters are cumulative since the service started, so they
|
|
are differenced like the totals; the longest is since the start."""
|
|
ga = after.get("gc")
|
|
if not ga:
|
|
return None
|
|
gb = before.get("gc") or {}
|
|
def minus(key):
|
|
return [a - b for a, b in zip(ga.get(key, []),
|
|
gb.get(key) or [0] * len(ga.get(key, [])))]
|
|
seconds = minus("seconds")
|
|
return {
|
|
"collections": minus("collections"),
|
|
"ms": [round(x * 1000.0, 1) for x in seconds],
|
|
"long_pauses": ga.get("long_pauses", 0) - gb.get("long_pauses", 0),
|
|
"long_ms": round((ga.get("long_seconds", 0.0)
|
|
- gb.get("long_seconds", 0.0)) * 1000.0, 1),
|
|
"threshold_ms": ga.get("threshold_ms"),
|
|
"max_ms_since_start": ga.get("max_ms"),
|
|
}
|
|
|
|
|
|
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),
|
|
# None from a service that predates the count: its handovers are
|
|
# among the freezes above.
|
|
"handover_freezes": totals.get("handover_freezes"),
|
|
"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()},
|
|
"ops": op_rows(totals),
|
|
"gc": gc_window(before, after),
|
|
}
|
|
# 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()))
|
|
if report.get("handover_freezes") is not None:
|
|
print(f"Handover gaps {report['handover_freezes']}"
|
|
" >=250ms before a new screen's first frame; not in the freezes")
|
|
gc_stats = report.get("gc")
|
|
if gc_stats:
|
|
counts, ms = gc_stats["collections"], gc_stats["ms"]
|
|
print(f"Garbage collection gen0/1/2 {counts[0]}/{counts[1]}/{counts[2]}"
|
|
f" ({ms[0]}/{ms[1]}/{ms[2]} ms) >={gc_stats['threshold_ms']:g}ms: "
|
|
f"{gc_stats['long_pauses']} ({gc_stats['long_ms']} ms)"
|
|
f" longest since start {gc_stats['max_ms_since_start']} ms")
|
|
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()
|
|
ops = report.get("ops") or {}
|
|
if ops:
|
|
# Frames presented straight after render-thread work of each kind. A
|
|
# late rate well above the overall one points at that work.
|
|
print(f"{'after work':<18}{'frames':>8}{'late':>8}{'late %':>8}"
|
|
f"{'freezes':>9}{'MB moved':>10}")
|
|
for kind, row in ops.items():
|
|
pct = "-" if row["late_pct"] is None else f"{row['late_pct']:g}"
|
|
print(f"{kind:<18}{row['frames']:>8}{row['late']:>8}{pct:>8}"
|
|
f"{row['freezes']:>9}{row['bytes'] / 1e6:>10.2f}")
|
|
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())
|