diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index a53b2ce5..24a8857e 100644 --- a/scripts/frame_soak.py +++ b/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": - totals[key] = {k: v - tb[key].get(k, 0) for k, v in value.items()} + if isinstance(value, dict): + 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__": diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 3743569b..c6d69689 100644 --- a/src/common/frame_timing.py +++ b/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 -``GAP_SECONDS`` or more are not frames at all (one scroll ending, another -starting later) and are ignored. +would drown the jitter the late count exists to measure. ``freeze_by`` splits +them by length. Intervals of ``GAP_SECONDS`` or more are ignored as not being +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 - or estimate < self.refresh_period): + current = 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.""" diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index 67703af1..700e2c5d 100644 --- a/test/test_frame_timing.py +++ b/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[150] = 3.0 # one scroll ended, another began later: ignored + intervals[80] = 0.400 # a render-thread plugin fetch: freeze + 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 abs(totals["freeze_seconds"] - 0.4) < 1e-9 + assert totals["freezes"] == 2 + 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)