From 32a697a01dac66d0ab28f9409f726c04111f1448 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Sun, 28 Jun 2026 19:50:06 +0200 Subject: [PATCH] perf: add iOS snapshot timing diagnostics --- .../RunnerTests+Models.swift | 10 ++ .../RunnerTests+Snapshot.swift | 112 +++++++----- .../RunnerTests+SnapshotCapturePlan.swift | 113 ++++++++++-- src/__tests__/snapshot-diagnostics.test.ts | 163 ++++++++++++++++-- src/core/interactors/apple.ts | 3 + src/daemon/handlers/snapshot-capture.ts | 20 ++- src/snapshot-diagnostics.ts | 138 ++++++++++++++- 7 files changed, 481 insertions(+), 78 deletions(-) diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift index ac8a8919d..76450a984 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Models.swift @@ -207,6 +207,7 @@ struct DataPayload: Codable { let nodes: [SnapshotNode]? let truncated: Bool? let snapshotQuality: SnapshotQuality? + var snapshotTiming: SnapshotTiming? let gestureStartUptimeMs: Double? let gestureEndUptimeMs: Double? let x: Double? @@ -245,6 +246,7 @@ struct DataPayload: Codable { nodes: [SnapshotNode]? = nil, truncated: Bool? = nil, snapshotQuality: SnapshotQuality? = nil, + snapshotTiming: SnapshotTiming? = nil, gestureStartUptimeMs: Double? = nil, gestureEndUptimeMs: Double? = nil, x: Double? = nil, @@ -282,6 +284,7 @@ struct DataPayload: Codable { self.nodes = nodes self.truncated = truncated self.snapshotQuality = snapshotQuality + self.snapshotTiming = snapshotTiming self.gestureStartUptimeMs = gestureStartUptimeMs self.gestureEndUptimeMs = gestureEndUptimeMs self.x = x @@ -314,6 +317,13 @@ struct DataPayload: Codable { } } +struct SnapshotTiming: Codable { + let totalMs: Double + let phases: [String: Double]? + let backends: [String: Double]? + let selectedBackend: String? +} + struct ErrorPayload: Codable { let code: String? let message: String diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Snapshot.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Snapshot.swift index 13e305ea9..e1bfbbbc5 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Snapshot.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+Snapshot.swift @@ -102,15 +102,21 @@ extension RunnerTests { private static let flatInteractiveFallbackBudget: TimeInterval = 1.0 func snapshotFast(app: XCUIApplication, options: SnapshotOptions) throws -> DataPayload { + let timing = SnapshotTimingRecorder() if let blocking = blockingSystemAlertSnapshot() { - return blocking + var payload = blocking + payload.snapshotTiming = timing.payload() + return payload } - return try runSnapshotCapturePlan( + var payload = try runSnapshotCapturePlan( Self.regularVisiblePlan, app: app, options: options, - terminal: .sparseWithFatalOnAXFailure + terminal: .sparseWithFatalOnAXFailure, + timing: timing ) + payload.snapshotTiming = timing.payload() + return payload } func recursiveTreeSnapshotPayload( @@ -246,15 +252,21 @@ extension RunnerTests { } func snapshotRaw(app: XCUIApplication, options: SnapshotOptions) throws -> DataPayload { + let timing = SnapshotTimingRecorder() if let blocking = blockingSystemAlertSnapshot() { - return blocking + var payload = blocking + payload.snapshotTiming = timing.payload() + return payload } - return try runSnapshotCapturePlan( + var payload = try runSnapshotCapturePlan( Self.rawDiagnosticPlan, app: app, options: options, - terminal: .throwOnAXFailure + terminal: .throwOnAXFailure, + timing: timing ) + payload.snapshotTiming = timing.payload() + return payload } func rawTreeSnapshotPayload( @@ -302,7 +314,11 @@ extension RunnerTests { return DataPayload(nodes: nodes, truncated: false) } - func snapshotFlatInteractive(app: XCUIApplication, options: SnapshotOptions) -> DataPayload { + func snapshotFlatInteractive( + app: XCUIApplication, + options: SnapshotOptions, + timing: SnapshotTimingRecorder? = nil + ) -> DataPayload { var nodes: [SnapshotNode] = [ interactiveRootNode(rect: .zero) ] @@ -313,39 +329,45 @@ extension RunnerTests { let deadline = options.interactiveOnly ? Date().addingTimeInterval(Self.flatInteractiveFallbackBudget) : Date.distantFuture - let viewport = safeSnapshotViewport(app: app) + let viewport = measureSnapshotPhase(timing, "query_sweep_viewport") { + safeSnapshotViewport(app: app) + } var seen = Set() var candidates: [SnapshotNode] = [] - let flatElements = flatInteractiveElements(app: app, deadline: deadline) - var truncated = flatElements.truncated - for element in flatElements.elements { - if Date() >= deadline { - NSLog("AGENT_DEVICE_RUNNER_SNAPSHOT_FLAT_FALLBACK_DEADLINE") - truncated = true - break - } - guard let node = flatSnapshotNode( - element: element, - index: 0, - parentIndex: 0, - viewport: viewport, - options: options - ) else { - continue - } - let key = "\(node.type)-\(node.label ?? "")-\(node.identifier ?? "")-\(node.value ?? "")-\(node.rect.x)-\(node.rect.y)-\(node.rect.width)-\(node.rect.height)" - if seen.contains(key) { continue } - seen.insert(key) - candidates.append(node) + let flatElements = measureSnapshotPhase(timing, "query_sweep_elements") { + flatInteractiveElements(app: app, deadline: deadline) } - candidates.sort { left, right in - if left.rect.y != right.rect.y { - return left.rect.y < right.rect.y + var truncated = flatElements.truncated + measureSnapshotPhase(timing, "query_sweep_shape") { + for element in flatElements.elements { + if Date() >= deadline { + NSLog("AGENT_DEVICE_RUNNER_SNAPSHOT_FLAT_FALLBACK_DEADLINE") + truncated = true + break + } + guard let node = flatSnapshotNode( + element: element, + index: 0, + parentIndex: 0, + viewport: viewport, + options: options + ) else { + continue + } + let key = "\(node.type)-\(node.label ?? "")-\(node.identifier ?? "")-\(node.value ?? "")-\(node.rect.x)-\(node.rect.y)-\(node.rect.width)-\(node.rect.height)" + if seen.contains(key) { continue } + seen.insert(key) + candidates.append(node) } - if left.rect.x != right.rect.x { - return left.rect.x < right.rect.x + candidates.sort { left, right in + if left.rect.y != right.rect.y { + return left.rect.y < right.rect.y + } + if left.rect.x != right.rect.x { + return left.rect.x < right.rect.x + } + return left.type < right.type } - return left.type < right.type } // The synthetic root doubles as the daemon's viewport (find.ts prefers on-screen matches @@ -560,16 +582,26 @@ extension RunnerTests { func makeSnapshotTraversalContext( app: XCUIApplication, - options: SnapshotOptions + options: SnapshotOptions, + timing: SnapshotTimingRecorder? = nil ) throws -> SnapshotTraversalContext? { - let viewport = safeSnapshotViewport(app: app) - let queryRoot = options.scope.flatMap { findScopeElement(app: app, scope: $0) } ?? app + let viewport = measureSnapshotPhase(timing, "viewport") { + safeSnapshotViewport(app: app) + } + let queryRoot = measureSnapshotPhase(timing, "scope_resolve") { + options.scope.flatMap { findScopeElement(app: app, scope: $0) } ?? app + } - guard let rootSnapshot = try captureSnapshotRoot(queryRoot) else { + let maybeRootSnapshot = try measureSnapshotPhase(timing, "xctest_root_snapshot") { + try captureSnapshotRoot(queryRoot) + } + guard let rootSnapshot = maybeRootSnapshot else { return nil } - let (flatSnapshots, snapshotRanges) = flattenedSnapshots(rootSnapshot) + let (flatSnapshots, snapshotRanges) = measureSnapshotPhase(timing, "flatten_tree") { + flattenedSnapshots(rootSnapshot) + } return SnapshotTraversalContext( queryRoot: queryRoot, rootSnapshot: rootSnapshot, diff --git a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SnapshotCapturePlan.swift b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SnapshotCapturePlan.swift index 8d9f4f0b7..8f7c61dd0 100644 --- a/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SnapshotCapturePlan.swift +++ b/ios-runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SnapshotCapturePlan.swift @@ -46,6 +46,69 @@ struct SnapshotBackendCapture { let effectiveDepth: Int? } +final class SnapshotTimingRecorder { + private let startedAt = Date() + private(set) var phases: [String: Double] = [:] + private(set) var backends: [String: Double] = [:] + private var selectedBackend: SnapshotBackendKind? + + @discardableResult + func measure(_ phase: String, _ work: () throws -> T) rethrows -> T { + let started = Date() + defer { phases[phase] = roundedElapsedMs(since: started) } + return try work() + } + + @discardableResult + func measureBackend(_ backend: SnapshotBackendKind, _ work: () throws -> T) rethrows -> T { + let started = Date() + defer { backends[backend.rawValue] = roundedElapsedMs(since: started) } + return try work() + } + + func selectBackend(_ backend: SnapshotBackendKind) { + selectedBackend = backend + } + + func payload() -> SnapshotTiming { + SnapshotTiming( + totalMs: roundedElapsedMs(since: startedAt), + phases: phases.isEmpty ? nil : phases, + backends: backends.isEmpty ? nil : backends, + selectedBackend: selectedBackend?.rawValue + ) + } + + private func roundedElapsedMs(since started: Date) -> Double { + let elapsed = Date().timeIntervalSince(started) * 1000 + return (elapsed * 10).rounded() / 10 + } +} + +@discardableResult +func measureSnapshotPhase( + _ timing: SnapshotTimingRecorder?, + _ phase: String, + _ work: () throws -> T +) rethrows -> T { + if let timing { + return try timing.measure(phase, work) + } + return try work() +} + +@discardableResult +func measureSnapshotBackend( + _ timing: SnapshotTimingRecorder?, + _ backend: SnapshotBackendKind, + _ work: () throws -> T +) rethrows -> T { + if let timing { + return try timing.measureBackend(backend, work) + } + return try work() +} + extension RunnerTests { static let sparseRecoveryTruncatedNodeThreshold = 8 /// Umbrella wall-clock budget for one capture plan. Individual backends bound themselves, @@ -69,7 +132,8 @@ extension RunnerTests { _ plan: [SnapshotBackendKind], app: XCUIApplication, options: SnapshotOptions, - terminal: SnapshotCaptureTerminalPolicy + terminal: SnapshotCaptureTerminalPolicy, + timing: SnapshotTimingRecorder? = nil ) throws -> DataPayload { var best: (kind: SnapshotBackendKind, capture: SnapshotBackendCapture)? var firstFailure: (reason: String, code: String)? @@ -86,7 +150,7 @@ extension RunnerTests { } let capture: SnapshotBackendCapture do { - guard let result = try captureWithBackend(kind, app: app, options: options) else { + guard let result = try captureWithBackend(kind, app: app, options: options, timing: timing) else { continue } capture = result @@ -119,6 +183,7 @@ extension RunnerTests { firstFailure?.reason ?? "sparse tree" ) } + timing?.selectBackend(kind) return stampedSnapshotPayload( capture, backend: kind, @@ -147,7 +212,10 @@ extension RunnerTests { } let fallbackPayload = - best.map { stampedSnapshotPayload($0.capture, backend: $0.kind, state: "sparse", reason: firstFailure) } + best.map { + timing?.selectBackend($0.kind) + return stampedSnapshotPayload($0.capture, backend: $0.kind, state: "sparse", reason: firstFailure) + } ?? stampedSnapshotPayload( SnapshotBackendCapture(payload: sparseTruncatedSnapshotPayload(), effectiveDepth: nil), backend: plan.last ?? .recursiveTree, @@ -160,24 +228,31 @@ extension RunnerTests { private func captureWithBackend( _ kind: SnapshotBackendKind, app: XCUIApplication, - options: SnapshotOptions + options: SnapshotOptions, + timing: SnapshotTimingRecorder? ) throws -> SnapshotBackendCapture? { - switch kind { - case .recursiveTree: - guard let context = try makeSnapshotTraversalContext(app: app, options: options) else { - return nil + try measureSnapshotBackend(timing, kind) { + switch kind { + case .recursiveTree: + guard let context = try makeSnapshotTraversalContext(app: app, options: options, timing: timing) else { + return nil + } + let payload = options.raw + ? try measureSnapshotPhase(timing, "raw_tree_shape") { + try rawTreeSnapshotPayload(context: context, options: options) + } + : measureSnapshotPhase(timing, "visible_tree_shape") { + recursiveTreeSnapshotPayload(context: context, options: options) + } + return SnapshotBackendCapture(payload: payload, effectiveDepth: nil) + case .querySweep: + return SnapshotBackendCapture( + payload: snapshotFlatInteractive(app: app, options: options, timing: timing), + effectiveDepth: nil + ) + case .privateAX: + return privateAXSnapshotCapture(app: app, options: options) } - let payload = options.raw - ? try rawTreeSnapshotPayload(context: context, options: options) - : recursiveTreeSnapshotPayload(context: context, options: options) - return SnapshotBackendCapture(payload: payload, effectiveDepth: nil) - case .querySweep: - return SnapshotBackendCapture( - payload: snapshotFlatInteractive(app: app, options: options), - effectiveDepth: nil - ) - case .privateAX: - return privateAXSnapshotCapture(app: app, options: options) } } diff --git a/src/__tests__/snapshot-diagnostics.test.ts b/src/__tests__/snapshot-diagnostics.test.ts index 568c2bcdd..b0dd638e3 100644 --- a/src/__tests__/snapshot-diagnostics.test.ts +++ b/src/__tests__/snapshot-diagnostics.test.ts @@ -1,8 +1,12 @@ -import { expect, test } from 'vitest'; +import assert from 'node:assert/strict'; +import { test } from 'vitest'; import { mergeSnapshotDiagnostics, + readSnapshotDiagnosticsSummary, + readSnapshotRunnerTiming, recordSnapshotTiming, summarizeSnapshotDiagnostics, + summarizeSnapshotTimingSamples, } from '../snapshot-diagnostics.ts'; test('records session snapshot timing stats', () => { @@ -11,18 +15,79 @@ test('records session snapshot timing stats', () => { recordSnapshotTiming(session, { durationMs: 400, backend: 'android', platform: 'android' }); recordSnapshotTiming(session, { durationMs: 2_100, backend: 'android', platform: 'android' }); - expect(summarizeSnapshotDiagnostics(session)).toEqual({ + const summary = summarizeSnapshotDiagnostics(session); + assert.deepEqual(summary?.stats, { + count: 2, + p50Ms: 400, + p95Ms: 2_100, + maxMs: 2_100, + slowThresholdMs: 1_500, + platform: 'android', + backends: { android: 2 }, + }); + assert.match(summary?.warning ?? '', /p95 2100ms over 2 captures/); +}); + +test('snapshot diagnostics summarizes bounded phase timing stats', () => { + const summary = summarizeSnapshotTimingSamples([ + { + durationMs: 1_000, + platform: 'ios', + backend: 'xctest', + phases: { + runner_total: 800, + xctest_root_snapshot: 650, + }, + }, + { + durationMs: 2_000, + platform: 'ios', + backend: 'xctest', + phases: { + runner_total: 1_700, + xctest_root_snapshot: 1_500, + }, + }, + ]); + + assert.equal(summary?.stats.p95Ms, 2_000); + assert.equal(summary?.phases?.runner_total?.p95Ms, 1_700); + assert.equal(summary?.phases?.xctest_root_snapshot?.p50Ms, 650); + assert.equal(summary?.phases?.runner_total?.platform, 'ios'); + assert.deepEqual(summary?.phases?.runner_total?.backends, { xctest: 2 }); +}); + +test('snapshot diagnostics reads serialized phase stats', () => { + const summary = readSnapshotDiagnosticsSummary({ stats: { - count: 2, - p50Ms: 400, - p95Ms: 2_100, - maxMs: 2_100, + count: 1, + p50Ms: 100, + p95Ms: 100, + maxMs: 100, slowThresholdMs: 1_500, - platform: 'android', - backends: { android: 2 }, + platform: 'ios', + }, + phases: { + runner_total: { + count: 1, + p50Ms: 80, + p95Ms: 80, + maxMs: 80, + slowThresholdMs: 1_500, + platform: 'ios', + }, + 'bad phase': { + count: 1, + p50Ms: 1, + p95Ms: 1, + maxMs: 1, + slowThresholdMs: 1_500, + }, }, - warning: expect.stringContaining('p95 2100ms over 2 captures'), }); + + assert.equal(summary?.phases?.runner_total?.p95Ms, 80); + assert.equal(summary?.phases?.['bad phase'], undefined); }); test('merges snapshot diagnostics without inflating capture count', () => { @@ -36,6 +101,16 @@ test('merges snapshot diagnostics without inflating capture count', () => { slowThresholdMs: 1_500, platform: 'android', }, + phases: { + runner_total: { + count: 1, + p50Ms: 200, + p95Ms: 200, + maxMs: 200, + slowThresholdMs: 1_500, + platform: 'android', + }, + }, }, { stats: { @@ -46,15 +121,71 @@ test('merges snapshot diagnostics without inflating capture count', () => { slowThresholdMs: 1_500, platform: 'android', }, + phases: { + runner_total: { + count: 2, + p50Ms: 300, + p95Ms: 1_700, + maxMs: 1_700, + slowThresholdMs: 1_500, + platform: 'android', + }, + }, }, ]); - expect(merged?.stats).toMatchObject({ - count: 3, - p50Ms: 500, - p95Ms: 1_900, - maxMs: 1_900, - platform: 'android', + assert.equal(merged?.stats.count, 3); + assert.equal(merged?.stats.p50Ms, 500); + assert.equal(merged?.stats.p95Ms, 1_900); + assert.equal(merged?.stats.maxMs, 1_900); + assert.equal(merged?.stats.platform, 'android'); + const runnerTotal = merged?.phases?.runner_total; + assert.ok(runnerTotal); + assert.equal(runnerTotal.count, 3); + assert.equal(runnerTotal.p50Ms, 300); + assert.equal(runnerTotal.p95Ms, 1_700); + assert.match(merged?.warning ?? '', /p95 1900ms over 3 captures/); +}); + +test('snapshot diagnostics parses runner timing into bounded phase names', () => { + const timing = readSnapshotRunnerTiming({ + totalMs: 120.4, + selectedBackend: 'tree', + phases: { + xctest_root_snapshot: 95.8, + 'bad phase': 100, + bad_value: 'slow', + }, + backends: { + tree: 110.2, + queries: 0, + }, + }); + + assert.deepEqual(timing, { + totalMs: 120.4, + selectedBackend: 'tree', + phases: { + xctest_root_snapshot: 96, + runner_total: 120, + 'backend.tree': 110, + 'backend.queries': 0, + }, }); - expect(merged?.warning).toContain('p95 1900ms over 3 captures'); +}); + +test('snapshot diagnostics keeps only recent timing samples', () => { + const session: { + snapshotDiagnostics?: { samples: Array<{ durationMs: number }> }; + } = {}; + + for (let index = 0; index < 55; index += 1) { + recordSnapshotTiming(session, { durationMs: index, platform: 'ios' }); + } + + assert.equal(session.snapshotDiagnostics?.samples.length, 50); + assert.equal(session.snapshotDiagnostics?.samples[0]?.durationMs, 5); + const summary = summarizeSnapshotDiagnostics(session); + assert.equal(summary?.stats.count, 50); + assert.equal(summary?.stats.maxMs, 54); }); diff --git a/src/core/interactors/apple.ts b/src/core/interactors/apple.ts index 18bfe4e5b..594c30afb 100644 --- a/src/core/interactors/apple.ts +++ b/src/core/interactors/apple.ts @@ -78,6 +78,7 @@ export function createAppleInteractor( truncated: result.truncated ?? false, backend: 'xctest', ...(result.quality ? { quality: result.quality } : {}), + ...(result.snapshotTiming ? { snapshotTiming: result.snapshotTiming } : {}), // Legacy runners without a quality verdict still surface their message text. ...(!result.quality && result.message ? { warnings: [result.message] } : {}), }; @@ -142,11 +143,13 @@ function readAppleSnapshotResult(result: Record): { truncated?: boolean; message?: string; quality?: SnapshotQualityVerdict; + snapshotTiming?: unknown; } { return { nodes: Array.isArray(result.nodes) ? (result.nodes as RawSnapshotNode[]) : undefined, truncated: typeof result.truncated === 'boolean' ? result.truncated : undefined, quality: readSnapshotQualityVerdict(result.snapshotQuality), + snapshotTiming: result.snapshotTiming, // Legacy runner context for builds that predate the structured verdict. message: typeof result.message === 'string' && result.message.trim().length > 0 diff --git a/src/daemon/handlers/snapshot-capture.ts b/src/daemon/handlers/snapshot-capture.ts index 157747b35..520d58bf4 100644 --- a/src/daemon/handlers/snapshot-capture.ts +++ b/src/daemon/handlers/snapshot-capture.ts @@ -47,7 +47,8 @@ import { snapshotCaptureAnnotationsFrom, type SnapshotCaptureAnnotations, } from '../../snapshot-capture-annotations.ts'; -import { recordSnapshotTiming } from '../../snapshot-diagnostics.ts'; +import { readSnapshotRunnerTiming, recordSnapshotTiming } from '../../snapshot-diagnostics.ts'; +import { emitDiagnostic } from '../../utils/diagnostics.ts'; type CaptureSnapshotParams = { device: SessionState['device']; @@ -65,6 +66,7 @@ type SnapshotData = { truncated?: boolean; backend?: SnapshotBackend; quality?: unknown; + snapshotTiming?: unknown; } & Omit; type SnapshotAttempt = { @@ -311,10 +313,24 @@ async function capturePostActionSnapshotAttempt( async function captureSnapshotAttempt(params: CaptureSnapshotParams): Promise { const startedAt = Date.now(); const data = await captureSnapshotData(params); - recordSnapshotTiming(params.session, { + const runnerTiming = readSnapshotRunnerTiming(data.snapshotTiming); + const timingSample = { durationMs: Date.now() - startedAt, backend: data.backend, platform: params.device.platform, + ...(runnerTiming?.phases ? { phases: runnerTiming.phases } : {}), + }; + recordSnapshotTiming(params.session, timingSample); + emitDiagnostic({ + level: 'debug', + phase: 'snapshot_capture_timing', + durationMs: timingSample.durationMs, + data: { + platform: params.device.platform, + backend: data.backend, + phases: runnerTiming?.phases, + runnerSelectedBackend: runnerTiming?.selectedBackend, + }, }); return { data, diff --git a/src/snapshot-diagnostics.ts b/src/snapshot-diagnostics.ts index 64ec2dd2e..fb38acc68 100644 --- a/src/snapshot-diagnostics.ts +++ b/src/snapshot-diagnostics.ts @@ -3,11 +3,15 @@ import type { Platform } from './utils/device.ts'; import { isRecord } from './utils/parsing.ts'; const SLOW_SNAPSHOT_P95_WARNING_MS = 1_500; +const SNAPSHOT_TIMING_SAMPLE_LIMIT = 50; +const SNAPSHOT_TIMING_PHASE_LIMIT = 24; +const SNAPSHOT_TIMING_PHASE_KEY_PATTERN = /^[a-z0-9_.-]{1,64}$/; export type SnapshotTimingSample = { durationMs: number; backend?: SnapshotBackend; platform?: Platform; + phases?: Record; }; export type SnapshotTimingStats = { @@ -26,9 +30,17 @@ export type SnapshotDiagnosticsState = { export type SnapshotDiagnosticsSummary = { stats: SnapshotTimingStats; + phases?: Record; warning?: string; }; +export type SnapshotRunnerTiming = { + totalMs?: number; + phases?: Record; + backends?: Record; + selectedBackend?: string; +}; + export function recordSnapshotTiming( session: { snapshotDiagnostics?: SnapshotDiagnosticsState } | undefined, sample: SnapshotTimingSample, @@ -38,7 +50,11 @@ export function recordSnapshotTiming( diagnostics.samples.push({ ...sample, durationMs: Math.max(0, Math.round(sample.durationMs)), + ...(sample.phases ? { phases: normalizeTimingPhases(sample.phases) } : {}), }); + if (diagnostics.samples.length > SNAPSHOT_TIMING_SAMPLE_LIMIT) { + diagnostics.samples.splice(0, diagnostics.samples.length - SNAPSHOT_TIMING_SAMPLE_LIMIT); + } } export function summarizeSnapshotDiagnostics( @@ -54,8 +70,10 @@ export function summarizeSnapshotTimingSamples( ): SnapshotDiagnosticsSummary | undefined { if (samples.length === 0) return undefined; const stats = buildSnapshotTimingStats(samples); + const phases = buildSnapshotPhaseStats(samples); return { stats, + ...(phases ? { phases } : {}), ...(stats.p95Ms >= SLOW_SNAPSHOT_P95_WARNING_MS ? { warning: formatSlowSnapshotWarning(stats) } : {}), @@ -68,8 +86,10 @@ export function mergeSnapshotDiagnostics( const samples = summaries.flatMap((summary) => samplesFromStats(summary?.stats)); if (samples.length === 0) return undefined; const stats = buildSnapshotTimingStats(samples); + const phases = mergeSnapshotPhaseStats(summaries); return { stats, + ...(phases ? { phases } : {}), ...(stats.p95Ms >= SLOW_SNAPSHOT_P95_WARNING_MS ? { warning: formatSlowSnapshotWarning(stats) } : {}), @@ -83,7 +103,30 @@ export function readSnapshotDiagnosticsSummary( const stats = readSnapshotTimingStats(value.stats); if (!stats) return undefined; const warning = typeof value.warning === 'string' ? value.warning : undefined; - return { stats, ...(warning ? { warning } : {}) }; + const phases = readSnapshotPhaseStats(value.phases); + return { stats, ...(phases ? { phases } : {}), ...(warning ? { warning } : {}) }; +} + +export function readSnapshotRunnerTiming(value: unknown): SnapshotRunnerTiming | undefined { + if (!isRecord(value)) return undefined; + const totalMs = readTimingNumber(value.totalMs); + const phases = normalizeTimingPhases({ + ...(isRecord(value.phases) ? readTimingNumberRecord(value.phases) : {}), + ...(totalMs !== undefined ? { runner_total: totalMs } : {}), + ...prefixTimingPhases('backend', isRecord(value.backends) ? value.backends : undefined), + }); + const selectedBackend = + typeof value.selectedBackend === 'string' && value.selectedBackend.trim().length > 0 + ? value.selectedBackend + : undefined; + if (totalMs === undefined && Object.keys(phases).length === 0 && !selectedBackend) { + return undefined; + } + return { + ...(totalMs !== undefined ? { totalMs } : {}), + ...(Object.keys(phases).length > 0 ? { phases } : {}), + ...(selectedBackend ? { selectedBackend } : {}), + }; } function buildSnapshotTimingStats(samples: SnapshotTimingSample[]): SnapshotTimingStats { @@ -99,6 +142,31 @@ function buildSnapshotTimingStats(samples: SnapshotTimingSample[]): SnapshotTimi }; } +function buildSnapshotPhaseStats( + samples: SnapshotTimingSample[], +): Record | undefined { + const phaseSamples = new Map(); + for (const sample of samples) { + if (!sample.phases) continue; + for (const [phase, durationMs] of Object.entries(sample.phases)) { + const current = phaseSamples.get(phase) ?? []; + current.push({ + durationMs, + platform: sample.platform, + backend: sample.backend, + }); + phaseSamples.set(phase, current); + } + } + if (phaseSamples.size === 0) return undefined; + return Object.fromEntries( + Array.from(phaseSamples.entries()) + .sort(([left], [right]) => left.localeCompare(right)) + .slice(0, SNAPSHOT_TIMING_PHASE_LIMIT) + .map(([phase, phaseTimingSamples]) => [phase, buildSnapshotTimingStats(phaseTimingSamples)]), + ); +} + function percentileNearestRank(values: number[], percentile: number): number { if (values.length === 0) return 0; const index = Math.max(0, Math.ceil((percentile / 100) * values.length) - 1); @@ -163,6 +231,38 @@ function readBackendCounts(value: Record): Record 0 ? Object.fromEntries(entries) : undefined; } +function readSnapshotPhaseStats(value: unknown): Record | undefined { + if (!isRecord(value)) return undefined; + const entries = Object.entries(value) + .filter(([key]) => SNAPSHOT_TIMING_PHASE_KEY_PATTERN.test(key)) + .slice(0, SNAPSHOT_TIMING_PHASE_LIMIT) + .flatMap(([key, stats]) => { + const timingStats = readSnapshotTimingStats(stats); + return timingStats ? ([[key, timingStats]] as const) : []; + }); + return entries.length > 0 ? Object.fromEntries(entries) : undefined; +} + +function mergeSnapshotPhaseStats( + summaries: Array, +): Record | undefined { + const phaseSamples = new Map(); + for (const summary of summaries) { + for (const [phase, stats] of Object.entries(summary?.phases ?? {})) { + const current = phaseSamples.get(phase) ?? []; + current.push(...samplesFromStats(stats)); + phaseSamples.set(phase, current); + } + } + if (phaseSamples.size === 0) return undefined; + return Object.fromEntries( + Array.from(phaseSamples.entries()) + .sort(([left], [right]) => left.localeCompare(right)) + .slice(0, SNAPSHOT_TIMING_PHASE_LIMIT) + .map(([phase, samples]) => [phase, buildSnapshotTimingStats(samples)]), + ); +} + function readOptionalSnapshotTimingStats( record: Record, ): Pick { @@ -191,3 +291,39 @@ function samplesFromStats(stats: SnapshotTimingStats | undefined): SnapshotTimin { durationMs: stats.maxMs, platform }, ]; } + +function normalizeTimingPhases(phases: Record): Record { + return Object.fromEntries( + Object.entries(phases) + .filter(([key, value]) => { + return SNAPSHOT_TIMING_PHASE_KEY_PATTERN.test(key) && Number.isFinite(value); + }) + .slice(0, SNAPSHOT_TIMING_PHASE_LIMIT) + .map(([key, value]) => [key, Math.max(0, Math.round(value))]), + ); +} + +function readTimingNumber(value: unknown): number | undefined { + return typeof value === 'number' && Number.isFinite(value) ? value : undefined; +} + +function readTimingNumberRecord(value: Record): Record { + return Object.fromEntries( + Object.entries(value).filter((entry): entry is [string, number] => { + return readTimingNumber(entry[1]) !== undefined; + }), + ); +} + +function prefixTimingPhases( + prefix: string, + value: Record | undefined, +): Record { + if (!value) return {}; + return Object.fromEntries( + Object.entries(readTimingNumberRecord(value)).map(([key, durationMs]) => [ + `${prefix}.${key}`, + durationMs, + ]), + ); +}