diff --git a/packages/contracts/src/snapshot-diagnostics.ts b/packages/contracts/src/snapshot-diagnostics.ts index a109b63783..5618fa04d2 100644 --- a/packages/contracts/src/snapshot-diagnostics.ts +++ b/packages/contracts/src/snapshot-diagnostics.ts @@ -4,6 +4,12 @@ import { isRecord } from './json.ts'; const SLOW_SNAPSHOT_P95_WARNING_MS = 1_500; +/** Warm captures needed before chronic slowness is distinguishable from noise. */ +const MIN_WARM_SAMPLE_COUNT = 3; + +/** Slow warm captures needed before slowness counts as chronic rather than a one-off hiccup. */ +const MIN_SLOW_WARM_SAMPLES = 2; + export type SnapshotTimingSample = { durationMs: number; backend?: SnapshotBackend; @@ -54,25 +60,55 @@ export function summarizeSnapshotTimingSamples( samples: SnapshotTimingSample[], ): SnapshotDiagnosticsSummary | undefined { if (samples.length === 0) return undefined; - const stats = buildSnapshotTimingStats(samples); + // The first capture folds one-time startup (runner launch, helper install) + // into its duration, and nearest-rank p95 over a small sample set is just + // its max — so the warning judges warm captures only, and only once enough + // exist to mean anything. A single warm outlier is a hiccup, not chronic + // slowness: the warning additionally needs a quorum of slow warm captures, + // so nearest-rank-equals-max can never fire it alone. Displayed stats still + // cover every sample. + const warm = samples.slice(1); + const judged = warm.length >= MIN_WARM_SAMPLE_COUNT ? buildSnapshotTimingStats(warm) : undefined; + const slowWarmCount = warm.filter( + (sample) => sample.durationMs >= SLOW_SNAPSHOT_P95_WARNING_MS, + ).length; + const warns = + judged !== undefined && + judged.p95Ms >= SLOW_SNAPSHOT_P95_WARNING_MS && + slowWarmCount >= MIN_SLOW_WARM_SAMPLES; return { - stats, - ...(stats.p95Ms >= SLOW_SNAPSHOT_P95_WARNING_MS - ? { warning: formatSlowSnapshotWarning(stats) } - : {}), + stats: buildSnapshotTimingStats(samples), + ...(warns && judged ? { warning: formatSlowSnapshotWarning(judged) } : {}), }; } export function mergeSnapshotDiagnostics( summaries: Array, ): SnapshotDiagnosticsSummary | undefined { - const samples = summaries.flatMap((summary) => samplesFromStats(summary?.stats)); + const present = summaries.filter( + (summary): summary is SnapshotDiagnosticsSummary => summary !== undefined, + ); + const samples = present.flatMap((summary) => samplesFromStats(summary.stats)); if (samples.length === 0) return undefined; const stats = buildSnapshotTimingStats(samples); + // Reconstructed samples are lossy and order-less (a run's cold start comes + // back as both its p95 and its max), so only layers holding ordered live + // samples judge slowness; merge aggregates display stats and carries a + // warning only when a constituent run judged one itself. The message speaks + // about the warned runs, never the aggregate — one slow run among many fast + // ones would otherwise produce "slow: p95 ". + const warned = present.filter((summary) => summary.warning); return { stats, - ...(stats.p95Ms >= SLOW_SNAPSHOT_P95_WARNING_MS - ? { warning: formatSlowSnapshotWarning(stats) } + ...(warned.length > 0 + ? { + warning: formatMergedSlowSnapshotWarning({ + warnedCount: warned.length, + totalCount: present.length, + worst: warned.reduce((max, summary) => Math.max(max, summary.stats.p95Ms), 0), + platform: stats.platform, + }), + } : {}), }; } @@ -128,6 +164,16 @@ function formatSlowSnapshotWarning(stats: SnapshotTimingStats): string { return `Warning: ${platform}snapshots are slow in this run: p95 ${stats.p95Ms}ms over ${stats.count} captures. Possible causes: device load, app or dev server stuck, helper fallback, or stale daemon.`; } +function formatMergedSlowSnapshotWarning(params: { + warnedCount: number; + totalCount: number; + worst: number; + platform?: PublicPlatform; +}): string { + const platform = params.platform ? `${params.platform} ` : ''; + return `Warning: ${platform}snapshots were slow in ${params.warnedCount} of ${params.totalCount} runs (worst run p95 ${params.worst}ms). Possible causes: device load, app or dev server stuck, helper fallback, or stale daemon.`; +} + function readSnapshotTimingStats(value: unknown): SnapshotTimingStats | undefined { if (!isRecord(value)) return undefined; const required = readRequiredSnapshotTimingStats(value); diff --git a/src/__tests__/snapshot-diagnostics.test.ts b/src/__tests__/snapshot-diagnostics.test.ts index 70ebb35bfd..230710af33 100644 --- a/src/__tests__/snapshot-diagnostics.test.ts +++ b/src/__tests__/snapshot-diagnostics.test.ts @@ -3,6 +3,7 @@ import { mergeSnapshotDiagnostics, recordSnapshotTiming, summarizeSnapshotDiagnostics, + summarizeSnapshotTimingSamples, } from '@agent-device/contracts/capture'; test('records session snapshot timing stats', () => { @@ -11,6 +12,8 @@ test('records session snapshot timing stats', () => { recordSnapshotTiming(session, { durationMs: 400, backend: 'android', platform: 'android' }); recordSnapshotTiming(session, { durationMs: 2_100, backend: 'android', platform: 'android' }); + // Two samples cannot distinguish chronic slowness from a one-off — stats are + // reported, but no warning fires. expect(summarizeSnapshotDiagnostics(session)).toEqual({ stats: { count: 2, @@ -21,10 +24,44 @@ test('records session snapshot timing stats', () => { platform: 'android', backends: { android: 2 }, }, - warning: expect.stringContaining('p95 2100ms over 2 captures'), }); }); +test('a slow cold-start capture alone does not warn', () => { + // First capture folds runner/helper startup (12s); warm captures are fast. + const samples = [12_400, 520, 540, 510, 530, 525].map((durationMs) => ({ + durationMs, + platform: 'ios' as const, + })); + + const summary = summarizeSnapshotTimingSamples(samples); + expect(summary?.warning).toBeUndefined(); + // The cold sample still shows in the full stats. + expect(summary?.stats).toMatchObject({ count: 6, maxMs: 12_400 }); +}); + +test('a single warm outlier does not warn (quorum rule)', () => { + // One 12s hiccup among fast warm captures: nearest-rank p95 IS that outlier + // through n=19, so without a quorum the restart-inviting warning would fire + // from one bad sample. + const samples = [12_400, 520, 520, 12_400].map((durationMs) => ({ + durationMs, + platform: 'ios' as const, + })); + + expect(summarizeSnapshotTimingSamples(samples)?.warning).toBeUndefined(); +}); + +test('chronically slow warm captures warn without counting the cold start', () => { + const samples = [12_400, 2_600, 2_700, 2_500, 2_800].map((durationMs) => ({ + durationMs, + platform: 'ios' as const, + })); + + const summary = summarizeSnapshotTimingSamples(samples); + expect(summary?.warning).toContain('p95 2800ms over 4 captures'); +}); + test('merges snapshot diagnostics without inflating capture count', () => { const merged = mergeSnapshotDiagnostics([ { @@ -56,5 +93,60 @@ test('merges snapshot diagnostics without inflating capture count', () => { maxMs: 1_900, platform: 'android', }); - expect(merged?.warning).toContain('p95 1900ms over 3 captures'); + // Neither constituent judged a warning (reconstructed samples are lossy and + // order-less), so the merge must not resurrect one from the aggregate. + expect(merged?.warning).toBeUndefined(); +}); + +test('merge carries a warning only when a constituent run judged one', () => { + const stats = { + count: 4, + p50Ms: 2_600, + p95Ms: 2_800, + maxMs: 2_800, + slowThresholdMs: 1_500, + platform: 'ios', + } as const; + + const merged = mergeSnapshotDiagnostics([ + { stats: { ...stats } }, + { stats: { ...stats }, warning: 'Warning: ios snapshots are slow in this run: …' }, + ]); + + expect(merged?.warning).toContain('slow in 1 of 2 runs'); + expect(merged?.warning).toContain('worst run p95 2800ms'); +}); + +test('merged warning speaks about the warned run, never the fast aggregate', () => { + // One slow warned run among many fast ones: the aggregate p95 is a fast + // number, and quoting it in a slowness warning would be self-contradictory. + const fast = { + count: 20, + p50Ms: 90, + p95Ms: 100, + maxMs: 100, + slowThresholdMs: 1_500, + platform: 'ios', + } as const; + const slow = { + count: 2, + p50Ms: 2_500, + p95Ms: 2_900, + maxMs: 2_900, + slowThresholdMs: 1_500, + platform: 'ios', + } as const; + + const merged = mergeSnapshotDiagnostics([ + { stats: { ...fast } }, + { stats: { ...fast } }, + { stats: { ...fast } }, + { stats: { ...slow }, warning: 'Warning: ios snapshots are slow in this run: …' }, + ]); + + // Aggregate p95 is fast — it must not appear as the headline number. + expect(merged?.stats.p95Ms).toBeLessThan(1_500); + expect(merged?.warning).toContain('slow in 1 of 4 runs'); + expect(merged?.warning).toContain('worst run p95 2900ms'); + expect(merged?.warning).not.toContain(`p95 ${merged?.stats.p95Ms}ms`); }); diff --git a/src/daemon/handlers/__tests__/session-replay-runtime-maestro.test.ts b/src/daemon/handlers/__tests__/session-replay-runtime-maestro.test.ts index 9c085b7151..43d22607c8 100644 --- a/src/daemon/handlers/__tests__/session-replay-runtime-maestro.test.ts +++ b/src/daemon/handlers/__tests__/session-replay-runtime-maestro.test.ts @@ -254,7 +254,12 @@ test('.ad replay normalizes resolved gesture and swipe syntax into structured da test('runReplayScriptFile reports snapshot diagnostics from per-action session samples', async () => { const root = mkdtempForTestSync('agent-device-replay-snapshot-samples-'); const scriptPath = path.join(root, 'flow.ad'); - fs.writeFileSync(scriptPath, ['snapshot', 'snapshot', ''].join('\n')); + // Four warm captures beyond the cold start: the slow-run warning judges warm + // samples only and needs at least three of them. + fs.writeFileSync( + scriptPath, + ['snapshot', 'snapshot', 'snapshot', 'snapshot', 'snapshot', ''].join('\n'), + ); const sessionStore = new SessionStore(path.join(root, 'state')); sessionStore.set( 's', @@ -305,14 +310,19 @@ test('runReplayScriptFile reports snapshot diagnostics from per-action session s const diagnostics = response.data?.snapshotDiagnostics as | { stats?: { count?: number }; warning?: string } | undefined; - assert.equal(diagnostics?.stats?.count, 2); - assert.match(String(diagnostics?.warning), /p95 1900ms over 2 captures/); + assert.equal(diagnostics?.stats?.count, 5); + assert.match(String(diagnostics?.warning), /p95 1900ms over 4 captures/); }); test('runReplayScriptFile reports snapshot diagnostics on replay failure', async () => { const root = mkdtempForTestSync('agent-device-replay-snapshot-failure-'); const scriptPath = path.join(root, 'flow.ad'); - fs.writeFileSync(scriptPath, ['snapshot', 'click "Missing"', ''].join('\n')); + // Three warm captures precede the failing click so the failure-path summary + // has enough warm samples to judge. + fs.writeFileSync( + scriptPath, + ['snapshot', 'snapshot', 'snapshot', 'snapshot', 'click "Missing"', ''].join('\n'), + ); const sessionStore = new SessionStore(path.join(root, 'state')); sessionStore.set( 's', @@ -341,7 +351,7 @@ test('runReplayScriptFile reports snapshot diagnostics on replay failure', async backend: 'xctest', platform: 'ios', }); - if (captures === 1) return { ok: true, data: {} }; + if (captures < 5) return { ok: true, data: {} }; return { ok: false, error: { code: 'COMMAND_FAILED', message: 'button missing' } }; }, }); @@ -350,9 +360,9 @@ test('runReplayScriptFile reports snapshot diagnostics on replay failure', async const diagnostics = response.error.details?.snapshotDiagnostics as | { stats?: { count?: number; p95Ms?: number }; warning?: string } | undefined; - assert.equal(diagnostics?.stats?.count, 2); + assert.equal(diagnostics?.stats?.count, 5); assert.equal(diagnostics?.stats?.p95Ms, 2_100); - assert.match(String(diagnostics?.warning), /p95 2100ms over 2 captures/); + assert.match(String(diagnostics?.warning), /p95 2100ms over 4 captures/); }); test('runReplayScriptFile applies CLI env overrides before Maestro compat mapping', async () => { diff --git a/src/daemon/handlers/__tests__/session-test-suite.test.ts b/src/daemon/handlers/__tests__/session-test-suite.test.ts index 260516acfb..aa6d3e75f8 100644 --- a/src/daemon/handlers/__tests__/session-test-suite.test.ts +++ b/src/daemon/handlers/__tests__/session-test-suite.test.ts @@ -467,8 +467,12 @@ test('test aggregates snapshot diagnostics from replay session samples', async ( maxMs: 1_900, platform: 'android', }, - warning: expect.stringContaining('p95 1900ms over 2 captures'), }); + // Neither single-capture run had enough warm samples to judge slowness, so + // the merged suite report must not resurrect a warning from the aggregate. + expect( + (data.snapshotDiagnostics as Record | undefined)?.warning, + ).toBeUndefined(); expect((data.tests as Array>)[1]?.snapshotDiagnostics).toMatchObject({ stats: { count: 1, @@ -516,14 +520,18 @@ test('test aggregates snapshot diagnostics from failed replay session samples', const data = expectOkData(response); expect(data.failed).toBe(1); + // A single capture is indistinguishable from a cold start — diagnostics are + // reported without a slow-run warning. expect(data.snapshotDiagnostics).toMatchObject({ stats: { count: 1, p95Ms: 2_100, platform: 'android', }, - warning: expect.stringContaining('p95 2100ms over 1 captures'), }); + expect( + (data.snapshotDiagnostics as Record | undefined)?.warning, + ).toBeUndefined(); expect((data.tests as Array>)[0]).toMatchObject({ status: 'failed', snapshotDiagnostics: {