From b667abbbcaa690803b384b4f20d1e4b2a4e6922c Mon Sep 17 00:00:00 2001 From: pjay Date: Wed, 22 Apr 2026 17:43:27 +0700 Subject: [PATCH] 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 | 1 + go.sum | 2 + internal/runner/runner.go | 58 +++++++--- internal/runner/runner_test.go | 102 ++++++++++++++++++ .../dev/sanderling/sidecar/DriverBackend.kt | 28 ++++- .../sanderling/sidecar/IdleDetectionTest.kt | 31 ++++++ 6 files changed, 205 insertions(+), 17 deletions(-) create mode 100644 sidecar/src/test/kotlin/dev/sanderling/sidecar/IdleDetectionTest.kt diff --git a/go.mod b/go.mod index b424e5c..35b65c3 100644 --- a/go.mod +++ b/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 ) diff --git a/go.sum b/go.sum index 4aa4194..ded4666 100644 --- a/go.sum +++ b/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= diff --git a/internal/runner/runner.go b/internal/runner/runner.go index 57903a3..d40e4b0 100644 --- a/internal/runner/runner.go +++ b/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 - // waitForIdle internally, and the SDK's Choreographer-held pause - // stalls the main thread, so dumping during the pause yields the - // pre-pause (stale) tree. Doing this first also means the spec sees - // a hierarchy that matches the snapshots captured a moment later. - tree, hierarchyErr := fetchHierarchy(ctx, options.Driver) + // Hierarchy, metrics, and logs are independent device reads. Run + // them concurrently so metrics+logs hide behind the hierarchy + // fetch (~2s). All three must finish before snapshotStep pauses + // the SDK. + var tree *hierarchy.Tree + 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 } diff --git a/internal/runner/runner_test.go b/internal/runner/runner_test.go index fb892da..c5dbc22 100644 --- a/internal/runner/runner_test.go +++ b/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() diff --git a/sidecar/src/main/kotlin/dev/sanderling/sidecar/DriverBackend.kt b/sidecar/src/main/kotlin/dev/sanderling/sidecar/DriverBackend.kt index 9a36a0e..6479729 100644 --- a/sidecar/src/main/kotlin/dev/sanderling/sidecar/DriverBackend.kt +++ b/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 `/`. @@ -316,8 +321,8 @@ class StubDriverBackend(private val platform: String) : DriverBackend { return try { val process = ProcessBuilder( listOf( - "adb", "shell", - "uiautomator dump /sdcard/window_dump.xml >/dev/null 2>&1 && cat /sdcard/window_dump.xml", + "adb", "exec-out", + "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,9 +335,26 @@ 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 // Stateful CPU delta tracker. Reading /proc//stat gives cumulative diff --git a/sidecar/src/test/kotlin/dev/sanderling/sidecar/IdleDetectionTest.kt b/sidecar/src/test/kotlin/dev/sanderling/sidecar/IdleDetectionTest.kt new file mode 100644 index 0000000..82d48bd --- /dev/null +++ b/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")) + } +}