perf: reduce per-step iteration time (~3.9s to ~2.3s) (#29)

* perf(sidecar): use exec-out + tmpfs for hierarchy dump

Avoids FUSE overhead on /sdcard and shell startup cost by using
exec-out with /data/local/tmp. Saves ~100ms per hierarchy fetch.

* perf(sidecar): replace Thread.sleep waitForIdle with real idle detection

Poll `dumpsys window -a` for mAnimating=true every 50ms instead of
blindly sleeping. Breaks early when device is idle, saving 500-800ms
per step since most settle in <200ms after an action.

* test(sidecar): add idle detection parsing tests

* perf(runner): parallelize hierarchy, metrics, and logs fetch

Run fetchHierarchy, captureMetrics, and collectLogs concurrently via
errgroup so metrics+logs (~150ms) hide behind the hierarchy fetch
(~2s) instead of running serially.

* perf(runner): pipeline post-action screenshot with next step

Defer the post-action screenshot from step N and run it concurrently
with step N+1's hierarchy/metrics/logs fetch. Saves ~335ms per step
by hiding screenshot latency behind the hierarchy fetch.

* test(runner): add tests for parallel fetch and pipelined screenshots

Verify that hierarchy, metrics, and logs are all called per step.
Verify post-action screenshots are written with correct step indices
when pipelined, including the final flush after the loop.

* perf(sidecar): grep mAnimating on-device instead of pulling full dump

The full `dumpsys window -a` output is ~88KB per poll. Running
grep on-device transfers only a count byte, cutting per-poll
overhead from ~63ms to ~56ms and eliminating 88KB of ADB transfer.

go.mod

@@ -6,6 +6,7 @@ require (
 	github.com/dop251/goja v0.0.0-20260311135729-065cd970411c
 	github.com/evanw/esbuild v0.28.0
 	github.com/fsnotify/fsnotify v1.9.0
+	golang.org/x/sync v0.20.0
 	google.golang.org/grpc v1.80.0
 	google.golang.org/protobuf v1.36.11
 )

go.sum

@@ -38,6 +38,8 @@ go.opentelemetry.io/otel/trace v1.39.0 h1:2d2vfpEDmCJ5zVYz7ijaJdOF59xLomrvj7bjt6
 go.opentelemetry.io/otel/trace v1.39.0/go.mod h1:88w4/PnZSazkGzz/w84VHpQafiU4EtqqlVdxWy+rNOA=
 golang.org/x/net v0.49.0 h1:eeHFmOGUTtaaPSGNmjBKpbng9MulQsJURQUAfUwY++o=
 golang.org/x/net v0.49.0/go.mod h1:/ysNB2EvaqvesRkuLAyjI1ycPZlQHM3q01F02UY/MV8=
+golang.org/x/sync v0.20.0 h1:e0PTpb7pjO8GAtTs2dQ6jYa5BWYlMuX047Dco/pItO4=
+golang.org/x/sync v0.20.0/go.mod h1:9xrNwdLfx4jkKbNva9FpL6vEN7evnE43NNNJQ2LF3+0=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.40.0 h1:DBZZqJ2Rkml6QMQsZywtnjnnGvHza6BTfYFWY9kjEWQ=
 golang.org/x/sys v0.40.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks=

internal/runner/runner.go

@@ -8,6 +8,8 @@ import (
 	"log/slog"
 	"time"
 
+	"golang.org/x/sync/errgroup"
+
 	"github.com/priyanshujain/sanderling/internal/agent"
 	"github.com/priyanshujain/sanderling/internal/driver"
 	"github.com/priyanshujain/sanderling/internal/hierarchy"
@@ -59,6 +61,8 @@ func Run(ctx context.Context, options Options) (Summary, error) {
 	stepIndex := 0
 	var lastAction *verifier.Action
 	var lastLogTime time.Time
+	var pendingPostScreenshotStep int
+	pendingPostScreenshot := false
 	for time.Now().Before(deadline) {
 		if err := ctx.Err(); err != nil {
 			break
@@ -66,12 +70,40 @@ func Run(ctx context.Context, options Options) (Summary, error) {
 		stepIndex++
 		stepStart := time.Now()
 
-		// Fetch hierarchy BEFORE pausing the SDK: uiautomator dump calls
+		// Hierarchy, metrics, and logs are independent device reads. Run
-		// waitForIdle internally, and the SDK's Choreographer-held pause
+		// them concurrently so metrics+logs hide behind the hierarchy
-		// stalls the main thread, so dumping during the pause yields the
+		// fetch (~2s). All three must finish before snapshotStep pauses
-		// pre-pause (stale) tree. Doing this first also means the spec sees
+		// the SDK.
-		// a hierarchy that matches the snapshots captured a moment later.
+		var tree *hierarchy.Tree
-		tree, hierarchyErr := fetchHierarchy(ctx, options.Driver)
+		var hierarchyErr error
+		var metrics *trace.Metrics
+		var logs []verifier.LogEntry
+
+		g, _ := errgroup.WithContext(ctx)
+		g.Go(func() error {
+			tree, hierarchyErr = fetchHierarchy(ctx, options.Driver)
+			return nil
+		})
+		si := stepIndex
+		g.Go(func() error {
+			metrics = captureMetrics(ctx, options, logger, si)
+			return nil
+		})
+		logSince := lastLogTime
+		g.Go(func() error {
+			logs = collectLogs(ctx, options.Driver, logSince)
+			return nil
+		})
+		if pendingPostScreenshot {
+			postStep := pendingPostScreenshotStep
+			g.Go(func() error {
+				captureScreenshot(ctx, options, logger, postStep, true)
+				return nil
+			})
+			pendingPostScreenshot = false
+		}
+		g.Wait()
+
 		if hierarchyErr != nil {
 			logger.Warn("hierarchy fetch failed", "step", stepIndex, "err", hierarchyErr)
 		}
@@ -80,17 +112,10 @@ func Run(ctx context.Context, options Options) (Summary, error) {
 			treeSize = len(tree.Elements)
 		}
 
-		// Sample metrics now, while the app is still running freely.
-		// Measuring after snapshotStep would see the SDK-paused app and
-		// report CPU=0 for every step.
-		metrics := captureMetrics(ctx, options, logger, stepIndex)
-
 		snapshot, err := snapshotStep(ctx, options)
 		if err != nil {
 			return summary, fmt.Errorf("step %d snapshot: %w", stepIndex, err)
 		}
-
-		logs := collectLogs(ctx, options.Driver, lastLogTime)
 		lastLogTime = stepStart
 
 		exceptions := decodeExceptions(snapshot)
@@ -173,7 +198,8 @@ func Run(ctx context.Context, options Options) (Summary, error) {
 		idleCtx, idleCancel := context.WithTimeout(ctx, options.IdleTimeout)
 		idleErr := options.Driver.WaitForIdle(idleCtx, options.IdleTimeout)
 		if nextErr == nil {
-			captureScreenshot(ctx, options, logger, stepIndex, true)
+			pendingPostScreenshot = true
+			pendingPostScreenshotStep = stepIndex
 		}
 		if idleErr != nil && idleCtx.Err() == nil {
 			logger.Warn("wait_for_idle failed", "step", stepIndex, "err", idleErr)
@@ -181,6 +207,10 @@ func Run(ctx context.Context, options Options) (Summary, error) {
 		idleCancel()
 	}
 
+	if pendingPostScreenshot {
+		captureScreenshot(ctx, options, logger, pendingPostScreenshotStep, true)
+	}
+
 	summary.EndTime = time.Now()
 	return summary, nil
 }

internal/runner/runner_test.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"fmt"
 	"log/slog"
 	"net"
 	"os"
@@ -16,6 +17,7 @@ import (
 	"time"
 
 	"github.com/priyanshujain/sanderling/internal/agent"
+	"github.com/priyanshujain/sanderling/internal/driver"
 	mockdriver "github.com/priyanshujain/sanderling/internal/driver/mock"
 	"github.com/priyanshujain/sanderling/internal/trace"
 	"github.com/priyanshujain/sanderling/internal/verifier"
@@ -423,6 +425,106 @@ func TestApplyAction_InputTextSurfacesFocusTapError(t *testing.T) {
 	})
 }
 
+func TestRunner_ParallelFetchCallsAllDriverMethods(t *testing.T) {
+	snapshots := []map[string]json.RawMessage{
+		{"screen": json.RawMessage(`"home"`), "balance": json.RawMessage(`100`)},
+	}
+	state := newHarness(t, snapshots)
+	state.mock.MetricsData = driver.Metrics{CPUPercent: 5.0, HeapBytes: 1024, TotalMemoryBytes: 4096}
+	state.mock.LogEntries = []driver.LogEntry{
+		{UnixMillis: 1000, Level: "E", Tag: "test", Message: "boom"},
+	}
+	state.startSDK(t)
+	state.acceptConnection(t)
+
+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+	defer cancel()
+	_, err := Run(ctx, Options{
+		Duration:        100 * time.Millisecond,
+		SnapshotTimeout: 2 * time.Second,
+		IdleTimeout:     50 * time.Millisecond,
+		BundleID:        "com.fixture",
+		Connection:      state.conn,
+		Driver:          state.mock,
+		Verifier:        state.verifier,
+		TraceWriter:     state.writer,
+	})
+	if err != nil {
+		t.Fatalf("Run: %v", err)
+	}
+
+	actions := state.mock.Actions()
+	var hasHierarchy, hasMetrics, hasLogs bool
+	for _, a := range actions {
+		switch a.Kind {
+		case mockdriver.ActionHierarchy:
+			hasHierarchy = true
+		case mockdriver.ActionMetrics:
+			hasMetrics = true
+		case mockdriver.ActionRecentLogs:
+			hasLogs = true
+		}
+	}
+	if !hasHierarchy {
+		t.Error("expected Hierarchy call in mock actions")
+	}
+	if !hasMetrics {
+		t.Error("expected Metrics call in mock actions")
+	}
+	if !hasLogs {
+		t.Error("expected RecentLogs call in mock actions")
+	}
+}
+
+func TestRunner_PipelinedPostScreenshotWritten(t *testing.T) {
+	snapshots := []map[string]json.RawMessage{
+		{"screen": json.RawMessage(`"home"`), "balance": json.RawMessage(`100`)},
+		{"screen": json.RawMessage(`"home"`), "balance": json.RawMessage(`200`)},
+		{"screen": json.RawMessage(`"home"`), "balance": json.RawMessage(`300`)},
+	}
+	state := newHarness(t, snapshots)
+	state.mock.ImageData = driver.Image{PNG: []byte("fakepng"), Width: 100, Height: 200}
+	state.startSDK(t)
+	state.acceptConnection(t)
+
+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+	defer cancel()
+	summary, err := Run(ctx, Options{
+		Duration:        200 * time.Millisecond,
+		SnapshotTimeout: 2 * time.Second,
+		IdleTimeout:     50 * time.Millisecond,
+		Connection:      state.conn,
+		Driver:          state.mock,
+		Verifier:        state.verifier,
+		TraceWriter:     state.writer,
+	})
+	if err != nil {
+		t.Fatalf("Run: %v", err)
+	}
+	if summary.Steps < 2 {
+		t.Fatalf("need at least 2 steps for pipelining test, got %d", summary.Steps)
+	}
+
+	screenshotDir := filepath.Join(state.writer.Directory(), "screenshots")
+
+	preFile := filepath.Join(screenshotDir, "step-00001.png")
+	if _, err := os.Stat(preFile); os.IsNotExist(err) {
+		t.Errorf("expected pre-screenshot for step 1: %s", preFile)
+	}
+
+	// Step 1's post-screenshot is pipelined into step 2's errgroup
+	postFile := filepath.Join(screenshotDir, "step-00001-after.png")
+	if _, err := os.Stat(postFile); os.IsNotExist(err) {
+		t.Errorf("expected pipelined post-screenshot for step 1: %s", postFile)
+	}
+
+	// Last step's post-screenshot is flushed after the loop
+	lastAfter := filepath.Join(screenshotDir, fmt.Sprintf("step-%05d-after.png", summary.Steps))
+	if _, err := os.Stat(lastAfter); os.IsNotExist(err) {
+		t.Errorf("expected flushed post-screenshot for last step %d: %s", summary.Steps, lastAfter)
+	}
+}
+
 func mustNewVerifier(t *testing.T) *verifier.Verifier {
 	t.Helper()
 	verifierInstance, err := verifier.New()

sidecar/src/main/kotlin/dev/sanderling/sidecar/DriverBackend.kt

@@ -82,6 +82,11 @@ class StubDriverBackend(private val platform: String) : DriverBackend {
     }
 
     companion object {
+        private const val IDLE_POLL_INTERVAL_MILLIS = 50L
+
+        internal fun isAnimationCountIdle(grepOutput: String): Boolean =
+            (grepOutput.trim().toIntOrNull() ?: 0) == 0
+
         // parseResolvedActivity extracts the activity name from the output of
         // `cmd package resolve-activity --brief`. The brief output is two
         // lines: metadata, then `<pkg>/<activity>`.
@@ -316,8 +321,8 @@ class StubDriverBackend(private val platform: String) : DriverBackend {
         return try {
             val process = ProcessBuilder(
                 listOf(
-                    "adb", "shell",
+                    "adb", "exec-out",
-                    "uiautomator dump /sdcard/window_dump.xml >/dev/null 2>&1 && cat /sdcard/window_dump.xml",
+                    "uiautomator dump /data/local/tmp/window_dump.xml >/dev/null 2>&1 && cat /data/local/tmp/window_dump.xml",
                 ),
             ).redirectErrorStream(false).start()
             val output = process.inputStream.bufferedReader().readText()
@@ -330,8 +335,25 @@ class StubDriverBackend(private val platform: String) : DriverBackend {
     }
 
     override fun waitForIdle(durationMillis: Long) {
-        if (durationMillis > 0) Thread.sleep(durationMillis)
+        if (durationMillis <= 0) return
+        val deadline = System.currentTimeMillis() + durationMillis
+        while (System.currentTimeMillis() < deadline) {
+            if (isDeviceIdle()) return
+            Thread.sleep(IDLE_POLL_INTERVAL_MILLIS)
         }
+    }
+
+    private fun isDeviceIdle(): Boolean {
+        return try {
+            val output = captureAdb(
+                listOf("shell", "dumpsys window -a | grep -c mAnimating=true"),
+            )
+            isAnimationCountIdle(output)
+        } catch (cause: Exception) {
+            false
+        }
+    }
+
 
     override fun healthy(): Boolean = true
 

sidecar/src/test/kotlin/dev/sanderling/sidecar/IdleDetectionTest.kt

@@ -0,0 +1,31 @@
+package dev.sanderling.sidecar
+
+import org.junit.Test
+import kotlin.test.assertFalse
+import kotlin.test.assertTrue
+
+class IdleDetectionTest {
+    @Test fun idleWhenCountIsZero() {
+        assertTrue(StubDriverBackend.isAnimationCountIdle("0\n"))
+    }
+
+    @Test fun idleWhenCountIsZeroNoNewline() {
+        assertTrue(StubDriverBackend.isAnimationCountIdle("0"))
+    }
+
+    @Test fun busyWhenCountIsOne() {
+        assertFalse(StubDriverBackend.isAnimationCountIdle("1\n"))
+    }
+
+    @Test fun busyWhenCountIsMultiple() {
+        assertFalse(StubDriverBackend.isAnimationCountIdle("3\n"))
+    }
+
+    @Test fun idleWhenOutputEmpty() {
+        assertTrue(StubDriverBackend.isAnimationCountIdle(""))
+    }
+
+    @Test fun idleWhenOutputIsNotANumber() {
+        assertTrue(StubDriverBackend.isAnimationCountIdle("error: no service"))
+    }
+}