rick/LEDMatrix
1
0
Fork 0
mirror of https://github.com/ChuckBuilds/LEDMatrix.git synced 2026-10-04 14:25:08 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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>
This commit is contained in:
Chuck
2026-09-30 18:36:38 -04:00
co-authored by Claude Opus 5.5
parent 7804ea8f69
commit 1252df9bad
6 changed files with 695 additions and 19 deletions
Download Patch File Download Diff File Expand all files Collapse all files
docs/SCROLL_PERFORMANCE.md
+7
View File
@@ -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
+42
View File
@@ -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
+192 -7
View File
@@ -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
+69 -12
View File
@@ -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
+22
View File
@@ -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
+363
View File
@@ -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