fix(perf): count 1-2s stalls, flag early frames, and keep the refresh estimate honest

Three gaps found by the first hdpi soaks:

- Intervals of 1s or more between two scrolling frames were dropped as
  "gaps between scrolls". But the scrolling state lapses only after 2s, so
  every 1-2s stall inside a scroll vanished from the report. Those are now
  freezes (the gap bound is a 5s sanity limit), with a breakdown by length.
- A frame a whole refresh early means the swap did not wait for the panel.
  Those are counted, and a soak with more than the threshold of them fails
  as NOT LOCKED instead of reporting a flattering late rate.
- The refresh estimate took the lowest window it had seen, so one window of
  non-blocking swaps halved it and made every early frame look on time. A
  window may now lower it by at most 20%.

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

scripts/frame_soak.py

@@ -84,14 +84,15 @@ def diff(before: Dict[str, Any], after: Dict[str, Any]) -> Dict[str, Any]:
     tb, ta = before["totals"], after["totals"]
     totals = {}
     for key, value in ta.items():
-        if key == "late_by":
+        if isinstance(value, dict):
-            totals[key] = {k: v - tb[key].get(k, 0) for k, v in value.items()}
+            totals[key] = {k: v - tb.get(key, {}).get(k, 0)
+                           for k, v in value.items()}
         elif key == "worst_interval_ms":
             # A running maximum can't be differenced; it is reported as the
             # worst since the service started.
             totals[key] = value
         else:
-            totals[key] = value - tb[key]
+            totals[key] = value - tb.get(key, 0)
     histograms = {}
     for name in (after.get("histograms") or {}):
         hb, ha = _histogram(before, name), _histogram(after, name)
@@ -143,6 +144,10 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]:
         "late_pct": round(100.0 * totals["late_frames"] / frames, 3) if frames else None,
         "missed_refreshes": totals["missed_refreshes"],
         "late_by": totals["late_by"],
+        "early_frames": totals.get("early_frames", 0),
+        "early_pct": (round(100.0 * totals.get("early_frames", 0) / frames, 3)
+                      if frames else None),
+        "freeze_by": totals.get("freeze_by", {}),
         "freezes": totals["freezes"],
         "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None,
         "freeze_seconds": round(totals["freeze_seconds"], 2),
@@ -178,9 +183,15 @@ def print_report(report: Dict[str, Any], limit: float) -> None:
               f"  missed refreshes {report['missed_refreshes']}"
               f"  [by 1: {late_by['1']}, 2: {late_by['2']}, "
               f"3-5: {late_by['3-5']}, 6+: {late_by['6+']}]")
+        if report["early_frames"]:
+            print(f"Early frames       {report['early_frames']} "
+                  f"({report['early_pct']}%)  swaps returned a refresh early")
     print(f"Freezes >=250ms    {report['freezes']}"
           f" ({report['freezes_per_hour']}/h, {report['freeze_seconds']}s total)"
           f"  worst gap since start {report['worst_interval_ms'] or '-'} ms")
+    if report["freezes"]:
+        print("                   by length: " + ", ".join(
+            f"{k}: {v}" for k, v in report["freeze_by"].items()))
     print()
     print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}")
     for name in ("blit", "wait", "work", "interval_per_hold"):
@@ -190,12 +201,26 @@ def print_report(report: Dict[str, Any], limit: float) -> None:
     print()
     if report["late_pct"] is None:
         print("RESULT  nothing scrolled - no verdict")
+    elif not locked(report, limit):
+        print(f"RESULT  FAIL  NOT LOCKED: {report['early_pct']}% of frames came a "
+              "refresh early, so the swaps were not waiting for the panel and "
+              "the late count means nothing")
     elif report["late_pct"] <= limit:
         print(f"RESULT  PASS  {report['late_pct']}% late <= {limit}%")
     else:
         print(f"RESULT  FAIL  {report['late_pct']}% late > {limit}%")
 
 
+def locked(report: Dict[str, Any], limit: float) -> bool:
+    """Whether the loop was paced by the panel at all."""
+    return (report.get("early_pct") or 0.0) <= limit
+
+
+def passed(report: Dict[str, Any], limit: float) -> bool:
+    return (report["late_pct"] is not None and locked(report, limit)
+            and report["late_pct"] <= limit)
+
+
 def touch_marker() -> bool:
     try:
         with open(VIEWER_MARKER, "a"):
@@ -302,7 +327,7 @@ def main(argv=None) -> int:
             json.dump(report, handle, indent=2)
     if report["late_pct"] is None:
         return 2
-    return 0 if report["late_pct"] <= args.max_late_pct else 1
+    return 0 if passed(report, args.max_late_pct) else 1
 
 
 if __name__ == "__main__":

src/common/frame_timing.py

@@ -28,14 +28,22 @@ An interval of ``FREEZE_SECONDS`` or more is a **freeze** instead -- a
 recompose, a plugin handover, a blocking call on the render thread. Those are
 counted separately, both because they are a different fault and because
 folding a single 400ms handover into the late count as "40 missed refreshes"
-would drown the jitter the late count exists to measure. Intervals of
+would drown the jitter the late count exists to measure. ``freeze_by`` splits
-``GAP_SECONDS`` or more are not frames at all (one scroll ending, another
+them by length. Intervals of ``GAP_SECONDS`` or more are ignored as not being
-starting later) and are ignored.
+frames of one scroll at all.
+
+A frame that arrives a whole refresh or more *early* means the swap did not
+wait for the panel: the emulator, the fallback display, or a hold that was not
+the one in effect. Those are counted as **early**, and a run with more than a
+trace of them was not locked to the panel, so its late count means nothing.
 
 The refresh period is estimated from the frames themselves: swaps that block
 on vsync can only land on refresh boundaries, so the low end of
 interval / hold is the period. It is the smallest per-window 10th percentile
-seen so far, over windows with enough frames to trust.
+seen so far, over windows with enough frames to trust -- except that a window
+cutting it by more than ``MAX_REFRESH_DROP`` is ignored. A panel's refresh does
+not jump like that; swaps that stopped blocking do, and adopting their period
+would make every early frame look on time.
 """
 
 from __future__ import annotations
@@ -62,7 +70,19 @@ BUCKET_COUNT = 256
 
 #: See the module docstring.
 FREEZE_SECONDS = 0.25
-GAP_SECONDS = 1.0
+
+#: Two frames that are both "scrolling" can be at most DisplayManager's
+#: scroll_inactivity_threshold (2s) apart: after that the second is recorded
+#: as static. This used to be 1s, which silently dropped every 1-2s stall
+#: inside a scroll. It is now only a sanity bound.
+GAP_SECONDS = 5.0
+
+#: Buckets for freeze length, as cumulative counters a soak can difference.
+FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"),
+                  (float("inf"), "2s+"))
+
+#: A window may lower the refresh-period estimate by at most this fraction.
+MAX_REFRESH_DROP = 0.2
 
 #: A window needs this many scrolling frames before its refresh estimate is
 #: trusted -- about a second of scrolling.
@@ -149,8 +169,10 @@ class FrameTimingRecorder:
             "late_frames": 0,
             "missed_refreshes": 0,
             "late_by": {"1": 0, "2": 0, "3-5": 0, "6+": 0},
+            "early_frames": 0,
             "freezes": 0,
             "freeze_seconds": 0.0,
+            "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS},
             "worst_interval_ms": 0.0,
         }
         self.histograms: Dict[str, Dict[int, int]] = {
@@ -217,8 +239,10 @@ class FrameTimingRecorder:
                           if interval < FREEZE_SECONDS)
         if len(per_hold) >= MIN_FRAMES_FOR_REFRESH:
             estimate = per_hold[len(per_hold) // 10]
-            if estimate > 0 and (self.refresh_period is None
+            current = self.refresh_period
-                                 or estimate < self.refresh_period):
+            if estimate > 0 and (
+                    current is None
+                    or current * (1.0 - MAX_REFRESH_DROP) <= estimate < current):
                 self.refresh_period = estimate
         period = self.refresh_period
 
@@ -229,6 +253,9 @@ class FrameTimingRecorder:
             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
                 continue
             totals["scroll_frames"] += 1
             for name, value in (("blit", blit), ("wait", wait),
@@ -245,6 +272,8 @@ class FrameTimingRecorder:
                     key = ("1" if missed == 1 else "2" if missed == 2
                            else "3-5" if missed <= 5 else "6+")
                     totals["late_by"][key] += 1
+                elif missed <= -1:
+                    totals["early_frames"] += 1
 
     def snapshot(self) -> Dict[str, Any]:
         """The JSON document: cumulative since this process started."""

test/test_frame_timing.py

@@ -96,14 +96,42 @@ def test_static_frames_and_the_start_of_a_scroll_are_not_timed(tmp_path):
 def test_freezes_are_separate_from_late_frames_and_gaps_are_ignored(tmp_path):
     r = _recorder(tmp_path)
     intervals = [PERIOD] * 200
-    intervals[80] = 0.400   # a recompose: freeze
+    intervals[80] = 0.400   # a render-thread plugin fetch: freeze
-    intervals[150] = 3.0    # one scroll ended, another began later: ignored
+    intervals[120] = 1.5    # a longer stall, still inside the scroll: freeze
+    intervals[150] = 6.0    # past any scroll's inactivity window: ignored
     _feed(r, intervals)
     totals = _aggregate(r)
-    assert totals["freezes"] == 1
+    assert totals["freezes"] == 2
-    assert abs(totals["freeze_seconds"] - 0.4) < 1e-9
+    assert abs(totals["freeze_seconds"] - 1.9) < 1e-9
+    assert totals["freeze_by"] == {"<0.5s": 1, "0.5-1s": 0, "1-2s": 1, "2s+": 0}
+    assert totals["late_frames"] == 0
+    assert totals["scroll_frames"] == 197
+
+
+def test_a_stall_between_one_and_two_seconds_is_not_lost(tmp_path):
+    # Two "scrolling" frames can be up to DisplayManager's 2s inactivity
+    # threshold apart. The first version ignored everything past 1s, so a
+    # 1.4s render-thread stall vanished from the report.
+    r = _recorder(tmp_path)
+    intervals = [PERIOD] * 100
+    intervals[40] = 1.4
+    _feed(r, intervals)
+    assert _aggregate(r)["freezes"] == 1
+
+
+def test_early_frames_are_counted(tmp_path):
+    # Hold 2 on a 100Hz panel: frames are due every 20ms. A swap that returns
+    # after 10ms did not wait out the hold.
+    r = _recorder(tmp_path)
+    _feed(r, [2 * PERIOD] * 200, hold=2)
+    _aggregate(r)
+    intervals = [2 * PERIOD] * 200
+    for i in range(0, 200, 20):
+        intervals[i] = PERIOD
+    _feed(r, intervals, hold=2, start=1000.0)
+    totals = _aggregate(r)
+    assert totals["early_frames"] == 10
     assert totals["late_frames"] == 0
-    assert totals["scroll_frames"] == 198
 
 
 def test_refresh_estimate_survives_a_window_full_of_misses(tmp_path):
@@ -151,6 +179,21 @@ def test_soak_report_is_the_difference_between_snapshots(tmp_path):
     assert report["timing_ms"]["interval_per_hold"]["max"] == 20.25
 
 
+def test_soak_fails_a_run_that_was_not_locked(tmp_path):
+    r = _recorder(tmp_path)
+    _feed(r, [2 * PERIOD] * 200, hold=2)
+    _aggregate(r)
+    before = json.loads(json.dumps(r.snapshot()))
+    _feed(r, [PERIOD] * 1000, hold=2, start=500.0)   # never waited out the hold
+    _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["late_pct"] == 0.0
+    assert report["early_pct"] == 100.0
+    assert not frame_soak.passed(report, 0.1)
+
+
 def test_soak_percentiles_mark_the_overflow_bucket():
     top = frame_timing.BUCKET_COUNT - 1
     result = frame_soak.percentiles({0: 98, top: 2}, 0.25)