LEDMatrix/scripts/frame_soak.py

#!/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"]
    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"],
        "late_pct": round(100.0 * totals["late_frames"] / frames, 3) if frames 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) / frames, 3)
                      if frames 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")
    report["held_refresh_hz"] = (round(1000.0 / typical, 1)
                                 if isinstance(typical, (int, float)) and typical else None)
    return report


def print_report(report: Dict[str, Any], limit: float) -> None:
    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())