From 1252df9bad869f6ff92cab74a89cb58610a0db59 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Wed, 30 Sep 2026 10:25:09 -0400 Subject: [PATCH] perf(timing): say which render-thread work a late frame followed The soak already says how often a moving frame reached the panel late, but not what the render thread was doing just before it. Vegas does two kinds of work there between frames -- building its strip (compose, extend) and, with live elements, patching changed pixels into it -- and deciding whether either is affordable needs their own numbers. - FrameTimingRecorder.note_op(kind, nbytes) tags the next presented frame. Totals gain op_frames, late_op_frames, op_freezes and op_bytes per kind; aggregate() still takes frames without ops. The file schema is unchanged. - Vegas tags compose and every strip extension (with the bytes it copied). - frame_soak prints an "after work" table: frames, late %, freezes and MB moved per kind, only when something tagged its work. - render_bench gains --strip-screens (Vegas-sized strips), --patch-bytes / --patch-every / --patch-where (in-place column writes, as a live element update does) and --extend-every-screens / --extend-width (append + trim on a fixed cadence that holds the strip's width). No runtime behaviour changes: this is the measurement gate for live Vegas elements. Co-Authored-By: Claude Opus 5.5 --- docs/SCROLL_PERFORMANCE.md | 7 + scripts/frame_soak.py | 42 ++++ scripts/render_bench.py | 199 +++++++++++++++- src/common/frame_timing.py | 81 ++++++- src/vegas_mode/render_pipeline.py | 22 ++ test/test_frame_ops.py | 363 ++++++++++++++++++++++++++++++ 6 files changed, 695 insertions(+), 19 deletions(-) create mode 100644 test/test_frame_ops.py diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index d8ff8f25..908d4685 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -342,6 +342,7 @@ service's user. | **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*. | +| **after work** | Frames presented straight after tagged render-thread work, with their own late rate: `extend` and `compose` (Vegas building its strip), `patch` (live elements, once they land). A kind whose late rate sits well above the overall one is the work making frames late. Shown only when something tagged its work. | The refresh rate is estimated from the frames themselves (swaps that block on vsync can only land on refresh boundaries). Cross-check it with @@ -406,6 +407,10 @@ sudo python3 scripts/render_bench.py --speed 50 # a held (frame_hold 2) spe sudo python3 scripts/render_bench.py --busy 2 # with threads imitating plugin updates sudo python3 scripts/render_bench.py --json /tmp/pi4-512x64.json +# render-thread strip work, each tagged so the report gives it a late rate: +sudo python3 scripts/render_bench.py --patch-bytes 101376 --patch-every 25 # a live map patch +sudo python3 scripts/render_bench.py --strip-screens 30 --extend-every-screens 6 # Vegas extensions + sudo systemctl start ledmatrix ``` @@ -468,6 +473,8 @@ refreshes" comes from. | `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. | +| `patches` | `--patch-bytes N --patch-every K`: N bytes of columns written into the strip in place every K frames, on screen or (`--patch-where ahead`) just past it -- what a live element update costs the render thread. Their frames are the `patch` row under *after work*. | +| `extensions` | `--extend-every-screens N`: a block appended and the scrolled-past columns trimmed every N screens, as continuous Vegas does. The cost is a copy of the whole strip, so size it like Vegas's with `--strip-screens` (8,000-20,000px). Their frames are the `extend` row. | `--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 diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index da233da7..1d347567 100644 --- a/scripts/frame_soak.py +++ b/scripts/frame_soak.py @@ -35,6 +35,9 @@ blit copying the frame into the matrix canvas (rgbmatrix SetImage). 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 @@ -126,6 +129,33 @@ def _edge(index: int, bucket_ms: float): 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 build_report(before, after, preview: bool) -> Dict[str, Any]: delta = diff(before, after) totals = delta["totals"] @@ -159,6 +189,7 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]: 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), } # 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 @@ -216,6 +247,17 @@ def print_report(report: Dict[str, Any], limit: float) -> None: 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): diff --git a/scripts/render_bench.py b/scripts/render_bench.py index 17f3d259..35325789 100755 --- a/scripts/render_bench.py +++ b/scripts/render_bench.py @@ -25,6 +25,14 @@ against another) and for A/B testing a change to the render path. sudo python3 scripts/render_bench.py --busy 2 # with background load sudo python3 scripts/render_bench.py --json /tmp/pi4.json + # the cost of changing pixels under a moving strip (Vegas live elements): + # a 101KB write into the visible columns every 25 frames + sudo python3 scripts/render_bench.py --patch-bytes 101376 --patch-every 25 + + # the cost of extending a Vegas-sized strip on the render thread: a 30-screen + # strip, extended by 6 screens (and trimmed) every 6 screens scrolled + sudo python3 scripts/render_bench.py --strip-screens 30 --extend-every-screens 6 + sudo systemctl start ledmatrix Like scripts/scroll_speeds.py, this never starts or stops the service itself, @@ -92,13 +100,17 @@ def load_config() -> dict: return config -def build_strip(width: int, height: int, label: str): - """A marquee strip a few screens wide, with text and colour. +def build_strip(width: int, height: int, label: str, screens: float = 4.0): + """A marquee strip about ``screens`` 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. + + The width matters to the extension mode, whose cost is a copy of the whole + strip: Vegas carries 8,000-20,000 columns, so measure extension against a + strip that wide (``--strip-screens``), not the four-screen default. """ from PIL import Image, ImageDraw, ImageFont @@ -123,7 +135,7 @@ def build_strip(width: int, height: int, label: str): text_width = max(1, box[2] - box[0]) text_height = box[3] - box[1] - reps = max(2, (width * 4) // text_width + 1) + reps = max(2, int(width * screens) // 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 @@ -179,6 +191,119 @@ class BackgroundLoad: zlib.compress(image.tobytes(), 1) +class StripWork: + """Render-thread work a Vegas strip does between frames, on a schedule. + + Patching writes a block of columns into the strip in place, as a live + element update does. Extending appends a block and trims what has scrolled + past, as continuous Vegas does (render_pipeline.extend_scroll_content). + Both run where Vegas runs them -- on the frame loop, before the next frame + is drawn -- and are tagged with ``FrameTimingRecorder.note_op``, so the + report shows how often the frame straight after each one was late. + + The content comes from the benchmark's own strip, prepared before the run: + in Vegas it is drawn off the render thread, so drawing it here would time + work the render thread never does. + """ + + def __init__(self, helper, recorder, source, *, patch_bytes: int = 0, + patch_every: int = 25, patch_where: str = "visible", + extend_every_screens: float = 0.0, extend_width: int = 0, + separator: int = 32) -> None: + import numpy as np + from PIL import Image + + self.helper = helper + self.recorder = recorder + self.width = helper.display_width + self.height = helper.display_height + self.patch_every = max(1, int(patch_every)) + self.patch_where = patch_where + self.separator = max(0, int(separator)) + self.patches = 0 + self.patched_bytes = 0 + self.extensions = 0 + self._frames = 0 + self._position_at_extend = 0.0 + + pixels = np.asarray(source.convert("RGB")) + source_width = pixels.shape[1] + + def columns(count: int, offset: int): + # Wraps around the source, so any width can be cut from it. + return np.ascontiguousarray( + pixels[:, (np.arange(count) + offset) % source_width]) + + # Two versions to alternate between, so every patch changes pixels. + self._patches = [] + if patch_bytes > 0: + count = max(1, int(patch_bytes) // (self.height * 3)) + self._patches = [columns(count, 0), columns(count, count)] + + self.extend_every = (int(extend_every_screens * self.width) + if extend_every_screens > 0 else 0) + self._blocks = [] + if self.extend_every: + # By default each append (block plus its separator) replaces + # exactly what scrolled past since the last one, so the strip + # holds its width, as Vegas's does in the steady state. + count = int(extend_width) or max(1, self.extend_every - self.separator) + self._blocks = [Image.fromarray(columns(count, 0)), + Image.fromarray(columns(count, count))] + + def reset(self) -> None: + """The strip was restarted from the beginning.""" + self._position_at_extend = self.helper.scroll_position + + def before_frame(self) -> None: + """Do whatever work is due before the next frame is drawn.""" + if self._blocks: + self._extend_if_due() + if self._patches: + self._frames += 1 + if self._frames % self.patch_every == 0: + self._patch() + + def _extend_if_due(self) -> None: + helper = self.helper + if helper.scroll_position < self._position_at_extend: + self._position_at_extend = helper.scroll_position + # Due on a fixed cadence rather than N screens after the last one ran, + # which would drift by the overshoot of a multi-pixel step each time. + due_at = self._position_at_extend + self.extend_every + if helper.scroll_position < due_at: + return + block = self._blocks[self.extensions % 2] + helper.append_content([block], item_gap=self.separator, element_gap=0) + moved = helper.cached_array.nbytes + # One screen kept behind the viewport, as Vegas does. The trim shifts + # every strip coordinate, the cadence's included. + cut = helper.drop_scrolled_prefix(keep_before=self.width) + if cut: + moved += helper.cached_array.nbytes + self._position_at_extend = due_at - cut + self.extensions += 1 + self.recorder.note_op("extend", moved) + + def _patch(self) -> None: + patch = self._patches[self.patches % 2] + strip = self.helper.cached_array + count = patch.shape[1] + if strip is None or count > strip.shape[1]: + return + start = int(self.helper.scroll_position) + if self.patch_where == "visible": + x = start + max(0, (self.width - count) // 2) + else: + # Just past the right edge: a change to content not yet on screen. + x = start + self.width + 16 + x = max(0, min(x, strip.shape[1] - count)) + strip[:, x:x + count] = patch + self.patches += 1 + self.patched_bytes += patch.nbytes + self.recorder.note_op("patch", patch.nbytes) + + def main(argv=None) -> int: parser = argparse.ArgumentParser( @@ -202,8 +327,36 @@ def main(argv=None) -> int: 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)") + parser.add_argument("--strip-screens", type=float, default=4.0, metavar="S", + help="strip width in screens (default 4). Vegas strips are " + "8,000-20,000px; the extension cost scales with it") + parser.add_argument("--patch-bytes", type=int, default=0, metavar="N", + help="write N bytes of columns into the strip in place " + "every --patch-every frames, as a Vegas live element " + "update does (a 150x64 card is ~29KB, a 512x64 map " + "~100KB)") + parser.add_argument("--patch-every", type=int, default=25, metavar="K", + help="frames between patches (default 25; 1 = every frame)") + parser.add_argument("--patch-where", choices=("visible", "ahead"), + default="visible", + help="patch the columns on screen, or just past its right " + "edge (default visible)") + parser.add_argument("--extend-every-screens", type=float, default=0.0, + metavar="N", + help="append a block and trim the strip every N screens " + "scrolled, as continuous Vegas does") + parser.add_argument("--extend-width", type=int, default=0, metavar="W", + help="width of each appended block in px (default: N " + "screens less the separator, so the strip holds its " + "width)") args = parser.parse_args(argv) + if args.extend_every_screens > 0 and args.strip_screens < args.extend_every_screens + 3: + # The strip must stay ahead of the viewport between extensions. + args.strip_screens = args.extend_every_screens + 3 + print(f"strip widened to {args.strip_screens:g} screens so extensions " + "keep ahead of the viewport") + # 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. @@ -272,8 +425,9 @@ def main(argv=None) -> int: 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")) + strip = build_strip(width, height, f"{choice.pixels_per_second:.0f} px/s", + screens=args.strip_screens) + helper.set_scrolling_image(strip) # 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 @@ -288,8 +442,23 @@ def main(argv=None) -> int: 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 "") + work = StripWork(helper, recorder, strip, + patch_bytes=args.patch_bytes, patch_every=args.patch_every, + patch_where=args.patch_where, + extend_every_screens=args.extend_every_screens, + extend_width=args.extend_width) + + doing = [] + if args.busy: + doing.append(f"{args.busy} background worker(s)") + if args.patch_bytes > 0: + doing.append(f"a {args.patch_bytes}B {args.patch_where} patch every " + f"{args.patch_every} frame(s)") + if work.extend_every: + doing.append(f"an extension every {args.extend_every_screens:g} screens") + print(f"scrolling {width}x{height} ({helper.cached_array.shape[1]}px strip) " + f"for {args.seconds:.0f}s" + + (" with " + ", ".join(doing) if doing else "") + " ...", flush=True) frames = 0 @@ -309,8 +478,11 @@ def main(argv=None) -> int: before = recorder.snapshot() run_started = now frames = duplicates = blanks = restarts = 0 + work.patches = work.patched_bytes = work.extensions = 0 if run_started is not None and now - run_started >= args.seconds: break + # Where Vegas does its strip work: before the frame is drawn. + work.before_frame() helper.update_scroll_position() if helper.is_scroll_complete(): # The helper parks at the end of the strip and stops @@ -320,6 +492,7 @@ def main(argv=None) -> int: # the benchmark measures a still image for the rest of the # run and reports a smoothness it never demonstrated. helper.reset_scroll() + work.reset() restarts += 1 visible = helper.get_visible_portion() column = int(helper.scroll_position) @@ -375,6 +548,11 @@ def main(argv=None) -> int: if restarts: print(f"restarts {restarts} (the strip was scrolled through " f"{restarts} time{'s' if restarts != 1 else ''})") + if work.patches: + print(f"patches {work.patches} ({work.patched_bytes / 1e6:.1f} MB " + "written into the strip)") + if work.extensions: + print(f"extensions {work.extensions}") if args.json_path: report.update({ @@ -388,6 +566,13 @@ def main(argv=None) -> int: "duplicate_frames": duplicates, "blank_frames": blanks, "strip_restarts": restarts, + "strip_screens": args.strip_screens, + "patch_bytes": args.patch_bytes, + "patch_every": args.patch_every, + "patch_where": args.patch_where, + "patches": work.patches, + "extend_every_screens": args.extend_every_screens, + "extensions": work.extensions, "max_late_pct": args.max_late_pct, "passed": frame_soak.passed(report, args.max_late_pct), }) diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 46305bd6..dea2fd94 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -66,6 +66,17 @@ 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. +Operations +---------- +The late count says how often, not which work did it. Render-thread work that +happens between two frames -- extending the Vegas strip, patching a live +element into it -- calls :meth:`FrameTimingRecorder.note_op` first, and the +next presented frame carries the tag: the interval that frame ends is the one +the work landed in. ``op_frames`` counts timed frames per kind, +``late_op_frames`` the late ones among them, ``op_freezes`` those that were a +freeze instead, and ``op_bytes`` what the work moved. A kind whose late rate +sits well above the overall one is the work to look at. + Stall watchdog -------------- Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the @@ -153,11 +164,20 @@ def default_stats_path() -> str: return os.path.join(base, STATS_FILENAME) +#: One presented frame's interval: (interval, blit, wait, hold, ops), where +#: ops is the work noted before it (kind -> bytes) or None. +_Frame = Tuple[float, float, float, int, Optional[Dict[str, int]]] + + def _bucket(seconds: float) -> int: index = int(seconds * 1000.0 / BUCKET_MS) return min(max(index, 0), BUCKET_COUNT - 1) +def _bump(counter: Dict[str, int], key: str, by: int = 1) -> None: + counter[key] = counter.get(key, 0) + by + + def binding_releases_gil() -> Optional[bool]: """Whether the loaded rgbmatrix binding releases the GIL, or None. @@ -250,12 +270,14 @@ class FrameTimingRecorder: self.info = dict(info or {}) # Render-thread state. - self._pending: List[Tuple[float, float, float, int]] = [] + self._pending: List[_Frame] = [] 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._unsure: Optional[_Frame] = None + # Work noted since the last frame (kind -> bytes), for the next one. + self._ops: Optional[Dict[str, int]] = None self._last_flush: Optional[float] = None self._queue: "queue.SimpleQueue" = queue.SimpleQueue() self._worker: Optional[threading.Thread] = None @@ -281,6 +303,11 @@ class FrameTimingRecorder: "freeze_seconds": 0.0, "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS}, "worst_interval_ms": 0.0, + # Per kind of noted render-thread work; see "Operations". + "op_frames": {}, + "late_op_frames": {}, + "op_freezes": {}, + "op_bytes": {}, } self.histograms: Dict[str, Dict[int, int]] = { "blit": {}, "wait": {}, "work": {}, "interval_per_hold": {}, @@ -305,6 +332,21 @@ class FrameTimingRecorder: # -- render thread ------------------------------------------------------ + def note_op(self, kind: str, nbytes: int = 0) -> None: + """Tag the next presented frame with work done before it. + + Render thread only, like :meth:`record`, which consumes the tag: the + interval the next frame ends is the one this work landed in. Several + notes before one frame accumulate, per kind. See "Operations". + + :param kind: a short name for the work, e.g. ``"extend"``, ``"patch"``. + :param nbytes: how much the work moved, summed into ``op_bytes``. + """ + ops = self._ops + if ops is None: + ops = self._ops = {} + ops[kind] = ops.get(kind, 0) + int(nbytes) + def record(self, blit: float, wait: float, hold: int, scrolling: bool, presented_at: float) -> None: """One frame reached the panel. @@ -318,6 +360,7 @@ class FrameTimingRecorder: previous = self._previous self._previous = (presented_at, scrolling, hold) self.last_frame = (presented_at, scrolling, threading.get_ident()) + ops, self._ops = self._ops, None if not scrolling: self._static_frames += 1 # The scroll ended, or its state went missing for this frame: the @@ -325,7 +368,8 @@ class FrameTimingRecorder: # 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]) + self._unsure = (presented_at - previous[0], blit, wait, + previous[2], ops) 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()) @@ -335,14 +379,14 @@ class FrameTimingRecorder: unsure, self._unsure = self._unsure, None if previous[1]: if interval < GAP_SECONDS: - self._pending.append((interval, blit, wait, hold)) + self._pending.append((interval, blit, wait, hold, ops)) 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)) + self._pending.append((interval, blit, wait, hold, ops)) if self._last_flush is None: self._last_flush = presented_at @@ -382,15 +426,17 @@ class FrameTimingRecorder: 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.""" + def aggregate(self, batch: List[_Frame], static: int) -> None: + """Fold one window of frames into the running totals. + + Each frame is ``(interval, blit, wait, hold, ops)``; ``ops`` (the work + noted before it, or None) may be left off. + """ totals = self.totals totals["static_frames"] += static - per_hold = sorted(interval / max(1, hold) - for interval, _, _, hold in batch - if interval < FREEZE_SECONDS) + per_hold = sorted(frame[0] / max(1, frame[3]) for frame in batch + if frame[0] < FREEZE_SECONDS) if len(per_hold) >= MIN_FRAMES_FOR_REFRESH: estimate = per_hold[len(per_hold) // 10] current = self.refresh_period @@ -412,15 +458,22 @@ class FrameTimingRecorder: period = self.refresh_period histograms = self.histograms - for interval, blit, wait, hold in batch: + for frame in batch: + interval, blit, wait, hold = frame[:4] + ops = frame[4] if len(frame) > 4 else None totals["worst_interval_ms"] = max(totals["worst_interval_ms"], interval * 1000.0) + if ops: + for kind, nbytes in ops.items(): + _bump(totals["op_bytes"], kind, nbytes) 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 + for kind in ops or (): + _bump(totals["op_freezes"], kind) continue totals["scroll_frames"] += 1 for name, value in (("blit", blit), ("wait", wait), @@ -432,6 +485,10 @@ class FrameTimingRecorder: if period: totals["timed_frames"] += 1 missed = round(interval / period) - hold + for kind in ops or (): + _bump(totals["op_frames"], kind) + if missed >= 1: + _bump(totals["late_op_frames"], kind) if missed >= 1: totals["late_frames"] += 1 totals["missed_refreshes"] += missed diff --git a/src/vegas_mode/render_pipeline.py b/src/vegas_mode/render_pipeline.py index 9de7d85a..8558a0a8 100644 --- a/src/vegas_mode/render_pipeline.py +++ b/src/vegas_mode/render_pipeline.py @@ -328,6 +328,7 @@ class RenderPipeline: return False self._static_markers = self._markers_for_composition(blocks) + self._note_op('compose', self._strip_nbytes()) # Track which plugins are in this scroll (get safely via buffer status) self._segments_in_scroll = self.stream_manager.get_active_plugin_ids() @@ -356,6 +357,22 @@ class RenderPipeline: logger.exception("Error composing scroll content") return False + def _note_op(self, kind: str, nbytes: int = 0) -> None: + """Tag the next presented frame with render-thread work done for it. + + See "Operations" in src/common/frame_timing.py: a soak can then say + how often a frame straight after an extension or a patch was late, + rather than only how often any frame was. + """ + timing = getattr(self.display_manager, 'frame_timing', None) + note = getattr(timing, 'note_op', None) + if note is not None: + note(kind, nbytes) + + def _strip_nbytes(self) -> int: + array = self.scroll_helper.cached_array + return int(array.nbytes) if array is not None else 0 + def _markers_for_composition(self, blocks: List[Image.Image]) -> Tuple[Tuple[int, str], ...]: """Static markers for a strip just built by create_scrolling_image. @@ -525,6 +542,7 @@ class RenderPipeline: element_gap=0, ) if appended: + self._note_op('extend', self._strip_nbytes()) logger.info( "[%s] Appended deferred content: strip now %dpx, %dpx ahead", plugin_id, self.scroll_helper.total_scroll_width, @@ -626,6 +644,7 @@ class RenderPipeline: ) if not appended: return False + moved = self._strip_nbytes() if statics: # Where each block ends, laid out as append_content does: a @@ -646,6 +665,9 @@ class RenderPipeline: if cut and self._static_markers: self._static_markers = tuple( (max(0, x - cut), pid) for x, pid in self._static_markers) + # The append built the whole strip anew, and a trim copies what is + # left of it again: both land in the frame after this one. + self._note_op('extend', moved + (self._strip_nbytes() if cut else 0)) self._segments_in_scroll = [pid for pid, _ in grouped] self.stats['composition_count'] += 1 diff --git a/test/test_frame_ops.py b/test/test_frame_ops.py new file mode 100644 index 00000000..d3e255be --- /dev/null +++ b/test/test_frame_ops.py @@ -0,0 +1,363 @@ +"""Attributing late frames to render-thread work (FrameTimingRecorder.note_op). + +The recorder already says how often a moving frame was late. These tests pin +the part that says which work it followed: Vegas tags a strip extension or a +live-element patch before the frame it lands in, and the soak report gives +each kind its own late rate. The render bench drives the same work on a +schedule so it can be measured on a panel with nothing else running. +""" +import json +import sys +from pathlib import Path + +import numpy as np +from PIL import Image + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) +sys.path.insert(0, str(Path(__file__).resolve().parent.parent / "scripts")) + +from src.common.frame_timing import FrameTimingRecorder # noqa: E402 +from src.common.scroll_helper import ScrollHelper # noqa: E402 +from src.vegas_mode.config import VegasModeConfig # noqa: E402 +from src.vegas_mode.render_pipeline import RenderPipeline # noqa: E402 + +import frame_soak # noqa: E402 +import render_bench # noqa: E402 + +PERIOD = 0.010 # a 100Hz panel + + +def _recorder(tmp_path, **kwargs): + return FrameTimingRecorder(path=str(tmp_path / "stats.json"), + flush_interval=1e9, refresh_hz=100.0, **kwargs) + + +def _frame(recorder, t, scrolling=True, hold=1): + recorder.record(0.002, 0.004, hold, scrolling, t) + + +def _totals(recorder): + recorder.drain() + return recorder.totals + + +# -- the recorder ----------------------------------------------------------- + + +def test_a_noted_op_tags_the_next_frame_only(tmp_path): + r = _recorder(tmp_path) + t = 100.0 + _frame(r, t) + for i in range(10): + if i == 4: + r.note_op("patch", 1000) + t += PERIOD + _frame(r, t) + totals = _totals(r) + assert totals["op_frames"] == {"patch": 1} + assert totals["late_op_frames"] == {} + assert totals["op_bytes"] == {"patch": 1000} + + +def test_a_late_frame_after_an_op_is_counted_against_it(tmp_path): + r = _recorder(tmp_path) + t = 100.0 + _frame(r, t) + for i in range(20): + late = i in (5, 12) + if late or i == 15: + r.note_op("extend", 4_000_000) + t += 2 * PERIOD if late else PERIOD + _frame(r, t) + totals = _totals(r) + assert totals["late_frames"] == 2 + assert totals["op_frames"] == {"extend": 3} + assert totals["late_op_frames"] == {"extend": 2} + assert totals["op_bytes"] == {"extend": 12_000_000} + + +def test_notes_before_one_frame_accumulate_per_kind(tmp_path): + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("patch", 100) + r.note_op("patch", 50) + r.note_op("extend", 7) + _frame(r, 100.0 + PERIOD) + totals = _totals(r) + assert totals["op_frames"] == {"patch": 1, "extend": 1} + assert totals["op_bytes"] == {"patch": 150, "extend": 7} + + +def test_an_op_before_a_freeze_is_a_freeze_not_a_late_frame(tmp_path): + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("extend", 10) + _frame(r, 100.4) + totals = _totals(r) + assert totals["freezes"] == 1 + assert totals["op_freezes"] == {"extend": 1} + assert totals["op_frames"] == {} + assert totals["op_bytes"] == {"extend": 10} + + +def test_an_op_survives_the_scroll_state_going_missing_for_a_frame(tmp_path): + # The frame the op landed in was presented with the scroll state missing; + # the scroll resumed, so the interval counts, and so does its tag. + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("patch", 5) + _frame(r, 100.0 + 2 * PERIOD, scrolling=False) + _frame(r, 100.0 + 3 * PERIOD) + totals = _totals(r) + assert totals["late_frames"] == 1 + assert totals["late_op_frames"] == {"patch": 1} + + +def test_an_op_noted_before_a_static_frame_is_dropped(tmp_path): + r = _recorder(tmp_path) + _frame(r, 100.0, scrolling=False) + r.note_op("patch", 5) + _frame(r, 101.0, scrolling=False) + _frame(r, 102.0, scrolling=False) + totals = _totals(r) + assert totals["op_frames"] == {} and totals["op_bytes"] == {} + + +def test_frames_before_the_period_is_known_are_not_op_frames(tmp_path): + # op_frames is a denominator for late_op_frames, which needs a period. + r = FrameTimingRecorder(path=str(tmp_path / "s.json"), flush_interval=1e9) + _frame(r, 100.0) + r.note_op("patch", 5) + _frame(r, 100.0 + PERIOD) + totals = _totals(r) + assert totals["op_frames"] == {} + assert totals["op_bytes"] == {"patch": 5} + + +def test_aggregate_still_takes_frames_without_ops(tmp_path): + r = _recorder(tmp_path) + r.aggregate([(PERIOD, 0.002, 0.004, 1)] * 5, 0) + assert r.totals["scroll_frames"] == 5 + assert r.totals["op_frames"] == {} + + +# -- the soak report ---------------------------------------------------------- + + +def _report(r, before): + r.drain() + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + return frame_soak.build_report(before, after, preview=False) + + +def test_the_soak_report_gives_each_kind_its_late_rate(tmp_path): + r = _recorder(tmp_path) + _frame(r, 50.0) + r.note_op("patch", 10) + _frame(r, 50.0 + PERIOD) + r.drain() + before = json.loads(json.dumps(r.snapshot())) + + t = 100.0 + _frame(r, t) + for i in range(400): + late = i % 100 == 0 + if i % 4 == 0: + r.note_op("patch", 1000) + t += 2 * PERIOD if late else PERIOD + _frame(r, t) + report = _report(r, before) + row = report["ops"]["patch"] + assert row["frames"] == 100 # the frame before the baseline is not in it + assert row["late"] == 4 + assert row["late_pct"] == 4.0 + assert row["bytes"] == 100_000 + + +def test_the_soak_report_has_no_op_rows_when_nothing_was_tagged(tmp_path, capsys): + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + t = 100.0 + _frame(r, t) + for _ in range(200): + t += PERIOD + _frame(r, t) + report = _report(r, before) + assert report["ops"] == {} + frame_soak.print_report(report, 0.1) + assert "after work" not in capsys.readouterr().out + + +def test_the_soak_report_prints_the_op_table(tmp_path, capsys): + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + t = 100.0 + _frame(r, t) + for i in range(200): + if i == 10: + r.note_op("extend", 3_000_000) + t += PERIOD + _frame(r, t) + frame_soak.print_report(_report(r, before), 0.1) + out = capsys.readouterr().out + assert "after work" in out + assert "extend" in out + + +def test_a_report_from_an_older_recorder_has_an_empty_op_table(): + totals = {"late_frames": 0} + assert frame_soak.op_rows(totals) == {} + + +# -- Vegas tags its own work --------------------------------------------------- + +W, H = 128, 32 + + +class _DM: + width = W + height = H + + def __init__(self, recorder): + self.image = Image.new("RGB", (W, H)) + self.frame_timing = recorder + + def set_scrolling_state(self, *a): + pass + + def update_display(self): + pass + + +class _Stream: + def __init__(self, groups): + self.groups = groups + self.plugin_manager = type("PM", (), {"plugins": {}})() + self.plugin_adapter = None + self._i = 0 + + def get_grouped_content_for_composition(self): + return self.groups[0] + + def get_active_plugin_ids(self): + return [pid for pid, _ in self.groups[0]] + + def take_next_group(self, count=None, offscreen_only=False): + if self._i >= len(self.groups): + return [] + group = self.groups[self._i] + self._i += 1 + return group + + +class _NoteSpy: + def __init__(self): + self.notes = [] + + def note_op(self, kind, nbytes=0): + self.notes.append((kind, nbytes)) + + +def _block(w): + return Image.new("RGB", (w, H), (255, 255, 255)) + + +def test_vegas_tags_a_compose_and_every_extension(): + spy = _NoteSpy() + groups = [[("a", [_block(600)])], [("b", [_block(600)])], [("c", [_block(600)])]] + p = RenderPipeline(VegasModeConfig(lead_in_width=0, continuous_scroll=True), + _DM(spy), _Stream(groups)) + assert p.compose_scroll_content() + assert [kind for kind, _ in spy.notes] == ["compose"] + + p.scroll_helper.scroll_position = 400.0 # far enough to trim on extension + assert p.extend_scroll_content() + kind, moved = spy.notes[-1] + assert kind == "extend" + # The append built the whole strip anew and the trim copied it again. + assert moved > p.scroll_helper.cached_array.nbytes + + +def test_vegas_without_a_recorder_does_not_fail(): + class DM(_DM): + def __init__(self): + super().__init__(None) + + groups = [[("a", [_block(600)])], [("b", [_block(600)])]] + p = RenderPipeline(VegasModeConfig(lead_in_width=0, continuous_scroll=True), + DM(), _Stream(groups)) + assert p.compose_scroll_content() + assert p.extend_scroll_content() + + +# -- the render bench's strip work -------------------------------------------- + + +def _helper(screens=6): + helper = ScrollHelper(W, H) + helper.set_scrolling_image(render_bench.build_strip(W, H, "t", screens=screens)) + return helper + + +def test_the_bench_strip_can_be_made_vegas_wide(): + assert render_bench.build_strip(W, H, "t", screens=30).width >= W * 30 + + +def test_a_visible_patch_writes_its_columns_on_screen_and_nothing_else(): + helper = _helper() + spy = _NoteSpy() + work = render_bench.StripWork(helper, spy, helper.cached_image, + patch_bytes=40 * H * 3, patch_every=1) + helper.scroll_position = 200.0 + before = helper.cached_array.copy() + work.before_frame() + changed = np.flatnonzero((helper.cached_array != before).any(axis=(0, 2))) + assert changed.size + assert changed.min() >= 200 and changed.max() < 200 + W + assert changed.max() - changed.min() < 40 + assert spy.notes == [("patch", 40 * H * 3)] + assert work.patches == 1 + + +def test_an_ahead_patch_lands_past_the_viewport(): + helper = _helper() + work = render_bench.StripWork(helper, _NoteSpy(), helper.cached_image, + patch_bytes=20 * H * 3, patch_every=1, + patch_where="ahead") + helper.scroll_position = 100.0 + before = helper.cached_array.copy() + work.before_frame() + changed = np.flatnonzero((helper.cached_array != before).any(axis=(0, 2))) + assert changed.min() >= 100 + W + + +def test_patches_run_every_k_frames(): + helper = _helper() + spy = _NoteSpy() + work = render_bench.StripWork(helper, spy, helper.cached_image, + patch_bytes=10 * H * 3, patch_every=5) + for _ in range(20): + work.before_frame() + assert work.patches == 4 and len(spy.notes) == 4 + + +def test_extensions_keep_the_strip_bounded_and_the_scroll_going(): + helper = _helper(screens=8) + helper.set_pixels_per_frame(4) + spy = _NoteSpy() + work = render_bench.StripWork(helper, spy, helper.cached_image, + extend_every_screens=2) + widths = [] + for _ in range(3000): + work.before_frame() + helper.update_scroll_position() + assert not helper.is_scroll_complete() + widths.append(helper.cached_array.shape[1]) + assert work.extensions >= 10 + assert {kind for kind, _ in spy.notes} == {"extend"} + # Appends and trims balance: the strip holds its width (within one + # extension of it) instead of growing or running out ahead of the viewport. + assert max(widths) - min(widths) <= 3 * W + assert widths[-1] >= widths[0] - W + assert helper.remaining_unscrolled() > 0