From 003581f2fd21896c6273bed248e90b5e0971bdc5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Thu, 11 Jun 2026 08:55:22 +0200 Subject: [PATCH] perf(ios): anchor recording gesture clock from runner response stamps Every ok runner response now carries a transport-stamped currentUptimeMs captured just before the HTTP write. Simulator recording start anchors gesture overlay timing from the warm snapshot response it already makes, skipping the standalone uptime request. The standalone uptime path stays as fallback for older runner builds, and journal-stored responses remain unstamped so recovered results never pair a stale uptime with a late receipt time. Closes #670 --- .../RunnerTests+CommandExecution.swift | 2 + .../RunnerTests+CommandJournal.swift | 40 ++++ .../RunnerTests+Models.swift | 14 +- .../RunnerTests+Transport.swift | 11 +- .../handlers/__tests__/record-trace.test.ts | 184 +++++++++++++++++- src/daemon/handlers/record-trace-ios.ts | 33 +++- src/daemon/handlers/record-trace-recording.ts | 23 ++- 7 files changed, 290 insertions(+), 17 deletions(-) diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandExecution.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandExecution.swift index ebe461aee..29b926a34 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandExecution.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandExecution.swift @@ -244,6 +244,8 @@ extension RunnerTests { } func executeUptime() -> Response { + // Placeholder value: the transport layer (jsonResponse) overwrites currentUptimeMs with a + // fresher send-time stamp on every ok response; kept so direct callers still get a value. Response( ok: true, data: DataPayload(currentUptimeMs: currentUptimeMs()) diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandJournal.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandJournal.swift index dee4606fd..0eb2bf4c4 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandJournal.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+CommandJournal.swift @@ -165,6 +165,46 @@ extension RunnerTests { XCTAssertEqual(status.lifecycleState, RunnerCommandLifecycleState.notAccepted.rawValue) } + func testStampingCurrentUptimePreservesPayload() { + let stamped = Response(ok: true, data: DataPayload(message: "recording started")) + .stampingCurrentUptimeMs(123.5) + + XCTAssertEqual(stamped.ok, true) + XCTAssertEqual(stamped.data?.message, "recording started") + XCTAssertEqual(stamped.data?.currentUptimeMs, 123.5) + } + + func testStampingCurrentUptimeCreatesPayloadWhenNil() { + let stamped = Response(ok: true).stampingCurrentUptimeMs(456.0) + + XCTAssertEqual(stamped.ok, true) + XCTAssertEqual(stamped.data?.currentUptimeMs, 456.0) + } + + func testStampingCurrentUptimeSkipsErrorResponses() { + let response = Response(ok: false, error: ErrorPayload(message: "boom")) + let stamped = response.stampingCurrentUptimeMs(789.0) + + XCTAssertEqual(stamped.ok, false) + XCTAssertNil(stamped.data) + XCTAssertEqual(stamped.error?.message, "boom") + } + + func testJournalStoredResponseStaysUnstamped() throws { + let journal = RunnerCommandJournal() + let recordStart = runnerJournalCommand("recordStart", id: "record-start-anchor") + + journal.accept(command: recordStart) + journal.finish( + command: recordStart, + response: Response(ok: true, data: DataPayload(message: "recording started")) + ) + + let status = journal.status(commandId: "record-start-anchor") + let responseJson = try XCTUnwrap(status.lifecycleResponseJson) + XCTAssertFalse(responseJson.contains("currentUptimeMs")) + } + func testCommandJournalRetentionPolicy() throws { let journal = RunnerCommandJournal() diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift index e1ecdcf9b..06ef2b480 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift @@ -162,6 +162,18 @@ struct Response: Codable { } } +extension Response { + // The daemon pairs this gesture-clock anchor with its own receipt time to map + // gesture uptimes onto wall-clock for the recording touch overlay. Error responses + // carry no anchor so the daemon falls back instead of pairing a stale value. + func stampingCurrentUptimeMs(_ value: Double) -> Response { + guard ok else { return self } + var payload = data ?? DataPayload() + payload.currentUptimeMs = value + return Response(ok: ok, data: payload, error: error) + } +} + struct DataPayload: Codable { let message: String? let text: String? @@ -177,7 +189,7 @@ struct DataPayload: Codable { let y2: Double? let referenceWidth: Double? let referenceHeight: Double? - let currentUptimeMs: Double? + var currentUptimeMs: Double? let commandId: String? let lifecycleState: String? let lifecycleCommand: String? diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Transport.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Transport.swift index 99e54ec98..c7d74684a 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Transport.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Transport.swift @@ -170,8 +170,17 @@ extension RunnerTests { // MARK: - Response Encoding private func jsonResponse(status: Int, response: Response) -> Data { + // Stamp the gesture-clock uptime at the END of command handling, just before the HTTP + // write, so the warm snapshot and recordStart responses carry the anchor for free. This + // runs AFTER commandJournal.finish, so journal-stored lifecycleResponseJson stays + // unstamped — recovered/status-replayed results carry no anchor and the daemon falls back + // rather than pairing a stale uptime with a much-later receipt time. + let stamped = + response.ok + ? response.stampingCurrentUptimeMs(ProcessInfo.processInfo.systemUptime * 1000) + : response let encoder = JSONEncoder() - let body = (try? encoder.encode(response)).flatMap { String(data: $0, encoding: .utf8) } ?? "{}" + let body = (try? encoder.encode(stamped)).flatMap { String(data: $0, encoding: .utf8) } ?? "{}" return httpResponse(status: status, body: body) } diff --git a/src/daemon/handlers/__tests__/record-trace.test.ts b/src/daemon/handlers/__tests__/record-trace.test.ts index 267e0302e..98ab5e877 100644 --- a/src/daemon/handlers/__tests__/record-trace.test.ts +++ b/src/daemon/handlers/__tests__/record-trace.test.ts @@ -1144,8 +1144,13 @@ test('record start does not fail when iOS simulator runner warm-up fails', async wait: Promise.resolve({ stdout: '', stderr: '', exitCode: 0 }), }; }); - mockRunIosRunnerCommand.mockImplementation(async () => { - throw new Error('runner warm-up unavailable'); + const runnerCalls: RunnerCall[] = []; + mockRunIosRunnerCommand.mockImplementation(async (_device, command) => { + runnerCalls.push({ command: command.command }); + if (command.command === 'snapshot') { + throw new Error('runner warm-up unavailable'); + } + return { currentUptimeMs: 30_000 }; }); const response = await runRecordCommand({ @@ -1156,6 +1161,181 @@ test('record start does not fail when iOS simulator runner warm-up fails', async expect(response?.ok).toBe(true); expect(started).toBe(true); + // Warm-up failure falls back to the standalone uptime command for the anchor. + expect(runnerCalls.map((call) => call.command)).toEqual(['snapshot', 'uptime']); + const recording = sessionStore.get(sessionName)?.recording; + expect(recording?.platform).toBe('ios'); + if (recording?.platform === 'ios') { + expect(recording.gestureClockOriginUptimeMs).toBe(30_000); + } +}); + +test('record start anchors gesture clock from simulator warm-up and skips standalone uptime', async () => { + const sessionStore = makeSessionStore(); + const sessionName = 'ios-sim-warm-anchor'; + const session = makeSession(sessionName, { + platform: 'ios', + id: 'sim-1', + name: 'Simulator', + kind: 'simulator', + booted: true, + }); + session.appBundleId = 'com.apple.Preferences'; + sessionStore.set(sessionName, session); + + mockRunCmdBackground.mockImplementation(() => ({ + child: { kill: () => {} } as any, + wait: Promise.resolve({ stdout: '', stderr: '', exitCode: 0 }), + })); + const runnerCalls: RunnerCall[] = []; + mockRunIosRunnerCommand.mockImplementation(async (_device, command) => { + runnerCalls.push({ command: command.command }); + if (command.command === 'snapshot') { + return { currentUptimeMs: 20_000 }; + } + return {}; + }); + + const beforeMs = Date.now(); + const response = await runRecordCommand({ + sessionStore, + sessionName, + positionals: ['start', './sim-warm-anchor.mp4'], + }); + const afterMs = Date.now(); + + expect(response?.ok).toBe(true); + expect(runnerCalls.map((call) => call.command)).toEqual(['snapshot']); + const recording = sessionStore.get(sessionName)?.recording; + expect(recording?.platform).toBe('ios'); + if (recording?.platform === 'ios') { + expect(recording.gestureClockOriginUptimeMs).toBe(20_000); + expect(recording.gestureClockOriginAtMs).toBeGreaterThanOrEqual(beforeMs); + expect(recording.gestureClockOriginAtMs).toBeLessThanOrEqual(afterMs); + } +}); + +test('record start falls back to standalone uptime when warm response lacks currentUptimeMs', async () => { + const sessionStore = makeSessionStore(); + const sessionName = 'ios-sim-warm-missing'; + const session = makeSession(sessionName, { + platform: 'ios', + id: 'sim-1', + name: 'Simulator', + kind: 'simulator', + booted: true, + }); + session.appBundleId = 'com.apple.Preferences'; + sessionStore.set(sessionName, session); + + mockRunCmdBackground.mockImplementation(() => ({ + child: { kill: () => {} } as any, + wait: Promise.resolve({ stdout: '', stderr: '', exitCode: 0 }), + })); + const runnerCalls: RunnerCall[] = []; + mockRunIosRunnerCommand.mockImplementation(async (_device, command) => { + runnerCalls.push({ command: command.command }); + if (command.command === 'uptime') { + return { currentUptimeMs: 30_000 }; + } + return {}; + }); + + const response = await runRecordCommand({ + sessionStore, + sessionName, + positionals: ['start', './sim-warm-missing.mp4'], + }); + + expect(response?.ok).toBe(true); + expect(runnerCalls.map((call) => call.command)).toEqual(['snapshot', 'uptime']); + const recording = sessionStore.get(sessionName)?.recording; + expect(recording?.platform).toBe('ios'); + if (recording?.platform === 'ios') { + expect(recording.gestureClockOriginUptimeMs).toBe(30_000); + } +}); + +test('record start rejects non-finite or non-positive warm anchors', async () => { + for (const badValue of [Number.NaN, -1]) { + const sessionStore = makeSessionStore(); + const sessionName = `ios-sim-warm-bad-${badValue}`; + const session = makeSession(sessionName, { + platform: 'ios', + id: 'sim-1', + name: 'Simulator', + kind: 'simulator', + booted: true, + }); + session.appBundleId = 'com.apple.Preferences'; + sessionStore.set(sessionName, session); + + mockRunCmdBackground.mockImplementation(() => ({ + child: { kill: () => {} } as any, + wait: Promise.resolve({ stdout: '', stderr: '', exitCode: 0 }), + })); + const runnerCalls: RunnerCall[] = []; + mockRunIosRunnerCommand.mockImplementation(async (_device, command) => { + runnerCalls.push({ command: command.command }); + if (command.command === 'snapshot') { + return { currentUptimeMs: badValue }; + } + return { currentUptimeMs: 30_000 }; + }); + + const response = await runRecordCommand({ + sessionStore, + sessionName, + positionals: ['start', `./sim-warm-bad-${badValue}.mp4`], + }); + + expect(response?.ok).toBe(true); + expect(runnerCalls.map((call) => call.command)).toEqual(['snapshot', 'uptime']); + const recording = sessionStore.get(sessionName)?.recording; + expect(recording?.platform).toBe('ios'); + if (recording?.platform === 'ios') { + expect(recording.gestureClockOriginUptimeMs).toBe(30_000); + } + } +}); + +test('record start degrades to wall-clock when warm anchor missing and uptime fails', async () => { + const sessionStore = makeSessionStore(); + const sessionName = 'ios-sim-anchor-degraded'; + const session = makeSession(sessionName, { + platform: 'ios', + id: 'sim-1', + name: 'Simulator', + kind: 'simulator', + booted: true, + }); + session.appBundleId = 'com.apple.Preferences'; + sessionStore.set(sessionName, session); + + mockRunCmdBackground.mockImplementation(() => ({ + child: { kill: () => {} } as any, + wait: Promise.resolve({ stdout: '', stderr: '', exitCode: 0 }), + })); + mockRunIosRunnerCommand.mockImplementation(async (_device, command) => { + if (command.command === 'uptime') { + throw new Error('uptime unavailable'); + } + return {}; + }); + + const response = await runRecordCommand({ + sessionStore, + sessionName, + positionals: ['start', './sim-anchor-degraded.mp4'], + }); + + expect(response?.ok).toBe(true); + const recording = sessionStore.get(sessionName)?.recording; + expect(recording?.platform).toBe('ios'); + if (recording?.platform === 'ios') { + expect(recording.gestureClockOriginAtMs).toBeUndefined(); + expect(recording.gestureClockOriginUptimeMs).toBeUndefined(); + } }); test('record start skips iOS simulator runner warm-up when touch overlays are hidden', async () => { diff --git a/src/daemon/handlers/record-trace-ios.ts b/src/daemon/handlers/record-trace-ios.ts index cfb76da6f..b75c14944 100644 --- a/src/daemon/handlers/record-trace-ios.ts +++ b/src/daemon/handlers/record-trace-ios.ts @@ -89,19 +89,24 @@ async function stopRunnerRecordingBestEffort(params: { } } +type RunnerGestureClockAnchor = { + gestureClockOriginAtMs: number; + gestureClockOriginUptimeMs: number; +}; + export async function warmIosSimulatorRunner(params: { req: DaemonRequest; activeSession: SessionState; device: SessionState['device']; logPath?: string; deps: RecordTraceDeps; -}): Promise { +}): Promise { const { req, activeSession, device, logPath, deps } = params; const appBundleId = normalizeAppBundleId(activeSession); - if (!appBundleId) return; + if (!appBundleId) return undefined; try { - await deps.runIosRunnerCommand( + const result = await deps.runIosRunnerCommand( device, { command: 'snapshot', @@ -112,6 +117,27 @@ export async function warmIosSimulatorRunner(params: { }, getIosRunnerOptions(req, logPath, activeSession), ); + // Pair the runner-stamped uptime with daemon receipt time. The runner stamps + // currentUptimeMs just before sending the response, so receive time is the closest + // wall-clock pair; the request midpoint would be wrong because this warm request can + // include cold runner build/launch (10s+). + const receivedAtMs = Date.now(); + if ( + typeof result.currentUptimeMs === 'number' && + Number.isFinite(result.currentUptimeMs) && + result.currentUptimeMs > 0 + ) { + emitDiagnostic({ + level: 'debug', + phase: 'record_start_gesture_clock_anchor', + data: { source: 'warm_snapshot' }, + }); + return { + gestureClockOriginAtMs: receivedAtMs, + gestureClockOriginUptimeMs: result.currentUptimeMs, + }; + } + return undefined; } catch (error) { emitDiagnostic({ level: 'warn', @@ -123,6 +149,7 @@ export async function warmIosSimulatorRunner(params: { error: formatRecordTraceError(error), }, }); + return undefined; } } diff --git a/src/daemon/handlers/record-trace-recording.ts b/src/daemon/handlers/record-trace-recording.ts index 846659b17..52aec14f4 100644 --- a/src/daemon/handlers/record-trace-recording.ts +++ b/src/daemon/handlers/record-trace-recording.ts @@ -128,20 +128,23 @@ async function startIosSimulatorRecording(params: { }): Promise> { const { req, activeSession, device, logPath, deps, recordingBase, resolvedOut } = params; - if (recordingBase.showTouches) { - await warmIosSimulatorRunner({ - req, - activeSession, - device, - logPath, - deps, - }); - } + // The warm-up carries the gesture-clock anchor on its snapshot response when the runner + // stamps it, letting us skip a standalone uptime command. The anchor is a pure clock pair + // (origin uptime + daemon receipt time), so capturing it before the recorder spawn/settle + // window is equivalent to capturing it after: recordingStartedAt stays readyAt below. + const warmAnchor = recordingBase.showTouches + ? await warmIosSimulatorRunner({ req, activeSession, device, logPath, deps }) + : undefined; const { child, wait } = deps.startIosSimulatorRecording({ device, outPath: resolvedOut }); const readyAt = await waitForLocalRecordingSettleWindow(resolvedOut); let gestureClockOriginAtMs: number | undefined; let gestureClockOriginUptimeMs: number | undefined; - if (recordingBase.showTouches) { + if (warmAnchor) { + gestureClockOriginAtMs = warmAnchor.gestureClockOriginAtMs; + gestureClockOriginUptimeMs = warmAnchor.gestureClockOriginUptimeMs; + } else if (recordingBase.showTouches) { + // Fallback for older runner builds (or a failed/unavailable warm anchor): issue a + // standalone uptime command and pair it at the request midpoint. try { const uptimeRequestStartedAtMs = Date.now(); const uptimeResult = await deps.runIosRunnerCommand(