fix: droiddeckctl pacing judges cadence per refresh-rate record and always turns timestats off (#894)

* fix: droiddeckctl pacing judges cadence per refresh-rate record and always turns timestats off

Follow-up to the CodeRabbit reviews of #843/#855:
- off-cadence is counted per layer record against that record's own cadence,
  allowing the neighbouring millisecond bucket (16.7 ms lands in 16 or 17);
- refreshRates comes from the chosen layer records only;
- records with no counted frames are skipped, so an empty game layer no longer
  hides the session's SurfaceView, and a capture with no frames exits NO_FRAMES;
- adb failures while enabling or dumping map to PACING_FAILED, and timestats
  is disabled in every case.

* fix: droiddeckctl pacing reports when timestats could not be turned off

tools/droiddeckctl

@@ -300,27 +300,35 @@ def pacing_summary(text: str, package: str = PACKAGE) -> dict:
     frames shown, and 60 handed over can be 48 on screen with one in four held for two refreshes.
     """
     records = {"game": [], "surface": []}
-    for part in re.split(r"^layerName = ", text, flags=re.M)[1:]:
-        name, _, body = part.partition("\n")
+    for part in re.split(r"^displayRefreshRate = ", text, flags=re.M)[1:]:
+        rate = re.match(r"(\d+)", part)
+        layer = re.search(r"^layerName = (.*)$", part, re.M)
+        frames = re.search(r"^totalFrames = (\d+)", part, re.M)
+        hist = re.search(r"^present2present histogram is as below:\n(.*)", part, re.M)
+        if not (rate and layer and frames and hist):
+            continue
+        name = layer.group(1)
         kind = ("game" if "droiddeck_wayland_game" in name
                 else "surface" if f"SurfaceView[{package}/" in name else None)
-        frames = re.search(r"^totalFrames = (\d+)", body, re.M)
-        hist = re.search(r"^present2present histogram is as below:\n(.*)", body, re.M)
-        if kind and frames and hist:
-            records[kind].append((re.sub(r"#\d+$", "", name.strip()), int(frames.group(1)), hist.group(1)))
+        if kind and int(frames.group(1)):
+            bins = {int(ms): int(n) for ms, n in re.findall(r"(\d+)ms=(\d+)", hist.group(1)) if int(n)}
+            records[kind].append((re.sub(r"#\d+$", "", name.strip()), int(frames.group(1)), bins, int(rate.group(1))))
     chosen = records["game"] or records["surface"]
     histogram: dict[int, int] = {}
-    for _, _, hist in chosen:
-        for ms, count in re.findall(r"(\d+)ms=(\d+)", hist):
-            if int(count):
-                histogram[int(ms)] = histogram.get(int(ms), 0) + int(count)
+    off = 0
+    for _, _, bins, _ in chosen:
+        for ms, count in bins.items():
+            histogram[ms] = histogram.get(ms, 0) + count
+        if bins:
+            # SurfaceFlinger bins by whole milliseconds, so one cadence spans two buckets (16.7 ms: 16 and 17).
+            mode = max(bins, key=bins.get)
+            off += sum(count for ms, count in bins.items() if abs(ms - mode) > 1)
     intervals = sum(histogram.values())
     cadence = max(histogram, key=histogram.get) if histogram else None
-    off = intervals - histogram.get(cadence, 0) if histogram else 0
     return {
-        "layers": sorted({name for name, _, _ in chosen}),
-        "frames": sum(frames for _, frames, _ in chosen),
-        "refreshRates": sorted({int(r) for r in re.findall(r"^displayRefreshRate = (\d+)", text, re.M)}),
+        "layers": sorted({name for name, _, _, _ in chosen}),
+        "frames": sum(frames for _, frames, _, _ in chosen),
+        "refreshRates": sorted({rate for _, _, _, rate in chosen}),
         "presentToPresentMs": {str(ms): histogram[ms] for ms in sorted(histogram)},
         "cadenceMs": cadence,
         "offCadence": off,
@@ -332,17 +340,30 @@ def pacing(adb: str, serial: str, seconds: float) -> dict:
     """Frames on screen and their intervals over `seconds`, from SurfaceFlinger's timestats."""
     seconds = max(1.0, min(600.0, seconds))
     timestats = ("shell", "dumpsys", "SurfaceFlinger", "--timestats")
-    if run_adb(adb, serial, *timestats, "-clear", "-enable").returncode != 0:
+    try:
+        enabled = run_adb(adb, serial, *timestats, "-clear", "-enable")
+    except ControlError as exc:
+        raise ControlError(str(exc), "PACING_FAILED") from exc
+    if enabled.returncode != 0:
         raise ControlError("could not enable SurfaceFlinger timestats", "PACING_FAILED")
     started = time.monotonic()
-    time.sleep(seconds)
-    dump = run_adb(adb, serial, *timestats, "-dump", timeout=60)
-    elapsed = time.monotonic() - started
-    run_adb(adb, serial, *timestats, "-disable")
+    try:
+        time.sleep(seconds)
+        dump = run_adb(adb, serial, *timestats, "-dump", timeout=60)
+    except ControlError as exc:
+        raise ControlError(str(exc), "PACING_FAILED") from exc
+    finally:
+        elapsed = time.monotonic() - started
+        try:
+            disabled = run_adb(adb, serial, *timestats, "-disable").returncode == 0
+        except ControlError:
+            disabled = False
     if dump.returncode != 0:
         raise ControlError(dump.stderr.decode(errors="replace").strip() or "timestats dump failed", "PACING_FAILED")
+    if not disabled:
+        raise ControlError("could not turn SurfaceFlinger timestats off", "PACING_FAILED")
     summary = pacing_summary(dump.stdout.decode(errors="replace"))
-    if not summary["layers"]:
+    if not summary["layers"] or not summary["frames"]:
         raise ControlError("No DroidDeck layer drew during the capture: is a session on screen?", "NO_FRAMES")
     summary["fpsOnScreen"] = round(summary["frames"] / elapsed, 1)
     return {"ok": True, "command": "pacing", "seconds": round(elapsed, 1), **summary}

tools/tests/test_droiddeckctl.py

@@ -305,6 +305,65 @@ class DroiddeckctlTest(FakeAdbTest):
         self.assertEqual(4, code)
         self.assertEqual("NO_FRAMES", out["error"]["code"])
 
+    def test_pacing_counts_both_buckets_of_one_cadence_and_only_the_chosen_layers_rates(self):
+        text = "SurfaceFlinger TimeStats:\n" + "".join([
+            timestats_record("droiddeck_wayland_game#7", 910, {16: 450, 17: 450, 33: 10}, 60),
+            timestats_record("StatusBar#106", 4, {8: 3}, 90),
+        ])
+        summary = ctl.pacing_summary(text, "com.droiddeck.launcher")
+        self.assertEqual(10, summary["offCadence"])
+        self.assertEqual([60], summary["refreshRates"])
+
+    def test_pacing_skips_a_game_layer_with_no_frames_for_the_surfaceview(self):
+        text = "SurfaceFlinger TimeStats:\n" + "".join([
+            timestats_record("droiddeck_wayland_game#7", 0, {}, 120),
+            timestats_record("a1 SurfaceView[com.droiddeck.launcher/com.droiddeck.launcher.SessionActivity]#8", 600, {16: 598, 33: 1}, 120),
+        ])
+        summary = ctl.pacing_summary(text, "com.droiddeck.launcher")
+        self.assertEqual(600, summary["frames"])
+        self.assertIn("SurfaceView[com.droiddeck.launcher/", summary["layers"][0])
+
+    def test_pacing_with_a_layer_that_drew_no_frames_exits_4(self):
+        self.configure({}, timestats="SurfaceFlinger TimeStats:\n" + timestats_record("droiddeck_wayland_game#7", 0, {}, 120))
+        with unittest.mock.patch.object(ctl.time, "sleep"):
+            code, out = self.run_ctl("pacing", "--seconds", "1")
+        self.assertEqual(4, code)
+        self.assertEqual("NO_FRAMES", out["error"]["code"])
+
+    def test_pacing_turns_timestats_off_when_the_dump_fails(self):
+        calls = []
+
+        def adb(_adb, _serial, *args, timeout=30):
+            calls.append(args[3:])
+            if "-dump" in args:
+                raise ctl.ControlError("timed out", "ADB_FAILED")
+            return ctl.subprocess.CompletedProcess(args, 0, b"", b"")
+
+        with unittest.mock.patch.object(ctl, "run_adb", adb), unittest.mock.patch.object(ctl.time, "sleep"):
+            with self.assertRaises(ctl.ControlError) as caught:
+                ctl.pacing("adb", "fake-1", 1)
+        self.assertEqual("PACING_FAILED", caught.exception.code)
+        self.assertEqual(("--timestats", "-disable"), calls[-1])
+
+    def test_pacing_fails_when_timestats_cannot_be_turned_off(self):
+        def adb(_adb, _serial, *args, timeout=30):
+            return ctl.subprocess.CompletedProcess(args, 1 if "-disable" in args else 0, b"", b"")
+
+        with unittest.mock.patch.object(ctl, "run_adb", adb), unittest.mock.patch.object(ctl.time, "sleep"):
+            with self.assertRaises(ctl.ControlError) as caught:
+                ctl.pacing("adb", "fake-1", 1)
+        self.assertEqual("PACING_FAILED", caught.exception.code)
+        self.assertIn("timestats off", str(caught.exception))
+
+    def test_pacing_maps_an_adb_failure_while_enabling_to_pacing_failed(self):
+        def adb(*_args, **_kwargs):
+            raise ctl.ControlError("adb vanished", "ADB_FAILED")
+
+        with unittest.mock.patch.object(ctl, "run_adb", adb):
+            with self.assertRaises(ctl.ControlError) as caught:
+                ctl.pacing("adb", "fake-1", 1)
+        self.assertEqual("PACING_FAILED", caught.exception.code)
+
     def test_input_requests(self):
         self.configure({"input": {"ok": True, "command": "input"}})
         self.run_ctl("input", "tap", "0.5", "0.25", "--space", "fraction")