perf(timing): say which render-thread work a late frame followed (#694)

* 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 <noreply@anthropic.com>

* docs(changelog): note the frame-op attribution and bench modes

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

CHANGELOG.md

@@ -334,6 +334,18 @@ read any of them:
 
 ### Tooling
 
+- The frame-timing recorder says which render-thread work a late frame
+  followed. Work done between two frames calls
+  `FrameTimingRecorder.note_op(kind, nbytes)` and the next presented frame
+  carries the tag; the stats gain `op_frames`, `late_op_frames`, `op_freezes`
+  and `op_bytes` per kind (additive; the file's schema version is unchanged).
+  Vegas tags every strip `compose` and `extend`, and `frame_soak.py` prints an
+  "after work" table with each kind's own late rate.
+  `scripts/render_bench.py` can drive the same work on a panel with nothing
+  else running: `--strip-screens` for a Vegas-sized strip, `--patch-bytes /
+  --patch-every / --patch-where` for in-place column writes, and
+  `--extend-every-screens` for appending and trimming on a fixed cadence.
+  See "Soaking a rig" in `docs/SCROLL_PERFORMANCE.md`.
 - `scripts/sports_drift_report.py`: for a ledmatrix-plugins checkout, counts
   how many different bodies each method family has across the nine
   scoreboards' `sports.py`, `manager.py` and `game_renderer.py`, lists the

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

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):

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),
         })

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

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

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