feat(timing): time garbage-collection pauses in the frame stats (#722)

A GcMonitor in src/common/frame_timing.py, installed once per process from gc.callbacks by the display manager (and render_bench), counts collections and seconds per generation, the longest, and those of 20 ms or more. A long one tags the next presented frame 'gc' in record(), so frame_soak shows its late rate under 'after work'; the stats file gains an additive 'gc' block printed as a 'Garbage collection' line; and a Render stall dump says when a long collection ran inside the stall. Diagnostic only: nothing tunes, freezes or disables the collector.

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

CHANGELOG.md

@@ -19,6 +19,20 @@ accepts both, but the store flags the old spelling as deprecated
 
 ## Unreleased
 
+### Garbage-collection pauses in the frame stats
+
+- The display now times every Python garbage collection
+  (`src.common.frame_timing.GcMonitor`, installed once per process from
+  `gc.callbacks`). The collector stops every thread while it runs, and a
+  long one looked like any other render stall. A collection of 20 ms or more
+  tags the next presented frame `gc`, so `scripts/frame_soak.py` shows its
+  late rate under *after work*; the stats file gains an additive `gc` block
+  (collections and seconds per generation, the longest, the long ones),
+  which the soak report prints as a "Garbage collection" line; and a
+  `Render stall` dump says when a long collection ran inside the stall.
+  `scripts/render_bench.py` records the same. Diagnostic only: nothing tunes,
+  freezes or disables the collector.
+
 ### Outlined text: one rasterization
 
 - New `draw_text_outlined(draw, xy, text, font, fill, outline_color=(0, 0,

docs/SCROLL_PERFORMANCE.md

@@ -350,8 +350,9 @@ the same side of it.
 | **blit** | Copying the frame into the matrix canvas (`SetImage`). It grows with width × height × `pwm_bits`: ~5.5 ms at 512×64 with 8 bits on a Pi 4. It is the biggest fixed cost, and it sets the refresh rates a rig can hold one pixel per refresh at. |
 | **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. |
+| **Garbage collection** | Python's cyclic collector stops every thread while it runs. Collections per generation in the run and the time they took, how many took 20 ms or more, and the longest since the service started. A long one tags the next frame `gc` (see *after work*), and a `Render stall` dump says when one ran inside the stall. Diagnostic only: nothing tunes the collector. Missing from stats written by an older service. |
 | **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), `handover` (a new screen's first frame). A kind whose late rate sits well above the overall one is the work making frames late. Shown only when something tagged its work. |
+| **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), `handover` (a new screen's first frame), `gc` (a garbage collection of 20 ms or more ran since the frame before). 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

scripts/frame_soak.py

@@ -167,6 +167,29 @@ def op_rows(totals: Dict[str, Any]) -> Dict[str, Dict[str, Any]]:
     return rows
 
 
+def gc_window(before: Dict[str, Any], after: Dict[str, Any]) -> Optional[Dict[str, Any]]:
+    """Garbage collection over the run, or None from a service without the
+    monitor. The counters are cumulative since the service started, so they
+    are differenced like the totals; the longest is since the start."""
+    ga = after.get("gc")
+    if not ga:
+        return None
+    gb = before.get("gc") or {}
+    def minus(key):
+        return [a - b for a, b in zip(ga.get(key, []),
+                                      gb.get(key) or [0] * len(ga.get(key, [])))]
+    seconds = minus("seconds")
+    return {
+        "collections": minus("collections"),
+        "ms": [round(x * 1000.0, 1) for x in seconds],
+        "long_pauses": ga.get("long_pauses", 0) - gb.get("long_pauses", 0),
+        "long_ms": round((ga.get("long_seconds", 0.0)
+                          - gb.get("long_seconds", 0.0)) * 1000.0, 1),
+        "threshold_ms": ga.get("threshold_ms"),
+        "max_ms_since_start": ga.get("max_ms"),
+    }
+
+
 def build_report(before, after, preview: bool) -> Dict[str, Any]:
     delta = diff(before, after)
     totals = delta["totals"]
@@ -204,6 +227,7 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
         "timing_ms": {name: percentiles(h, bucket_ms)
                       for name, h in delta["histograms"].items()},
         "ops": op_rows(totals),
+        "gc": gc_window(before, after),
     }
     # The rate the panel held while rendering: the typical frame's interval
     # per refresh held. A few percent under the idle rate is normal (the Pi is
@@ -257,6 +281,13 @@ def print_report(report: Dict[str, Any], limit: float) -> None:
     if report.get("handover_freezes") is not None:
         print(f"Handover gaps      {report['handover_freezes']}"
               "  >=250ms before a new screen's first frame; not in the freezes")
+    gc_stats = report.get("gc")
+    if gc_stats:
+        counts, ms = gc_stats["collections"], gc_stats["ms"]
+        print(f"Garbage collection gen0/1/2 {counts[0]}/{counts[1]}/{counts[2]}"
+              f" ({ms[0]}/{ms[1]}/{ms[2]} ms)  >={gc_stats['threshold_ms']:g}ms: "
+              f"{gc_stats['long_pauses']} ({gc_stats['long_ms']} ms)"
+              f"  longest since start {gc_stats['max_ms_since_start']} ms")
     print()
     print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}")
     for name in ("blit", "wait", "work", "interval_per_hold"):

scripts/render_bench.py

@@ -438,6 +438,7 @@ def main(argv=None) -> int:
         flush_interval=float("inf"),
         info=display._frame_timing_info(),  # pylint: disable=protected-access
         refresh_hz=idle_hz,
+        gc_monitor=frame_timing.install_gc_monitor(),
     )
     recorder.scrolling_now = display._scrolling_now  # pylint: disable=protected-access
     display.frame_timing = recorder

src/common/frame_timing.py

@@ -92,6 +92,18 @@ which presents from a thread of its own, and drops the note again with
 :meth:`FrameTimingRecorder.drop_op` once that call returns, so a first
 ``display()`` that drew nothing cannot leave the tag for an unrelated frame.
 
+Garbage collection
+------------------
+
+Python's cyclic collector stops every thread while it runs. :class:`GcMonitor`
+times each collection from ``gc.callbacks``; the display manager installs one
+per process. A collection of ``GC_PAUSE_SECONDS`` or more tags the next
+presented frame ``gc`` (:data:`GC_OP`), so it shows in ``op_frames``,
+``late_op_frames`` and ``op_freezes`` like noted work, and the snapshot carries
+a ``gc`` block of cumulative counters: collections and seconds per generation,
+the longest, and the long ones. A stall dump says when a long collection ran
+inside the stall. Diagnostic only: nothing tunes or freezes the collector.
+
 Stall watchdog
 --------------
 Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the
@@ -110,6 +122,7 @@ three times per threshold, so keep it to diagnostic runs, not soaks.
 from __future__ import annotations
 
 import copy
+import gc
 import json
 import logging
 import os
@@ -153,6 +166,11 @@ FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"),
 #: "What is counted".
 HANDOVER_OP = "handover"
 
+#: The op a garbage collection of ``GC_PAUSE_SECONDS`` or more tags the next
+#: frame with; see "Garbage collection".
+GC_OP = "gc"
+GC_PAUSE_SECONDS = 0.020
+
 #: A window may lower the refresh-period estimate by at most this fraction.
 MAX_REFRESH_DROP = 0.2
 
@@ -184,6 +202,80 @@ def default_stats_path() -> str:
     return os.path.join(base, STATS_FILENAME)
 
 
+class GcMonitor:
+    """Times every garbage collection, from ``gc.callbacks``.
+
+    Python's cyclic collector stops every thread for as long as a collection
+    takes, and a full one over a large heap (a season of game dicts) can take
+    longer than a frame. Nothing measured that, so a stall it caused looked
+    like any other. The callback runs inside the collection, with the GIL
+    held, and collections never overlap, so these plain counters need no
+    lock: the render thread and the stats writer only read them.
+
+    Install it once per process with :func:`install_gc_monitor`.
+    """
+
+    def __init__(self, threshold: float = GC_PAUSE_SECONDS):
+        self.threshold = threshold
+        self._started: Optional[float] = None
+        #: Per generation (0, 1, 2), since the monitor was installed.
+        self.collections = [0, 0, 0]
+        self.seconds = [0.0, 0.0, 0.0]
+        self.max_seconds = 0.0
+        #: Collections of ``threshold`` or more, and their total length. The
+        #: recorder compares ``long_pauses`` with the count it last saw to tag
+        #: the next frame.
+        self.long_pauses = 0
+        self.long_seconds = 0.0
+        #: ``time.perf_counter()`` at the end of the last long collection,
+        #: and its length, for the stall watchdog.
+        self.last_long: Optional[Tuple[float, float]] = None
+
+    def __call__(self, phase: str, info: Dict[str, Any]) -> None:
+        now = time.perf_counter()
+        if phase == "start":
+            self._started = now
+            return
+        started, self._started = self._started, None
+        if started is None:
+            return
+        took = now - started
+        generation = min(max(int(info.get("generation", 0)), 0), 2)
+        self.collections[generation] += 1
+        self.seconds[generation] += took
+        if took > self.max_seconds:
+            self.max_seconds = took
+        if took >= self.threshold:
+            self.long_seconds += took
+            self.last_long = (now, took)
+            self.long_pauses += 1
+
+    def snapshot(self) -> Dict[str, Any]:
+        """Cumulative counters for the stats file (all since installation)."""
+        return {
+            "threshold_ms": round(self.threshold * 1000.0, 3),
+            "collections": list(self.collections),
+            "seconds": [round(x, 6) for x in self.seconds],
+            "max_ms": round(self.max_seconds * 1000.0, 3),
+            "long_pauses": self.long_pauses,
+            "long_seconds": round(self.long_seconds, 6),
+        }
+
+
+_gc_monitor: Optional[GcMonitor] = None
+_gc_monitor_lock = threading.Lock()
+
+
+def install_gc_monitor() -> GcMonitor:
+    """The process's GcMonitor, installed in ``gc.callbacks`` on first call."""
+    global _gc_monitor
+    with _gc_monitor_lock:
+        if _gc_monitor is None:
+            _gc_monitor = GcMonitor()
+            gc.callbacks.append(_gc_monitor)
+        return _gc_monitor
+
+
 #: 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]]]
@@ -279,11 +371,15 @@ class FrameTimingRecorder:
         flush_interval: float = FLUSH_INTERVAL,
         info: Optional[Dict[str, Any]] = None,
         refresh_hz: Optional[float] = None,
+        gc_monitor: Optional[GcMonitor] = None,
     ):
         """
         :param refresh_hz: the panel's rate, measured independently (see the
             module docstring). Omit it to estimate from the frames alone, as
             the display service does.
+        :param gc_monitor: tags frames after a long garbage collection and
+            adds its counters to the stats (see "Garbage collection"). The
+            display manager passes the process's :func:`install_gc_monitor`.
         """
         self.path = path or default_stats_path()
         self.flush_interval = flush_interval
@@ -298,6 +394,8 @@ class FrameTimingRecorder:
         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.gc_monitor = gc_monitor
+        self._gc_seen = gc_monitor.long_pauses if gc_monitor is not None else 0
         self._last_flush: Optional[float] = None
         self._queue: "queue.SimpleQueue" = queue.SimpleQueue()
         self._worker: Optional[threading.Thread] = None
@@ -403,6 +501,15 @@ class FrameTimingRecorder:
         self._previous = (presented_at, scrolling, hold)
         self.last_frame = (presented_at, scrolling, threading.get_ident())
         ops, self._ops = self._ops, None
+        monitor = self.gc_monitor
+        if monitor is not None and monitor.long_pauses != self._gc_seen:
+            # A long collection ran since the last frame: the interval this
+            # frame ends is the one it landed in. Read here rather than
+            # noted, since note_op is the render thread's and a collection
+            # runs on whichever thread triggered it.
+            self._gc_seen = monitor.long_pauses
+            ops = dict(ops) if ops else {}
+            ops[GC_OP] = ops.get(GC_OP, 0)
         if not scrolling:
             self._static_frames += 1
             # The scroll ended, or its state went missing for this frame: the
@@ -565,6 +672,9 @@ class FrameTimingRecorder:
             "binding_releases_gil": self._binding_gil,
             "info": info,
             "totals": copy.deepcopy(self.totals),
+            # Additive: absent from older files and when no monitor is set.
+            **({"gc": self.gc_monitor.snapshot()}
+               if self.gc_monitor is not None else {}),
             # JSON keys are strings; readers convert back.
             "histograms": {name: {str(k): v for k, v in sorted(h.items())}
                            for name, h in self.histograms.items()},
@@ -706,11 +816,17 @@ class StallWatchdog:
         pending = getattr(self.recorder, "_ops", None)
         where = ("in a handover gap" if pending and HANDOVER_OP in pending
                  else "mid-scroll")
+        monitor = getattr(self.recorder, "gc_monitor", None)
+        last_long = getattr(monitor, "last_long", None)
+        gc_note = ""
+        if last_long is not None and time.perf_counter() - last_long[0] <= age:
+            gc_note = (f"; a {last_long[1] * 1000.0:.0f}ms garbage collection "
+                       "ran inside it")
         lines = [
             f"Render stall: no frame for {age * 1000.0:.0f}ms {where} "
             f"(watchdog woke {late * 1000.0:.0f}ms late"
             + ("; the interpreter itself was blocked" if late >= age / 2 else "")
-            + ")",
+            + gc_note + ")",
             f"-- {names.get(ident, ident)} (presents frames):",
         ]
         stalled = frames.get(ident)

src/display_manager.py

@@ -57,7 +57,7 @@ import freetype
 
 from src.common import snapshot_policy
 from src import display_watchdog
-from src.common.frame_timing import FrameTimingRecorder
+from src.common.frame_timing import FrameTimingRecorder, install_gc_monitor
 
 if TYPE_CHECKING:
     from src.common.render_gate import RenderGate
@@ -365,7 +365,8 @@ class DisplayManager:
 
         # Timing of every presented frame, whoever drew it, for
         # scripts/frame_soak.py. See src/common/frame_timing.py.
-        self.frame_timing = FrameTimingRecorder(info=self._frame_timing_info())
+        self.frame_timing = FrameTimingRecorder(
+            info=self._frame_timing_info(), gc_monitor=install_gc_monitor())
         self.frame_timing.scrolling_now = self._scrolling_now
 
         self._scrolling_state = {

test/test_frame_timing.py

@@ -619,3 +619,123 @@ def test_render_bench_strip_lights_a_real_share_of_pixels():
     assert strip.width >= 128 * 4
     lit = sum(1 for px in strip.getdata() if px != (0, 0, 0))
     assert lit / (strip.width * strip.height) > 0.05
+
+
+# -- garbage collection --------------------------------------------------------
+
+def _collection(monitor, monkeypatch, start, took, generation=2):
+    """One collection of ``took`` seconds, as gc.callbacks would report it."""
+    clock = iter([start, start + took])
+    monkeypatch.setattr(frame_timing.time, "perf_counter", lambda: next(clock))
+    monitor("start", {"generation": generation})
+    monitor("stop", {"generation": generation, "collected": 0, "uncollectable": 0})
+    monkeypatch.undo()
+
+
+def test_the_gc_monitor_times_a_real_collection():
+    import gc
+    monitor = frame_timing.GcMonitor(threshold=0.0)
+    gc.callbacks.append(monitor)
+    try:
+        gc.collect()
+    finally:
+        gc.callbacks.remove(monitor)
+    assert monitor.collections[2] >= 1
+    assert monitor.seconds[2] > 0.0
+    assert monitor.long_pauses >= 1
+
+
+def test_only_collections_past_the_threshold_are_long(monkeypatch):
+    monitor = frame_timing.GcMonitor(threshold=0.020)
+    _collection(monitor, monkeypatch, 1.0, 0.005, generation=0)
+    _collection(monitor, monkeypatch, 2.0, 0.030)
+    assert monitor.collections == [1, 0, 1]
+    assert monitor.long_pauses == 1
+    assert monitor.long_seconds == pytest.approx(0.030)
+    assert monitor.max_seconds == pytest.approx(0.030)
+    assert monitor.last_long == (pytest.approx(2.030), pytest.approx(0.030))
+
+
+def test_a_long_collection_tags_the_next_frame_only(tmp_path, monkeypatch):
+    monitor = frame_timing.GcMonitor(threshold=0.020)
+    r = _recorder(tmp_path, gc_monitor=monitor)
+    _settle(r)
+    t = _feed(r, [PERIOD] * 10, start=200.0)
+    _collection(monitor, monkeypatch, 0.0, 0.025)
+    r.record(0.002, 0.004, 1, True, t + 0.04)        # late: the GC was in it
+    _feed(r, [PERIOD] * 10, start=t + 0.04)
+    totals = _aggregate(r)
+    assert totals["op_frames"] == {"gc": 1}
+    assert totals["late_op_frames"] == {"gc": 1}
+
+
+def test_a_long_collection_keeps_other_noted_work(tmp_path, monkeypatch):
+    monitor = frame_timing.GcMonitor(threshold=0.020)
+    r = _recorder(tmp_path, gc_monitor=monitor)
+    _settle(r)
+    t = _feed(r, [PERIOD] * 10, start=200.0)
+    r.note_op("extend", 100)
+    _collection(monitor, monkeypatch, 0.0, 0.025)
+    r.record(0.002, 0.004, 1, True, t + PERIOD)
+    totals = _aggregate(r)
+    assert totals["op_frames"] == {"extend": 1, "gc": 1}
+    assert totals["op_bytes"] == {"extend": 100, "gc": 0}
+
+
+def test_the_snapshot_carries_gc_counters_only_with_a_monitor(tmp_path, monkeypatch):
+    assert "gc" not in _recorder(tmp_path).snapshot()
+    monitor = frame_timing.GcMonitor(threshold=0.020)
+    _collection(monitor, monkeypatch, 0.0, 0.025)
+    snap = _recorder(tmp_path, gc_monitor=monitor).snapshot()
+    assert snap["gc"]["collections"] == [0, 0, 1]
+    assert snap["gc"]["long_pauses"] == 1
+    assert snap["gc"]["max_ms"] == pytest.approx(25.0)
+
+
+def test_soak_reports_the_collections_inside_the_run(tmp_path, monkeypatch, capsys):
+    monitor = frame_timing.GcMonitor(threshold=0.020)
+    r = _recorder(tmp_path, gc_monitor=monitor)
+    _collection(monitor, monkeypatch, 0.0, 0.040)      # before the run
+    _feed(r, [PERIOD] * 200)
+    _aggregate(r)
+    before = json.loads(json.dumps(r.snapshot()))
+    _collection(monitor, monkeypatch, 1.0, 0.003, generation=0)
+    _collection(monitor, monkeypatch, 2.0, 0.025)
+    _feed(r, [PERIOD] * 200, start=500.0)
+    _aggregate(r)
+    after = json.loads(json.dumps(r.snapshot()))
+    after["updated"] = before["updated"] + 10.0
+    report = frame_soak.build_report(before, after, preview=False)
+    assert report["gc"]["collections"] == [1, 0, 1]
+    assert report["gc"]["long_pauses"] == 1
+    assert report["gc"]["long_ms"] == pytest.approx(25.0)
+    assert report["gc"]["max_ms_since_start"] == pytest.approx(40.0)
+    frame_soak.print_report(report, 0.1)
+    assert "Garbage collection gen0/1/2 1/0/1" in capsys.readouterr().out
+
+
+def test_soak_report_from_a_service_without_the_monitor(tmp_path):
+    r = _recorder(tmp_path)
+    _feed(r, [PERIOD] * 200)
+    _aggregate(r)
+    snap = json.loads(json.dumps(r.snapshot()))
+    later = dict(snap, updated=snap["updated"] + 10.0)
+    assert frame_soak.build_report(snap, later, preview=False)["gc"] is None
+
+
+def test_watchdog_says_when_a_long_collection_ran_inside_the_stall(caplog):
+    rec = _FakeRecorder()
+    rec.gc_monitor = frame_timing.GcMonitor()
+    rec.gc_monitor.last_long = (time.perf_counter() - 0.1, 0.35)
+    dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0)
+    rec.last_frame = (10.0, True, 1)
+    with caplog.at_level("WARNING", logger="src.common.frame_timing"):
+        dog.check(10.4, 0.0, None, False)
+    assert "a 350ms garbage collection ran inside it" in caplog.records[0].getMessage()
+
+
+def test_installing_the_gc_monitor_twice_installs_it_once():
+    import gc
+    first = frame_timing.install_gc_monitor()
+    assert frame_timing.install_gc_monitor() is first
+    assert sum(1 for cb in gc.callbacks if cb is first) == 1