diff --git a/packages/contracts/package.json b/packages/contracts/package.json index e0df095203..cd020253b9 100644 --- a/packages/contracts/package.json +++ b/packages/contracts/package.json @@ -340,6 +340,10 @@ "types": "./src/orientation-runtime.ts", "default": "./src/orientation-runtime.ts" }, + "./perf-hang-next-steps": { + "types": "./src/perf-hang-next-steps.ts", + "default": "./src/perf-hang-next-steps.ts" + }, "./perf-runtime": { "types": "./src/perf-runtime.ts", "default": "./src/perf-runtime.ts" diff --git a/packages/contracts/src/__tests__/perf-hang-next-steps.test.ts b/packages/contracts/src/__tests__/perf-hang-next-steps.test.ts new file mode 100644 index 0000000000..8114d53594 --- /dev/null +++ b/packages/contracts/src/__tests__/perf-hang-next-steps.test.ts @@ -0,0 +1,31 @@ +import { test } from 'vitest'; +import assert from 'node:assert/strict'; +import { perfHangNextSteps, perfHitchNextSteps } from '../perf-hang-next-steps.ts'; + +test('perfHangNextSteps names the top symbol for a running-dominant main-thread hang', () => { + const steps = perfHangNextSteps({ + runningMs: 3_800, + blockedMs: 200, + topSymbol: 'HangViewController.blockMainThread(seconds:)', + threadName: 'Main Thread', + }); + assert.match(steps.join('\n'), /HangViewController\.blockMainThread\(seconds:\)/); + assert.match(steps.join('\n'), /perf cpu profile/); + assert.ok(!steps.join('\n').includes('blocked, not running')); +}); + +test('perfHangNextSteps recommends offloading for a blocked-dominant hang', () => { + const steps = perfHangNextSteps({ runningMs: 10, blockedMs: 2_900, threadName: 'main' }); + assert.equal(steps.length, 1); + assert.match(steps.join('\n'), /blocked, not running/); +}); + +test('perfHangNextSteps recommends a CPU profile without a top symbol', () => { + const steps = perfHangNextSteps({ runningMs: 900, blockedMs: 0 }); + assert.equal(steps.length, 1); + assert.match(steps.join('\n'), /perf cpu profile/); +}); + +test('perfHitchNextSteps points at layout cost and trace UIs', () => { + assert.match(perfHitchNextSteps().join('\n'), /layout cost/); +}); diff --git a/packages/contracts/src/perf-hang-next-steps.ts b/packages/contracts/src/perf-hang-next-steps.ts new file mode 100644 index 0000000000..10de923df9 --- /dev/null +++ b/packages/contracts/src/perf-hang-next-steps.ts @@ -0,0 +1,89 @@ +/** One main-thread freeze window attributed from a native trace. */ +export type PerfHang = Readonly<{ + /** Offset from trace start in milliseconds. */ + startOffsetMs: number; + durationMs: number; + thread: string; + /** Innermost sampled symbol with the most running weight inside the window. */ + topSymbol?: string; + runningMs: number; + blockedMs: number; + source: string; + nextSteps: string[]; +}>; + +export type PerfHangCause = Readonly<{ + runningMs: number; + blockedMs: number; + topSymbol?: string; + threadName?: string; +}>; + +/** + * Static rule table for one classified hang. Returns agent-actionable next steps + * from the hang cause only; it never parses free-form tool output. + */ +export function perfHangNextSteps(cause: PerfHangCause): string[] { + if (cause.runningMs >= cause.blockedMs) { + return cause.topSymbol + ? [ + `Inspect ${cause.topSymbol} on the main thread; it holds the most samples in this window.`, + 'Run perf cpu profile around the interaction for a symbol-level breakdown.', + ] + : ['Run perf cpu profile around the interaction to attribute CPU work inside this window.']; + } + return [ + 'The main thread is blocked, not running; move the waiting work (I/O, binder, lock) off the main thread.', + ]; +} + +/** + * Static rule for hitch evidence without a CPU hotspot. + */ +export function perfHitchNextSteps(): string[] { + return [ + 'Frame hitches have no matching CPU hotspot; check layout cost and overdraw, then open the trace in Instruments or the Perfetto UI.', + ]; +} + +/** A symbol ranked by accumulated on-CPU self-sample weight. */ +export type PerfTraceHotspot = Readonly<{ + symbol: string; + binary?: string; + selfSampleMs: number; +}>; + +/** Hitch tally for the attached app only. */ +export type PerfTraceHitches = Readonly<{ + available: boolean; + count: number; + maxDurationMs?: number; + nextSteps: string[]; +}>; + +/** + * Shared unavailable half of a trace-analysis stop summary. Each platform names + * its own typed reasons; the envelope stays one shape for CLI and clients. + */ +export type PerfTraceAnalysisUnavailable = Readonly<{ + available: false; + reason: Reason; + message: string; + hint: string; +}>; + +/** + * Shared trace-analysis envelope attached to a native `perf trace stop` result + * `summary` on every platform: either interpreted evidence or a typed failure. + */ +export type PerfTraceAnalysis = + | Readonly<{ + available: true; + tracePath: string; + hangs: Hang[]; + hangCount: number; + hitches?: PerfTraceHitches; + hotspots: Hotspot[]; + notes: string[]; + }> + | PerfTraceAnalysisUnavailable; diff --git a/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-hitches.xml b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-hitches.xml new file mode 100644 index 0000000000..e4a5d184e4 --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-hitches.xml @@ -0,0 +1,10 @@ + + + +startStartstart-timedurationDurationdurationprocessProcessprocessis-systemIs Systembooleanswap-idSwap IDuint32labelSwap IDstringdisplayDisplaydisplay-namenarrative-descriptionPotential Issuestring3751313541833329157204TODO0166621740xfe3e9eDisplay 1 +5167964500166622870xfe3f0f +1589284566616666583166629770xfe41c1 +85120040002000000091502TODO0166625000xfe4000 diff --git a/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile-hangtool.xml b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile-hangtool.xml new file mode 100644 index 0000000000..9ab558ad2b --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile-hangtool.xml @@ -0,0 +1,4 @@ + + + +timeSample Timesample-timethreadThreadthreadprocessProcessprocesscoreCorecorethread-stateStatethread-stateweightWeightweightstackBacktracetagged-backtrace222492695825002595118731TODO3Running100000056579267085658926541565992679125660926958566192641656629262915663926875566492645856659269585666926458566792604165668925750566992583356709255835671926166115672925833567392562556749256255675926000567692587556779267085567892558356799255835680925708568192562556829256255683925750568492554156859259585686925708568792575056889271255689925583569092612556919255835692925583569392562556949256255695925708569692583356979257505698925875569992658357009257505701928916570292587557039255835704925666570592570857069258335707925750570892562557099261254571092562557119260415712925666571392562557149256255715925875 \ No newline at end of file diff --git a/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile.xml b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile.xml new file mode 100644 index 0000000000..33d329b87d --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-timeprofile.xml @@ -0,0 +1,267 @@ + + +timeSample Timesample-timethreadThreadthreadprocessProcessprocesscoreCorecorethread-stateStatethread-stateweightWeightweightstackBacktracetagged-backtrace191683608324671244564549TODO3Running5000000 +21106738332467124340 +211377529124671244811 +2114574458 +21181240833549625 +21195761668 +2124575708 +2125359708784000 +2129574125 +2134573708 +2139573708 +2144573583 +2149573625 +2154573625 +21587523754178750 +21595738334 +2164573666 +21687633334189667 +2169574041 +21733100413736000 +2174573625 +2179573666 +2184573791 +2189573666 +2194573625 +2199574333 +2200397708823375 +2204573833 +2209573666 +2210405666832000 +2214576916 +2219573666 +2224573625 +2225340791767166 +22295741256 +2234573750 +2235353250779500 +2239574125 +2244573625 +2249573791 +2254573666 +2259573625 +2264573708 +2269573666 +2274573666 +2275313458739792 +2279574125 +2284573666 +2289573583 +2294576875 +2299573666 +2304573708 +23086709584097250 +230957725010 +2314573625 +2319573625 +2324573583 +2329573625 +2334573666 +2339573541 +2344573583 +2349573708 +2350270875697167 +2354573833 +2359573708 +2360281416707708 +2364574375 +2369573708 +2374573666 +2375308041734375 +23795750009 +2384573750 +2389573666 +2394573625 +2399573625 +2404573583 +2409573625 +2414575250 +2419573583 +2424573791 +2425374041800250 +2429576708 +2434573625 +2439573583 +2444573625 +2449576708 +2454573708 +24587693754195667 +2459573833 +2464573750 +24687802914206541 +2469577375 +2474573666 +2479573625 +2484576625 +2489573708 +2494573750 +2499573791 +2500275958702167 +2504576916 +2509576625 +2514573750 +2519573750 +2524573666 +2525486583912917 +2529574333 +2534573666 +2535505041931375 +2539573875 +2544573958 +2549573708 +2554573791 +2559573583 +2564573666 +2569573625 +2574573625 +2575328083754458 +2579574041 +2584573750 +2589573666 +2594574000 +2599573666 +2604577708 +26086641664086458 +2609573625 +2614573750 +2619573666 +2624576666 +2629573625 +2634576791 +2639573625 +2644573791 +2649577291 +2650314666737375 +2654573750 +2659573916 +2664573666 +2669573666 +2674573791 +2675194458620667 +2679576916 +2684573625 +2689573708 +2694573833 +2699573750 +2704573666 +2709573708 +2714573666 +2719573583 +2724573625 +2725354041780416 +2729574125 +2734573625 +2739576625 +2744573666 +2745366208792542 +2749576916 +2754573666 +27586377914064125 +2759573708 +2764576500 +2769576541 +2774576541 +2779573583 +2784573625 +2789573791 +2794573625 +2799573833 +2800402916829083 +28045742087 +2809573708 +2814576500 +2819573875 +2824573625 +2825372708799083 +2829575833 +2834573625 +2835385458811833 +28395752505 +2844573958 +2849573791 +2854573875 +2859573583 +2864573583 +2869573583 +2874573708 +2875354416780708 +2879574083 +2884573791 +2885362666788875 +2889574333 +2894574000 +2895372166798166 +2899576708 +2904573583 +29086380004064417 +2909573666 +2914573791 +2919573583 +2924573708 +2929573708 +2934573625 +2939573583 +2944573875 +2949573625 +2950290166716541 +2954573958 +2959573625 +2964573583 +2969573583 +2974573625 +2975110166536541 +2979573916 +2984573583 +2985123500549917 +2989573833 +2994573625 +2999576708 +3004573875 +3009573708 +3014573916 +3019573666 +3024573708 +3025316416742708 +3029573791 +3034573583 +3039573583 +3044573625 +3049573666 +3054576583 +30584051253828542 +3059574083 +3064573666 +3069573625 +3074573708 +3079573625 +3084573708 +3089573583 +3094573708 +3099573583 +3099784750211167 +3104574333 +3109573791 +3114576625 +3119573666 +3124576666 +3125172833596167 +3129573833 +3134573750 +3139576833 +3144573708 +3149578333 +3154576541 +3159573583 +3164576750 +3169573625 +3174573708 +3175257791684083 +3179573875 +3184573708 +3185268458694750 +3189574041 +3194573583 +3199573708 + diff --git a/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-toc.xml b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-toc.xml new file mode 100644 index 0000000000..38aa290643 --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/fixtures/perf-trace-analysis-toc.xml @@ -0,0 +1,73 @@ + + + + + + + + + + + + 2026-10-23T08:13:26.393+02:00 + 2026-10-23T08:13:56.983+02:00 + 30.590010 + Time limit reached + 27.1 (27A9275) + Time Profiler + Deferred + 30 seconds + + + + + + + + + + + + + + + + + + +
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+ + + + \ No newline at end of file diff --git a/packages/platform-apple/src/core/__tests__/perf-trace-analysis.test.ts b/packages/platform-apple/src/core/__tests__/perf-trace-analysis.test.ts new file mode 100644 index 0000000000..77a55ab976 --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/perf-trace-analysis.test.ts @@ -0,0 +1,198 @@ +import { test } from 'vitest'; +import assert from 'node:assert/strict'; +import { readFileSync } from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { + analyzeAppleTraceTables, + matchesAppleTraceTarget, + readAppleTraceTableSchemas, +} from '../perf-trace-analysis.ts'; + +// Excerpts captured with xctrace (Xcode 27.1) from an iOS simulator run of a hang app: +// busy main-thread hangs. Hangs are derived from the time-profile samples because +// Instruments does not fill potential-hangs on simulated devices. +const fixtures = path.join(path.dirname(fileURLToPath(import.meta.url)), 'fixtures'); +const tocXml = readFileSync(path.join(fixtures, 'perf-trace-analysis-toc.xml'), 'utf8'); +const timeProfileXml = readFileSync( + path.join(fixtures, 'perf-trace-analysis-timeprofile.xml'), + 'utf8', +); + +const TARGET = { + tracePath: '/tmp/HangApp.trace', + targetProcesses: ['HangApp'], + targetPids: [64549], +}; + +// Non-monotonic merge: a sample whose (time + weight) ends before the current run +// end must not move that end backwards, so the run duration keeps the accounting +// span instead of collapsing to the late sample's small end. +function nonMonotonicTimeProfileXml(): string { + const thread = + '24671243464549'; + const running = 'Running'; + const frame = ''; + return ` + 1000000000${thread}${running}3000000000${frame} + 1000000000${running}100000000 + 1100000000${running}100000000 + `; +} + +test('deriveAppleHangs keeps a non-monotonic sample from moving the run end backwards', () => { + // Sample 1 spans 1.0s..4.0s. Sample 2 (time 1.0s, weight 0.1s) merges into the + // run and its end (1.1s) is before the run end (4.0s): with a plain assignment + // the duration would collapse to 0.1s and drop below the 250ms threshold. + // The monotonic Math.max keeps the 3.0s span with running capped by exposure. + const result = analyzeAppleTraceTables({ + target: TARGET, + tocXml, + timeProfileXml: nonMonotonicTimeProfileXml(), + }); + assert.equal(result.available, true); + if (!result.available) return; + assert.equal(result.hangs.length, 1); + const hang = result.hangs[0]!; + assert.equal(hang.durationMs, 3_000); + assert.equal(hang.runningMs, 3_000); + assert.equal(hang.runningMs + hang.blockedMs <= hang.durationMs, true); +}); + +test('readAppleTraceTableSchemas lists TOC schemas from a real Time Profiler export', () => { + const schemas = readAppleTraceTableSchemas(tocXml); + assert.ok(schemas.includes('time-profile')); + assert.ok(schemas.includes('potential-hangs')); + assert.ok(schemas.includes('hang-risks')); + assert.ok(!schemas.includes('hitches')); + assert.deepEqual(schemas, [...schemas].sort()); +}); + +test('analyzeAppleTraceTables derives main-thread hangs from real time-profile samples', () => { + const result = analyzeAppleTraceTables({ + target: TARGET, + tocXml, + timeProfileXml, + }); + assert.equal(result.available, true); + if (!result.available) return; + // The fixture holds one induced busy main-thread window from a hang-app run. + const busyHang = result.hangs.find((hang) => hang.durationMs > 1_000); + assert.ok(busyHang, 'expected a >=1s derived hang'); + assert.equal(busyHang.source, 'time-profile'); + assert.equal(Math.abs(busyHang.startOffsetMs - 2_111) < 50, true); + assert.equal(Math.abs(busyHang.durationMs - 1_094) < 100, true); + assert.equal( + Math.abs(busyHang.runningMs - busyHang.durationMs) < busyHang.runningMs * 0.25, + true, + ); + assert.ok(busyHang.topSymbol && busyHang.topSymbol.length > 0); + assert.ok(busyHang.nextSteps.length > 0); + assert.match(busyHang.nextSteps.join('\n'), /Inspect .*main thread|perf cpu profile/i); + // The split and top symbol come only from the samples that formed the run, so a + // hang can never claim more time than it spans. + assert.equal(busyHang.runningMs + busyHang.blockedMs <= busyHang.durationMs, true); + assert.match(result.notes.join('\n'), /hangs were derived from contiguous Time Profiler samples/); +}); + +test('analyzeAppleTraceTables names table-export-failed when the TOC lists time-profile but its export failed', () => { + const result = analyzeAppleTraceTables({ + target: TARGET, + tocXml, + failedTables: ['time-profile'], + }); + assert.equal(result.available, false); + if (result.available) return; + assert.equal(result.reason, 'table-export-failed'); + assert.ok(!/template/.test(result.hint), 'the hint must not send the agent to re-record'); + assert.ok(result.tableSchemas.includes('time-profile')); +}); + +test('analyzeAppleTraceTables ranks hotspots from real samples', () => { + const result = analyzeAppleTraceTables({ + target: TARGET, + tocXml, + timeProfileXml, + }); + assert.equal(result.available, true); + if (!result.available) return; + assert.ok(result.hotspots.length > 0); + const totals = result.hotspots.map((hotspot) => hotspot.selfSampleMs); + assert.deepEqual( + totals, + [...totals].sort((left, right) => right - left), + ); + assert.ok(totals[0] !== undefined && totals[0] > 0); +}); + +test('analyzeAppleTraceTables reports unavailable without a time-profile table', () => { + const result = analyzeAppleTraceTables({ target: TARGET, tocXml }); + assert.equal(result.available, false); + if (result.available) return; + assert.equal(result.reason, 'no-time-profile-table'); + assert.match(result.hint, /Time Profiler/); + assert.ok(result.tableSchemas.includes('time-profile')); +}); + +test('analyzeAppleTraceTables reports unavailable when samples belong to another process', () => { + const result = analyzeAppleTraceTables({ + target: { tracePath: '/tmp/Other.trace', targetProcesses: ['com.other.app'], targetPids: [1] }, + tocXml, + timeProfileXml, + }); + assert.equal(result.available, false); + if (result.available) return; + assert.equal(result.reason, 'no-process-samples'); +}); + +test('analyzeAppleTraceTables counts only the app hitches from a real exported hitches table', () => { + // Three byte-exact rows from a real "Animation Hitches" export (xctrace, Xcode + // 27.1, attached app), plus one foreign-process row that reuses the real cell + // encoding (a single-process attach never emitted foreign rows here, and every + // multi-process capture crashed xctrace export). The target matches by bare + // process name, so the foreign row must fall out of the process filter. + const hitchesXml = readFileSync(path.join(fixtures, 'perf-trace-analysis-hitches.xml'), 'utf8'); + const timeProfileHangToolXml = readFileSync( + path.join(fixtures, 'perf-trace-analysis-timeprofile-hangtool.xml'), + 'utf8', + ); + const result = analyzeAppleTraceTables({ + target: { + tracePath: '/tmp/HangTool.trace', + targetProcesses: ['HangTool'], + targetPids: [], + }, + tocXml, + timeProfileXml: timeProfileHangToolXml, + hitchesXml, + }); + assert.equal(result.available, true); + if (!result.available) return; + assert.ok(result.hitches, 'an exported hitches table must be reported'); + assert.equal(result.hitches.available, true); + // The fixture holds three attached-app rows and one foreign-process row. + assert.equal(result.hitches.count, 3); + assert.equal(result.hitches.maxDurationMs, 16.7); + assert.ok(result.hitches.nextSteps.length > 0); +}); + +test('analyzeAppleTraceTables reports hitches unavailable without the table', () => { + const result = analyzeAppleTraceTables({ + target: TARGET, + tocXml, + timeProfileXml, + }); + assert.equal(result.available, true); + if (!result.available) return; + assert.equal(result.hitches, undefined); +}); + +test('matchesAppleTraceTarget accepts the recorded pid and bare executable name only for the target app', () => { + const target = { targetProcesses: ['com.example.HangApp'], targetPids: [64549] }; + assert.equal(matchesAppleTraceTarget('HangApp (64549)', 64549, target), true); + assert.equal( + matchesAppleTraceTarget('HangApp (64549)', 64549, { ...target, targetPids: [] }), + true, + ); + assert.equal(matchesAppleTraceTarget('BackBoardASD (501)', 501, target), false); +}); diff --git a/packages/platform-apple/src/core/__tests__/perf-xctrace-trace-stop.test.ts b/packages/platform-apple/src/core/__tests__/perf-xctrace-trace-stop.test.ts new file mode 100644 index 0000000000..943485341f --- /dev/null +++ b/packages/platform-apple/src/core/__tests__/perf-xctrace-trace-stop.test.ts @@ -0,0 +1,190 @@ +import { beforeEach, test, vi } from 'vitest'; +import assert from 'node:assert/strict'; +import { promises as fs, readFileSync } from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { mkdtempForTest } from '../../__tests__/tmp-dir.ts'; + +vi.mock('@agent-device/host-kit/command', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + runCmd: vi.fn(actual.runCmd), + runCmdBackground: vi.fn(actual.runCmdBackground), + }; +}); + +import { runCmd, runCmdBackground } from '@agent-device/host-kit/command'; +import { + analyzeAppleXctraceTrace, + stopAppleXctracePerfCapture, + type AppleXctracePerfCapture, +} from '../perf-xctrace.ts'; +import { mockHostCommands, type MockRunCmdResult } from './perf.fixtures.ts'; + +const mockRunCmdBackground = vi.mocked(runCmdBackground); + +const fixtures = path.join(path.dirname(fileURLToPath(import.meta.url)), 'fixtures'); +const tocXml = readFileSync(path.join(fixtures, 'perf-trace-analysis-toc.xml'), 'utf8'); +const timeProfileXml = readFileSync( + path.join(fixtures, 'perf-trace-analysis-timeprofile.xml'), + 'utf8', +); + +beforeEach(() => { + vi.resetAllMocks(); + mockRunCmdBackground.mockImplementation(() => mockBackgroundXctrace()); +}); + +function emptyRunResult(): MockRunCmdResult { + return { stdout: '', stderr: '', exitCode: 0 }; +} + +function readOutputPath(args: readonly string[], flag = '--output'): string { + return args[args.indexOf(flag) + 1]!; +} + +function mockBackgroundXctrace(): ReturnType { + return { + child: { kill: vi.fn(() => true), pid: 1234 } as unknown as ReturnType< + typeof runCmdBackground + >['child'], + wait: Promise.resolve(emptyRunResult()), + }; +} + +function traceCapture(tracePath: string): AppleXctracePerfCapture { + return { + kind: 'xctrace', + mode: 'trace', + template: 'Time Profiler', + outPath: tracePath, + appBundleId: 'com.example.hangapp', + deviceId: 'sim-1', + platform: 'ios', + targetPids: [64549], + targetProcesses: ['HangApp'], + startedAt: '2026-04-01T10:00:00.000Z', + child: { kill: vi.fn(() => true), pid: 1234 } as unknown as AppleXctracePerfCapture['child'], + wait: Promise.resolve(emptyRunResult()), + }; +} + +test('stopAppleXctracePerfCapture attaches interpreted hangs from the exported tables', async () => { + const tmpDir = await mkdtempForTest('agent-device-xctrace-stop-analysis-'); + const tracePath = path.join(tmpDir, 'app.trace'); + await fs.writeFile(tracePath, 'trace', 'utf8'); + mockHostCommands([ + async (_cmd, args) => { + if (args[0] !== 'xctrace' || args[1] !== 'export') return null; + const xpath = args[args.indexOf('--xpath') + 1] ?? ''; + const xml = args.includes('--toc') + ? tocXml + : xpath.includes('time-profile') + ? timeProfileXml + : undefined; + if (xml === undefined) return { stdout: '', stderr: 'no such table', exitCode: 1 }; + await fs.writeFile(readOutputPath(args), xml, 'utf8'); + return emptyRunResult(); + }, + ]); + + try { + const result = await stopAppleXctracePerfCapture(traceCapture(tracePath)); + assert.ok(result.summary, 'trace-mode stop must attach the analysis summary'); + assert.equal(result.summary.available, true); + if (!result.summary.available) return; + const busyHang = result.summary.hangs.find((hang) => hang.durationMs > 1_000); + assert.ok(busyHang, 'the exported time-profile table must reach the analyzer'); + assert.equal(busyHang.source, 'time-profile'); + assert.ok(busyHang.topSymbol); + assert.ok(result.summary.hotspots.length > 0); + } finally { + await fs.rm(tmpDir, { recursive: true, force: true }); + } +}); + +test('stopAppleXctracePerfCapture reports a typed unavailable summary when table exports fail', async () => { + const tmpDir = await mkdtempForTest('agent-device-xctrace-stop-analysis-fail-'); + const tracePath = path.join(tmpDir, 'app.trace'); + await fs.writeFile(tracePath, 'trace', 'utf8'); + mockHostCommands([ + async (_cmd, args) => { + if (args[0] !== 'xctrace' || args[1] !== 'export') return null; + if (args.includes('--toc')) { + await fs.writeFile(readOutputPath(args), tocXml, 'utf8'); + return emptyRunResult(); + } + return { stdout: '', stderr: 'table export failed', exitCode: 1 }; + }, + ]); + + try { + const result = await stopAppleXctracePerfCapture(traceCapture(tracePath)); + assert.ok(result.summary); + assert.equal(result.summary.available, false); + if (result.summary.available) return; + // The TOC lists time-profile, so the failure is an export failure, not a + // missing table: the agent must not be sent to re-record with the same template. + assert.equal(result.summary.reason, 'table-export-failed'); + assert.ok(result.summary.tableSchemas.includes('time-profile')); + assert.ok(!/template/i.test(result.summary.hint)); + } finally { + await fs.rm(tmpDir, { recursive: true, force: true }); + } +}); + +test('analyzeAppleXctraceTrace abandons analysis when the stop budget is exhausted', async () => { + // The stop path derives the budget from its static cap minus the stop wait + // already spent; with nothing left, analysis must not run any host command. + const result = await analyzeAppleXctraceTrace({ + tracePath: '/tmp/app.trace', + targetProcesses: ['HangApp'], + targetPids: [1], + budgetMs: 0, + }); + assert.equal(result.available, false); + if (result.available) return; + assert.equal(result.reason, 'analysis-timeout'); + assert.equal(vi.mocked(runCmd).mock.calls.length, 0); +}); + +test('stopAppleXctracePerfCapture shrinks the analysis budget by the stop wait spent', async () => { + // The budget is the static cap minus the time between stop entry and analysis + // start. A stop wait that consumed 41s of the 40s cap leaves nothing, so the + // summary is the typed analysis-timeout and no export command runs. + const tmpDir = await mkdtempForTest('agent-device-xctrace-stop-budget-'); + const tracePath = path.join(tmpDir, 'app.trace'); + await fs.writeFile(tracePath, 'trace', 'utf8'); + const nowSpy = vi.spyOn(Date, 'now'); + const startedMs = nowSpy(); + let enteredAnalysis = false; + mockHostCommands([ + async (_cmd, args) => { + if (args[0] !== 'xctrace' || args[1] !== 'export') return null; + enteredAnalysis = true; + return { stdout: '', stderr: '', exitCode: 1 }; + }, + ]); + // stopAppleXctracePerfCapture reads Date.now() at entry, derives the budget + // before analysis, and the export pass reads it again per export. Return the + // entry time first, then a clock 41s ahead for every later read. + let nowCalls = 0; + nowSpy.mockImplementation(() => (++nowCalls === 1 ? startedMs : startedMs + 41_000)); + + try { + const result = await stopAppleXctracePerfCapture(traceCapture(tracePath)); + assert.ok(result.summary); + assert.equal(result.summary.available, false); + if (result.summary.available) return; + assert.equal(result.summary.reason, 'analysis-timeout'); + assert.equal( + enteredAnalysis, + false, + 'an exhausted stop-path budget must not spawn a single export', + ); + } finally { + nowSpy.mockRestore(); + await fs.rm(tmpDir, { recursive: true, force: true }); + } +}); diff --git a/packages/platform-apple/src/core/__tests__/perf.test.ts b/packages/platform-apple/src/core/__tests__/perf.test.ts index 0012fca1e2..eb7871de05 100644 --- a/packages/platform-apple/src/core/__tests__/perf.test.ts +++ b/packages/platform-apple/src/core/__tests__/perf.test.ts @@ -557,6 +557,7 @@ test('stopAppleXctracePerfCapture returns compact artifact metadata', async () = assert.equal(result.outPath, tracePath); assert.deepEqual(result.targetPids, [111]); assert.equal(result.template, 'Time Profiler'); + assert.equal(result.summary, undefined, 'cpu-profile stop must not run trace analysis'); } finally { await fs.rm(tmpDir, { recursive: true, force: true }); } diff --git a/packages/platform-apple/src/core/perf-frame.ts b/packages/platform-apple/src/core/perf-frame.ts index ce2914af79..1129364ecd 100644 --- a/packages/platform-apple/src/core/perf-frame.ts +++ b/packages/platform-apple/src/core/perf-frame.ts @@ -41,7 +41,7 @@ export type AppleFramePerfSample = { worstWindows?: AppleFrameDropWindow[]; }; -type AppleFrameHitchRow = { +export type AppleFrameHitchRow = { startNs: number; durationNs: number; pid?: number; @@ -118,7 +118,7 @@ function parseAppleDisplayRefreshRate(xml: string | undefined): number | undefin return undefined; } -function parseAppleHitchRows(xml: string): AppleFrameHitchRow[] { +export function parseAppleHitchRows(xml: string): AppleFrameHitchRow[] { const document = parseXmlDocumentSync(xml); const indexes = readAppleHitchSchemaIndexes(document); if (!indexes) return []; diff --git a/packages/platform-apple/src/core/perf-trace-analysis.ts b/packages/platform-apple/src/core/perf-trace-analysis.ts new file mode 100644 index 0000000000..82183e08a9 --- /dev/null +++ b/packages/platform-apple/src/core/perf-trace-analysis.ts @@ -0,0 +1,423 @@ +import { uniqueStrings } from '@agent-device/kernel/collections'; +import { parseXmlDocumentSync, type XmlNode } from '@agent-device/xml'; +import { + findAllXmlNodes, + indexXmlNodesById, + rememberXmlReferences, + resolveXmlNumber, + resolveXmlReference, + type XmlReference, +} from './perf-xml.ts'; +import { + perfHangNextSteps, + perfHitchNextSteps, + type PerfHang, + type PerfHangCause, + type PerfTraceAnalysis, + type PerfTraceAnalysisUnavailable, + type PerfTraceHitches, + type PerfTraceHotspot, +} from '@agent-device/contracts/perf-hang-next-steps'; +import { parseAppleHitchRows } from './perf-frame.ts'; + +// Mirrors the Time Profiler "Hangs" instrument default hangsThreshold (ms). +const APPLE_HANG_THRESHOLD_MS = 250; + +export type AppleTraceHang = Omit & { + source: 'time-profile'; +}; + +export type AppleTraceHotspot = PerfTraceHotspot; + +export type AppleTraceUnavailableReason = + | 'no-time-profile-table' + | 'no-process-samples' + | 'toc-export-failed' + | 'table-export-failed' + | 'analysis-timeout' + | 'analysis-failed'; + +export type AppleTraceAnalysis = Extract< + PerfTraceAnalysis, + { available: true } +>; + +export type AppleTraceAnalysisUnavailable = + PerfTraceAnalysisUnavailable & + Readonly<{ + /** Schemas the trace TOC listed, so an agent can tell absent from unexportable. */ + tableSchemas: string[]; + }>; + +export type AppleTraceAnalysisResult = AppleTraceAnalysis | AppleTraceAnalysisUnavailable; + +export type AppleTraceAnalysisTable = 'time-profile' | 'hang-risks' | 'hitches'; + +export type AppleTraceAnalysisTarget = { + tracePath: string; + targetProcesses: string[]; + targetPids: number[]; +}; + +export function readAppleTraceTableSchemas(tocXml: string): string[] { + return uniqueStrings( + findAllXmlNodes(parseXmlDocumentSync(tocXml), (node) => node.name === 'table') + .map((node) => node.attributes.schema) + .filter((schema): schema is string => typeof schema === 'string' && schema.length > 0), + ).sort(); +} + +export function analyzeAppleTraceTables(params: { + target: AppleTraceAnalysisTarget; + tocXml: string; + timeProfileXml?: string; + hangRisksXml?: string; + hitchesXml?: string; + /** TOC-listed tables whose xctrace export failed (for example hit the export timeout). */ + failedTables?: string[]; +}): AppleTraceAnalysisResult { + const { target } = params; + const tableSchemas = readAppleTraceTableSchemas(params.tocXml); + const failedTables = new Set(params.failedTables ?? []); + if (!params.timeProfileXml) { + if (failedTables.has('time-profile')) { + return { + available: false, + reason: 'table-export-failed', + message: + 'The trace lists a time-profile table, but exporting it failed, so hangs and hotspots are not attributable.', + hint: `The trace was recorded with the needed tables already; retry perf trace stop, or open ${target.tracePath} in Instruments if the export keeps failing.`, + tableSchemas, + }; + } + return { + available: false, + reason: 'no-time-profile-table', + message: + 'The Apple trace contains no time-profile table, so hangs and hotspots are not attributable.', + hint: `Record with --template "Time Profiler" for hang and hotspot evidence, or open ${target.tracePath} in Instruments for the raw tables.`, + tableSchemas, + }; + } + const samples = parseAppleTraceSamples(params.timeProfileXml, target); + if (samples.length === 0) { + return { + available: false, + reason: 'no-process-samples', + message: + 'The Apple trace time-profile table contains no samples for the session app process.', + hint: `Keep the app active while recording, then retry. Open ${target.tracePath} in Instruments to inspect the raw trace.`, + tableSchemas, + }; + } + // potential-hangs is parsed only once a physical-device capture provides a real + // fixture; this environment (iOS simulators, Xcode 27.1) exports it with zero rows. + const hangs = deriveAppleHangsFromSamples(samples); + const hitches = analyzeAppleHitches(params.hitchesXml, target); + return { + available: true, + tracePath: target.tracePath, + hangs, + hangCount: hangs.length, + hitches, + hotspots: rankAppleHotspots(samples).slice(0, APPLE_TRACE_HOTSPOT_LIMIT), + notes: buildAppleTraceNotes(hangs.length, params.hangRisksXml), + }; +} + +const APPLE_TRACE_HOTSPOT_LIMIT = 20; + +type AppleTraceSample = { + timeNs: number; + weightNs: number; + threadId: string; + threadName: string; + isMainThread: boolean; + running: boolean; + symbol: string; + binary?: string; +}; + +function parseAppleTraceSamples( + xml: string, + target: { targetProcesses: string[]; targetPids: number[] }, +): AppleTraceSample[] { + const nodes = parseXmlDocumentSync(xml); + const nodesById = indexXmlNodesById(nodes); + const references = new Map(); + for (const node of nodes) { + rememberXmlReferences([node], references); + } + const samples: AppleTraceSample[] = []; + for (const row of findAllXmlNodes(nodes, (node) => node.name === 'row')) { + const sample = readAppleTraceSample(row, nodesById, references, target); + if (sample) samples.push(sample); + } + samples.sort((left, right) => left.timeNs - right.timeNs); + return samples; +} + +function readAppleTraceSample( + row: XmlNode, + nodesById: Map, + references: Map, + target: { targetProcesses: string[]; targetPids: number[] }, +): AppleTraceSample | undefined { + const timeNs = resolveXmlNumber( + row.children.find((node) => node.name === 'sample-time' || node.name === 'time'), + references, + ); + const weightNs = resolveXmlNumber( + row.children.find((node) => node.name === 'weight'), + references, + ); + if (timeNs === null || weightNs === null || weightNs <= 0) return undefined; + const threadCell = resolveXmlReference( + row.children.find((node) => node.name === 'thread'), + nodesById, + ); + const processCell = resolveXmlReference( + threadCell?.children.find((node) => node.name === 'process'), + nodesById, + ); + if (!processCell) return undefined; + const pid = readAppleProcessPid(processCell, nodesById); + if (!matchesAppleTraceTarget(processCell.attributes.fmt ?? '', pid, target)) return undefined; + const stack = resolveXmlReference( + row.children.find((node) => node.name === 'backtrace' || node.name === 'tagged-backtrace'), + nodesById, + ); + const frame = stack + ? resolveXmlReference( + stack.children.find((node) => node.name === 'frame'), + nodesById, + ) + : undefined; + const binary = frame + ? resolveXmlReference( + frame.children.find((node) => node.name === 'binary'), + nodesById, + ) + : undefined; + const state = resolveXmlReference( + row.children.find((node) => node.name === 'thread-state'), + nodesById, + ); + const threadFmt = threadCell?.attributes.fmt ?? ''; + const threadId = threadCell?.attributes.id ?? threadCell?.attributes.ref ?? threadFmt; + return { + timeNs, + weightNs, + threadId, + threadName: appleThreadLabel(threadFmt), + isMainThread: isAppleMainThread(threadFmt), + running: (state?.text ?? state?.attributes.fmt ?? '').trim().toLowerCase() === 'running', + symbol: frame?.attributes.name?.trim() || '', + binary: binary?.attributes.name?.trim() || undefined, + }; +} + +// Instruments labels the main thread "Main Thread" (or the com.apple.main-thread +// queue) in the thread cell fmt. The tid is not the pid on Darwin, so the label is +// the identification. +function isAppleMainThread(threadFmt: string): boolean { + return /^(main thread|com\.apple\.main-thread)/i.test(threadFmt.trim()); +} + +function readAppleProcessPid(processCell: XmlNode, nodesById: Map): number { + const pidCell = resolveXmlReference( + processCell.children.find((node) => node.name === 'pid'), + nodesById, + ); + return Number( + pidCell?.text ?? processCell.attributes.fmt?.match(/\((\d+)\)$/)?.[1] ?? Number.NaN, + ); +} + +export function matchesAppleTraceTarget( + processFmt: string, + pid: number, + target: { targetProcesses: string[]; targetPids: number[] }, +): boolean { + if (target.targetPids.length > 0 && target.targetPids.includes(pid)) return true; + const processName = processFmt.replace(/\s*\(\d+\)\s*$/, '').trim(); + if (processName.length === 0) return false; + return target.targetProcesses.some( + (candidate) => + processName === candidate || + processName.endsWith(`.${candidate}`) || + (candidate.includes('.') && processName === candidate.split('.').pop()), + ); +} + +function appleThreadLabel(threadFmt: string): string { + const match = threadFmt.match(/^(.*?)\s+\(0x[0-9a-fA-F]+\)\s/); + return (match?.[1] ?? threadFmt).trim() || ''; +} + +function topWeightedSymbol(weights: Map): string | undefined { + let best: string | undefined; + let bestWeight = 0; + for (const [symbol, weight] of weights) { + if (weight > bestWeight) { + best = symbol; + bestWeight = weight; + } + } + return best; +} + +type DerivedAppleHangRun = { + threadId: string; + threadName: string; + startNs: number; + endNs: number; + runningNs: number; + blockedNs: number; + /** End of the time already attributed to this run; keeps overlapping sample weights from double-counting. */ + coveredNs: number; + /** Running weight per symbol, accumulated only from the samples that formed this run. */ + symbolWeightsNs: Map; +}; + +// Merges contiguous main-thread samples into frozen windows. Contiguity uses each +// sample's own weight as the sampling period, so sparse traces bridge and idle or +// sleep gaps (where the main thread has no on-CPU samples) stay split. The running +// and blocked split and the top symbol accumulate per run from exactly the samples +// that formed it, counting only each sample's uncovered exposure, so a hang never +// claims neighbouring work and its running+blocked total never exceeds its span. +function deriveAppleHangsFromSamples(samples: AppleTraceSample[]): AppleTraceHang[] { + const main = samples.filter((sample) => sample.isMainThread); + if (main.length === 0) return []; + const runs: DerivedAppleHangRun[] = []; + for (const sample of main) { + const gapNs = sample.weightNs * 4; + const previous = runs.at(-1); + if ( + previous && + previous.threadId === sample.threadId && + sample.timeNs - previous.endNs <= gapNs + ) { + // Sample ends must never move the run end backwards; a non-monotonic sample + // keeps running+blocked inside the run duration. + previous.endNs = Math.max(previous.endNs, sample.timeNs + sample.weightNs); + } else { + runs.push({ + threadId: sample.threadId, + threadName: sample.threadName, + startNs: sample.timeNs, + endNs: sample.timeNs + sample.weightNs, + runningNs: 0, + blockedNs: 0, + coveredNs: sample.timeNs, + symbolWeightsNs: new Map(), + }); + } + const run = runs.at(-1)!; + const sampleEndNs = sample.timeNs + sample.weightNs; + const exposureNs = Math.max(0, sampleEndNs - run.coveredNs); + run.coveredNs = Math.max(run.coveredNs, sampleEndNs); + if (sample.running) { + run.runningNs += exposureNs; + run.symbolWeightsNs.set( + sample.symbol, + (run.symbolWeightsNs.get(sample.symbol) ?? 0) + exposureNs, + ); + } else { + run.blockedNs += exposureNs; + } + } + return runs + .filter((run) => run.endNs - run.startNs >= APPLE_HANG_THRESHOLD_MS * 1_000_000) + .map((run) => { + const cause: PerfHangCause = { + runningMs: roundMs(run.runningNs / 1_000_000), + blockedMs: roundMs(run.blockedNs / 1_000_000), + topSymbol: topWeightedSymbol(run.symbolWeightsNs), + threadName: run.threadName, + }; + return { + startOffsetMs: roundMs(run.startNs / 1_000_000), + durationMs: roundMs((run.endNs - run.startNs) / 1_000_000), + thread: run.threadName, + topSymbol: cause.topSymbol, + runningMs: cause.runningMs, + blockedMs: cause.blockedMs, + source: 'time-profile' as const, + nextSteps: perfHangNextSteps(cause), + }; + }) + .sort((left, right) => right.durationMs - left.durationMs); +} + +function analyzeAppleHitches( + xml: string | undefined, + target: AppleTraceAnalysisTarget, +): PerfTraceHitches | undefined { + if (!xml) return undefined; + // The hitches table also carries other processes' rows; only the attached app's + // rows count. parseAppleHitchRows drops system rows and resolves the cells; + // matchesAppleTraceTarget accepts pid, exact process name, and bundle-id shaped + // targets, so it covers every row the perf-frame pid-or-name filter accepts. + const rows = parseAppleHitchRows(xml).filter((row) => + matchesAppleTraceTarget(row.processName ?? '', row.pid ?? Number.NaN, target), + ); + let maxDurationMs: number | undefined; + for (const row of rows) { + maxDurationMs = Math.max(maxDurationMs ?? 0, roundMs(row.durationNs / 1_000_000)); + } + return { + available: true, + count: rows.length, + maxDurationMs: rows.length > 0 ? maxDurationMs : undefined, + nextSteps: rows.length > 0 ? perfHitchNextSteps() : [], + }; +} + +function rankAppleHotspots(samples: AppleTraceSample[]): AppleTraceHotspot[] { + const weights = new Map(); + for (const sample of samples) { + const key = `${sample.binary ?? ''}\u0000${sample.symbol}`; + const previous = weights.get(key); + weights.set(key, { + symbol: sample.symbol, + binary: sample.binary, + weightNs: (previous?.weightNs ?? 0) + sample.weightNs, + }); + } + return [...weights.values()] + .sort( + (left, right) => right.weightNs - left.weightNs || left.symbol.localeCompare(right.symbol), + ) + .map(({ symbol, binary, weightNs }) => ({ + symbol, + binary, + selfSampleMs: roundMs(weightNs / 1_000_000), + })); +} + +function buildAppleTraceNotes( + derivedHangCount: number, + hangRisksXml: string | undefined, +): string[] { + const notes: string[] = []; + if (derivedHangCount > 0) { + notes.push( + 'hangs were derived from contiguous Time Profiler samples on the main thread; Instruments does not fill potential-hangs on simulated devices.', + ); + } + if (hangRisksXml && countAppleRows(hangRisksXml) > 0) { + notes.push( + 'hang-risks rows are advisory; the derived main-thread hangs are the primary evidence.', + ); + } + return notes; +} + +function countAppleRows(xml: string): number { + return findAllXmlNodes(parseXmlDocumentSync(xml), (node) => node.name === 'row').length; +} + +function roundMs(value: number): number { + return Math.round(value * 10) / 10; +} diff --git a/packages/platform-apple/src/core/perf-xctrace.ts b/packages/platform-apple/src/core/perf-xctrace.ts index 03fc3f0d9d..9af519a462 100644 --- a/packages/platform-apple/src/core/perf-xctrace.ts +++ b/packages/platform-apple/src/core/perf-xctrace.ts @@ -33,6 +33,9 @@ import { parseAppleTimeProfileSummary, type AppleTimeProfileFunction, } from './perf-time-profile.ts'; +import type { AppleTraceAnalysisResult, AppleTraceAnalysisTable } from './perf-trace-analysis.ts'; + +export type { AppleTraceAnalysisResult } from './perf-trace-analysis.ts'; import { IOS_DEVICECTL_DEFAULT_HINT, resolveIosDevicectlHint } from './devicectl.ts'; import { runXcrun } from './tool-provider.ts'; @@ -86,6 +89,8 @@ export type AppleXctracePerfResult = { targetProcesses: string[]; startedAt: string; endedAt: string; + /** Interpreted hang/hitch/hotspot evidence; present for stopped trace-mode captures. */ + summary?: AppleTraceAnalysisResult; }; export type AppleXctraceCpuProfileReport = { @@ -155,6 +160,7 @@ export async function stopAppleXctracePerfCapture( capture: AppleXctracePerfCapture, outPath = capture.outPath, ): Promise { + const stopStartedAtMs = Date.now(); if (outPath !== capture.outPath) { await ensureHostDirectory(path.dirname(outPath)); } @@ -193,6 +199,15 @@ export async function stopAppleXctracePerfCapture( targetProcesses: capture.targetProcesses, startedAt: capture.startedAt, endedAt: new Date().toISOString(), + summary: + capture.mode === 'trace' + ? await analyzeAppleXctraceTrace({ + tracePath: outPath, + targetProcesses: capture.targetProcesses, + targetPids: capture.targetPids, + budgetMs: remainingAppleTraceAnalysisBudgetMs(stopStartedAtMs), + }) + : undefined, }; } @@ -246,6 +261,192 @@ export async function writeAppleXctracePerfReport(params: { } } +/** + * Reads the hang, hitch, and Time Profiler tables present in an xctrace file and + * returns bounded agent-readable evidence. Exported tables follow the TOC, so a + * template without a table (for example Time Profiler without `hitches`) skips that + * table instead of failing the export. Best-effort by contract: this interprets a + * finished capture and never fails the capture itself. + */ +export async function analyzeAppleXctraceTrace(params: { + tracePath: string; + targetProcesses: string[]; + targetPids: number[]; + /** + * Remaining budget for the whole export-and-interpret pass, derived by the stop + * path from its static cap (APPLE_TRACE_ANALYSIS_DEADLINE_MS) minus the stop + * time already consumed. Defaults to the full cap; never exceeds it. + */ + budgetMs?: number; +}): Promise { + // One overall deadline bounds the whole export-and-interpret pass, so a slow + // xctrace export cannot eat the stop request's whole envelope. + const budgetMs = Math.min( + params.budgetMs ?? APPLE_TRACE_ANALYSIS_DEADLINE_MS, + APPLE_TRACE_ANALYSIS_DEADLINE_MS, + ); + if (budgetMs <= 0) { + return analyzeTraceTimeout(params.tracePath); + } + let deadlineTimer: ReturnType | undefined; + const deadline = new Promise((resolve) => { + deadlineTimer = setTimeout(() => resolve(analyzeTraceTimeout(params.tracePath)), budgetMs); + deadlineTimer.unref?.(); + }); + try { + return await Promise.race([ + runAppleTraceAnalysis({ ...params, exportBudgetMs: budgetMs }), + deadline, + ]); + } catch (error) { + return { + available: false, + reason: 'analysis-failed', + message: `Trace analysis failed: ${error instanceof Error ? error.message : String(error)}`, + hint: `Open ${params.tracePath} in Instruments to inspect the raw trace, then retry perf trace stop.`, + tableSchemas: [], + }; + } finally { + clearTimeout(deadlineTimer); + } +} + +function analyzeTraceTimeout(tracePath: string): AppleTraceAnalysisResult { + return { + available: false, + reason: 'analysis-timeout', + message: 'Trace analysis exceeded its overall deadline and was abandoned.', + hint: `Open ${tracePath} in Instruments to inspect the raw trace, or retry perf trace stop on a shorter capture.`, + tableSchemas: [], + }; +} + +// A static cap tied to the stop path's own waits: sizing the analysis pass at the +// graceful stop wait minus the force-kill window keeps worst-case stop plus analysis +// inside the stop request's envelope without mirroring the daemon request timeout +// here (no real deadline reaches the perf runtime). +const APPLE_TRACE_ANALYSIS_DEADLINE_MS = + APPLE_XCTRACE_STOP_GRACE_TIMEOUT_MS - APPLE_XCTRACE_STOP_FORCE_TIMEOUT_MS; + +// The static cap shrinks by the stop wait already spent, so a stop that consumed +// the full grace plus force-kill window leaves no analysis budget and the pass is +// abandoned before spawning any export. +function remainingAppleTraceAnalysisBudgetMs(stopStartedAtMs: number): number { + return Math.max(0, APPLE_TRACE_ANALYSIS_DEADLINE_MS - (Date.now() - stopStartedAtMs)); +} + +async function runAppleTraceAnalysis(params: { + tracePath: string; + targetProcesses: string[]; + targetPids: number[]; + exportBudgetMs: number; +}): Promise { + // Every export shares this one deadline, so a slow export shrinks (and finally + // cancels by timeout) the following ones instead of stacking 15s timeouts. + const deadlineAtMs = Date.now() + params.exportBudgetMs; + const exportTimeoutMs = () => + Math.min(IOS_DEVICE_PERF_EXPORT_TIMEOUT_MS, deadlineAtMs - Date.now()); + const tempDir = await makeHostTemporaryDirectory('agent-device-xctrace-trace-report-'); + try { + const toc = await exportAppleXctraceOptionalData({ + tracePath: params.tracePath, + outPath: path.join(tempDir, 'trace-toc.xml'), + query: 'toc', + timeoutMs: exportTimeoutMs(), + }); + if (toc === undefined) { + return { + available: false, + reason: 'toc-export-failed', + message: 'Failed to export the Apple xctrace table of contents.', + hint: `Open ${params.tracePath} in Instruments to inspect the raw trace, then retry perf trace stop.`, + tableSchemas: [], + }; + } + // Loading the analyzer on demand keeps the contracts rule table out of the + // eager perf-facade closure; only trace-stop analysis pays for it. + const { analyzeAppleTraceTables, readAppleTraceTableSchemas } = + await import('./perf-trace-analysis.ts'); + const tableSchemas = readAppleTraceTableSchemas(toc); + const exported = await exportAppleTraceTablesPresent( + params.tracePath, + tempDir, + tableSchemas, + exportTimeoutMs, + ); + return analyzeAppleTraceTables({ + target: { + tracePath: params.tracePath, + targetProcesses: params.targetProcesses, + targetPids: params.targetPids, + }, + tocXml: toc, + timeProfileXml: exported.tables['time-profile'], + hangRisksXml: exported.tables['hang-risks'], + hitchesXml: exported.tables.hitches, + failedTables: exported.failedTables, + }); + } finally { + await removeHostPath(tempDir).catch(() => {}); + } +} + +const APPLE_TRACE_ANALYSIS_TABLES = [ + 'time-profile', + 'hang-risks', + 'hitches', +] as const satisfies readonly AppleTraceAnalysisTable[]; + +async function exportAppleTraceTablesPresent( + tracePath: string, + tempDir: string, + tableSchemas: string[], + timeoutMs: () => number, +): Promise<{ + tables: Partial>; + failedTables: string[]; +}> { + const present = new Set(tableSchemas); + const tables: Partial> = {}; + const failedTables: string[] = []; + for (const table of APPLE_TRACE_ANALYSIS_TABLES) { + if (!present.has(table)) continue; + const remainingMs = timeoutMs(); + if (remainingMs <= 0) { + // The shared deadline has passed: stop spawning exports. The caller's + // overall deadline resolves the pass as analysis-timeout. + failedTables.push(table); + continue; + } + const xml = await exportAppleXctraceOptionalData({ + tracePath, + outPath: path.join(tempDir, `${table}.xml`), + query: { schema: table }, + timeoutMs: remainingMs, + }); + if (xml !== undefined) tables[table] = xml; + else failedTables.push(table); + } + return { tables, failedTables }; +} + +async function exportAppleXctraceOptionalData(params: { + tracePath: string; + outPath: string; + query: 'toc' | { schema: string }; + timeoutMs: number; +}): Promise { + try { + return await exportAppleXctraceData({ + ...params, + failureMessage: `Failed to export Apple xctrace ${params.query === 'toc' ? 'metadata' : params.query.schema} data`, + failureDetails: { tracePath: params.tracePath }, + }); + } catch { + return undefined; + } +} + export async function recordAppleXctraceTimedTrace(params: { device: DeviceInfo; appBundleId: string; @@ -305,6 +506,8 @@ export async function exportAppleXctraceData(params: { query: 'toc' | { schema: string }; failureMessage: string; failureDetails: Record; + /** Per-export timeout; the trace-analysis pass shrinks it under its own budget. */ + timeoutMs?: number; }): Promise { const exportArgs: ['xctrace', ...string[]] = [ 'xctrace', @@ -320,7 +523,7 @@ export async function exportAppleXctraceData(params: { requireExecSuccess( await runXcrun(exportArgs, { allowFailure: true, - timeoutMs: IOS_DEVICE_PERF_EXPORT_TIMEOUT_MS, + timeoutMs: params.timeoutMs ?? IOS_DEVICE_PERF_EXPORT_TIMEOUT_MS, }), params.failureMessage, (exportResult) => ({ diff --git a/packages/platform-apple/src/perf-facade.ts b/packages/platform-apple/src/perf-facade.ts index 5f29dc1adb..b02b4d06e5 100644 --- a/packages/platform-apple/src/perf-facade.ts +++ b/packages/platform-apple/src/perf-facade.ts @@ -7,12 +7,14 @@ export { sampleAppleMemoryPerf, } from './core/perf.ts'; export { + analyzeAppleXctraceTrace, cleanupAppleXctracePerfCapture, isRetryableIosDeviceTraceRecordFailure, resolveIosDevicePerfHint, startAppleXctracePerfCapture, stopAppleXctracePerfCapture, writeAppleXctracePerfReport, + type AppleTraceAnalysisResult, type AppleXctraceCpuProfileReport, type AppleXctracePerfCapture, type AppleXctracePerfMode, diff --git a/scripts/layering/contracts-exports.snapshot.json b/scripts/layering/contracts-exports.snapshot.json index da53c0a0c3..1fa2b9e066 100644 --- a/scripts/layering/contracts-exports.snapshot.json +++ b/scripts/layering/contracts-exports.snapshot.json @@ -81,6 +81,7 @@ "@agent-device/contracts/network-traffic", "@agent-device/contracts/observability", "@agent-device/contracts/orientation-runtime", + "@agent-device/contracts/perf-hang-next-steps", "@agent-device/contracts/perf-runtime", "@agent-device/contracts/perf-runtime-host", "@agent-device/contracts/perf-runtime-operation-builder", diff --git a/src/commands/perf/output.test.ts b/src/commands/perf/output.test.ts new file mode 100644 index 0000000000..008770b37c --- /dev/null +++ b/src/commands/perf/output.test.ts @@ -0,0 +1,47 @@ +import { test } from 'vitest'; +import assert from 'node:assert/strict'; +import { perfCliOutputFormatters } from './output.ts'; + +function format(data: Record): string { + const output = perfCliOutputFormatters.perf({ + result: { ok: true, ...data } as never, + } as never); + return output.text ?? ''; +} + +const APPLE_HANG = { + startOffsetMs: 2_111, + durationMs: 3_999, + thread: 'Main Thread', + topSymbol: 'HangViewController.blockMainThread(seconds:)', + runningMs: 3_900, + blockedMs: 99, + source: 'time-profile', + nextSteps: ['Inspect HangViewController.blockMainThread(seconds:) on the main thread.'], +}; + +test('Apple trace stop output lists hangs, hotspots, and next steps', () => { + const text = format({ + kind: 'xctrace', + mode: 'trace', + perf: 'stopped', + template: 'Time Profiler', + outPath: '/tmp/app.trace', + summary: { + available: true, + hangs: [APPLE_HANG], + hangCount: 1, + hitches: { available: true, count: 2, nextSteps: [] }, + hotspots: [{ symbol: 'swift_getTupleTypeMetadata', selfSampleMs: 1_250 }], + notes: [], + }, + }); + assert.match(text, /Perf trace: stopped/); + assert.match( + text, + /Hangs \(1\):\n- \+2s 4s Main Thread - HangViewController\.blockMainThread\(seconds:\) - running 4s \/ blocked 99ms/, + ); + assert.match(text, /Hitches: 2 animation hitches/); + assert.match(text, /Hotspots:\n- 1s swift_getTupleTypeMetadata/); + assert.match(text, /Next steps:\n- Inspect HangViewController/); +}); diff --git a/src/commands/perf/output.ts b/src/commands/perf/output.ts index 9ec488cd90..711d1eef33 100644 --- a/src/commands/perf/output.ts +++ b/src/commands/perf/output.ts @@ -1,4 +1,5 @@ import type { CommandRequestResult } from '@agent-device/contracts/client'; +import { uniqueStrings } from '@agent-device/kernel/collections'; import { isRecord } from '@agent-device/kernel/record'; import type { CliOutput } from '../command-contract.ts'; import { resultOutput, type CliOutputFormatter } from '../output-common.ts'; @@ -93,12 +94,15 @@ function formatAppleNativePerfOutput(data: Record): string | un const mode = typeof data.mode === 'string' ? data.mode : 'capture'; const lines = formatNativePerfLines(outPath, mode, state, data.template); const topFunctions = formatNativeTopFunctions(data); - return topFunctions.length > 0 - ? `${lines}\nTop CPU self time:\n${topFunctions.join('\n')}` - : lines; + const analysis = formatTraceAnalysisOutput(data); + const sections = [lines]; + if (topFunctions.length > 0) sections.push(`Top CPU self time:\n${topFunctions.join('\n')}`); + if (analysis) sections.push(analysis); + return sections.join('\n'); } const PERF_CLI_TOP_FUNCTION_LIMIT = 5; +const PERF_CLI_TRACE_ANALYSIS_LIMIT = 5; function formatNativeTopFunctions(data: Record): string[] { const summary = isRecord(data.summary) ? data.summary : undefined; @@ -113,6 +117,97 @@ function formatNativeTopFunctions(data: Record): string[] { }); } +function formatTraceAnalysisOutput(data: Record): string | undefined { + const hangs = readTraceHangs(data); + const summary = isRecord(data.summary) ? data.summary : undefined; + const sections: string[] = []; + const hangSection = formatTraceHangSection(hangs); + if (hangSection) sections.push(hangSection); + if (data.kind === 'xctrace' && isRecord(summary)) { + sections.push(...formatAppleTraceSections(summary)); + } + const nextSteps = uniqueStrings( + hangs + .slice(0, PERF_CLI_TRACE_ANALYSIS_LIMIT) + .flatMap((hang) => readStringArray(hang.nextSteps)), + ); + if (nextSteps.length > 0) { + sections.push(`Next steps:\n${nextSteps.map((step) => `- ${step}`).join('\n')}`); + } + if (sections.length > 0) return sections.join('\n'); + return formatTraceAnalysisUnavailable(summary); +} + +function formatTraceHangSection(hangs: Array>): string | undefined { + if (hangs.length === 0) return undefined; + const shown = hangs.slice(0, PERF_CLI_TRACE_ANALYSIS_LIMIT); + const lines = shown.map((hang) => formatTraceHangLine(hang)); + const overflow = hangs.length - shown.length; + if (overflow > 0) lines.push(`- and ${overflow} more, see the JSON summary`); + return `Hangs (${hangs.length}):\n${lines.join('\n')}`; +} + +function formatTraceAnalysisUnavailable( + summary: Record | undefined, +): string | undefined { + if (!isRecord(summary) || summary.available !== false) return undefined; + const message = readString(summary.message); + if (!message) return undefined; + return `Trace analysis: unavailable - ${readString(summary.reason) ?? message}`; +} + +function formatAppleTraceSections(summary: Record): string[] { + const sections: string[] = []; + if (isRecord(summary.hitches) && summary.hitches.available === true) { + const count = readFiniteNumber(summary.hitches.count); + if (count !== undefined && count > 0) { + sections.push(`Hitches: ${Math.round(count)} animation hitch${count === 1 ? '' : 'es'}`); + } + } + if (Array.isArray(summary.hotspots)) { + const hotspots = summary.hotspots.slice(0, PERF_CLI_TRACE_ANALYSIS_LIMIT).flatMap((entry) => { + if (!isRecord(entry)) return []; + const symbol = readString(entry.symbol); + const selfSampleMs = readFiniteNumber(entry.selfSampleMs); + if (!symbol || selfSampleMs === undefined) return []; + return [`- ${formatDurationMs(selfSampleMs)} ${symbol}`]; + }); + if (hotspots.length > 0) sections.push(`Hotspots:\n${hotspots.join('\n')}`); + } + return sections; +} + +function readTraceHangs(data: Record): Array> { + const summary = isRecord(data.summary) ? data.summary : undefined; + if (!Array.isArray(summary?.hangs)) return []; + return summary.hangs.filter(isRecord).flatMap((hang) => { + const startOffsetMs = readFiniteNumber(hang.startOffsetMs); + const durationMs = readFiniteNumber(hang.durationMs); + return startOffsetMs === undefined || durationMs === undefined ? [] : [hang]; + }); +} + +function formatTraceHangLine(hang: Record): string { + const startOffsetMs = readFiniteNumber(hang.startOffsetMs) ?? 0; + const durationMs = readFiniteNumber(hang.durationMs) ?? 0; + const thread = readString(hang.thread) ?? 'main'; + const topSymbol = readString(hang.topSymbol); + const runningMs = readFiniteNumber(hang.runningMs); + const blockedMs = readFiniteNumber(hang.blockedMs); + const parts = [`+${formatDurationMs(startOffsetMs)} ${formatDurationMs(durationMs)} ${thread}`]; + if (topSymbol) parts.push(topSymbol); + if (runningMs !== undefined && blockedMs !== undefined) { + parts.push(`running ${formatDurationMs(runningMs)} / blocked ${formatDurationMs(blockedMs)}`); + } + return `- ${parts.join(' - ')}`; +} + +function readStringArray(value: unknown): string[] { + return Array.isArray(value) + ? value.filter((item): item is string => typeof item === 'string') + : []; +} + function readNativePerfArtifactPath(data: Record): string | undefined { if (typeof data.outPath === 'string') return data.outPath; return typeof data.reportPath === 'string' ? data.reportPath : undefined; @@ -135,10 +230,12 @@ function formatAndroidNativePerfOutput(data: Record): string | const lines = `Perf ${summary.action}: ${summary.kind} ${summary.type}${formatNativePerfState( data, )}${formatNativePerfArtifact(data)}${formatNativePerfFrameHealth(data)}`; + const sections = [lines]; const topFunctions = formatNativeTopFunctions(data); - return topFunctions.length > 0 - ? `${lines}\nTop CPU self time:\n${topFunctions.join('\n')}` - : lines; + if (topFunctions.length > 0) sections.push(`Top CPU self time:\n${topFunctions.join('\n')}`); + const analysis = formatTraceAnalysisOutput(data); + if (analysis) sections.push(analysis); + return sections.join('\n'); } function readNativePerfSummary( diff --git a/src/commands/schema/cli-help-workflows.ts b/src/commands/schema/cli-help-workflows.ts index a042727d3b..43b12c0cff 100644 --- a/src/commands/schema/cli-help-workflows.ts +++ b/src/commands/schema/cli-help-workflows.ts @@ -143,13 +143,14 @@ Diagnostics and traces: agent-device press 'id="load-diagnostics"' agent-device trace stop ./traces/diagnostics.trace The trace path is positional. Do not use --path for trace start or trace stop. - Use perf xctrace only for Apple native CPU/profile or Animation Hitches artifacts: + Use perf xctrace only for Apple native CPU/profile and hang artifacts: agent-device perf cpu profile start --kind xctrace --template "Time Profiler" --out ./artifacts/app.trace agent-device perf cpu profile stop --kind xctrace --out ./artifacts/app.trace agent-device perf cpu profile report --kind xctrace --out ./artifacts/app-profile.json - agent-device perf trace start --kind xctrace --template "Animation Hitches" --out ./artifacts/hitches.trace - agent-device perf trace stop --kind xctrace --out ./artifacts/hitches.trace + agent-device perf trace start --kind xctrace --out ./artifacts/app.trace + agent-device perf trace stop --kind xctrace --out ./artifacts/app.trace perf xctrace keeps the .trace artifact on disk; CPU report returns a bounded weighted top-function summary. Do not dump .trace contents into context. + perf trace stop interprets the finished trace and reports hangs, hitches, hotspots, and next steps in the stop summary. Pass --template "Animation Hitches" only when hitch tables are the goal. For Android native CPU/trace evidence, use perf artifacts instead of raw adb/simpleperf/perfetto output: agent-device perf cpu profile start --kind simpleperf --out /tmp/cpu.perf.data agent-device perf cpu profile stop --kind simpleperf diff --git a/src/platform-runtime-perf-capture-host.test.ts b/src/platform-runtime-perf-capture-host.test.ts index f87592ceef..c1135500b2 100644 --- a/src/platform-runtime-perf-capture-host.test.ts +++ b/src/platform-runtime-perf-capture-host.test.ts @@ -276,7 +276,7 @@ test('starts, retargets, stops, and reclaims an Apple xctrace capture through on expect(processHost.terminateManagedProcessSet).toHaveBeenCalledWith([appleMarker]); }); -test('derives the xctrace template from the capture mode', async () => { +test('defaults the xctrace template to Time Profiler for every capture mode', async () => { appleXctrace.startAppleXctracePerfCapture.mockResolvedValue( appleCapture({ mode: 'cpu-profile', template: 'Time Profiler' }), ); @@ -297,7 +297,7 @@ test('derives the xctrace template from the capture mode', async () => { captureInput({ kind: 'xctrace', mode: 'trace' }), ); expect(appleXctrace.startAppleXctracePerfCapture).toHaveBeenLastCalledWith( - expect.objectContaining({ template: 'Animation Hitches' }), + expect.objectContaining({ template: 'Time Profiler' }), ); }); diff --git a/src/platform-runtime-perf-capture-host.ts b/src/platform-runtime-perf-capture-host.ts index 0c1c360ec0..30019614f3 100644 --- a/src/platform-runtime-perf-capture-host.ts +++ b/src/platform-runtime-perf-capture-host.ts @@ -24,7 +24,10 @@ import type { AndroidNativePerfStartResult, AndroidNativePerfStopResult, } from '@agent-device/platform-android/mechanics'; -import type { AppleXctracePerfCapture } from '@agent-device/platform-apple/perf'; +import type { + AppleTraceAnalysisResult, + AppleXctracePerfCapture, +} from '@agent-device/platform-apple/perf'; import { inspectManagedProcess, resolveManagedProcessIdentity, @@ -59,8 +62,7 @@ export async function startApplePerfCapture( input: PerfNativeCaptureStartInput, ): Promise { if (input.kind !== 'xctrace') throw wrongNativeKind('Apple', 'xctrace', input.kind); - const template = - input.template ?? (input.mode === 'cpu-profile' ? 'Time Profiler' : 'Animation Hitches'); + const template = input.template ?? 'Time Profiler'; const apple = await loadAppleXctrace(); const capture = await apple.startAppleXctracePerfCapture({ device, @@ -277,7 +279,10 @@ function stripAppleCapture( function compactAppleCapture( state: 'started' | 'stopped', - result: Omit & { endedAt?: string }, + result: Omit & { + endedAt?: string; + summary?: AppleTraceAnalysisResult; + }, ): PerfNativeCaptureSnapshot { return { perf: state, @@ -292,6 +297,7 @@ function compactAppleCapture( targetProcesses: result.targetProcesses, startedAt: result.startedAt, endedAt: result.endedAt, + ...(result.summary === undefined ? {} : { summary: result.summary }), }; } diff --git a/website/docs/docs/commands.md b/website/docs/docs/commands.md index 86d34085c5..ab9040294f 100644 --- a/website/docs/docs/commands.md +++ b/website/docs/docs/commands.md @@ -893,8 +893,8 @@ agent-device cdp memory snapshot capture --name baseline --gc agent-device perf cpu profile start --kind xctrace --template "Time Profiler" --out app.trace agent-device perf cpu profile stop --kind xctrace --out app.trace agent-device perf cpu profile report --kind xctrace --out app-profile.json -agent-device perf trace start --kind xctrace --template "Animation Hitches" --out hitches.trace -agent-device perf trace stop --kind xctrace --out hitches.trace +agent-device perf trace start --kind xctrace --out app.trace +agent-device perf trace stop --kind xctrace --out app.trace agent-device perf cpu profile start --kind simpleperf --out cpu.perf.data agent-device perf cpu profile stop --kind simpleperf --out cpu.perf.data agent-device perf cpu profile report --kind simpleperf --out cpu-report.json @@ -905,6 +905,7 @@ agent-device perf trace stop --kind perfetto --out app.perfetto-trace - Name one area: `frames`, `memory`, `cpu`, or `trace`. Bare `perf`, `perf sample`, `perf metrics`, and the `metrics` alias fail with guidance to the focused replacements. - `perf frames` returns frame/jank health (`droppedFramePercent`, `worstWindows`). `perf memory sample` returns a compact process memory sample in kilobytes. `perf memory snapshot` writes a heap or memgraph artifact and returns its path. - `perf cpu profile` and `perf trace` record Apple (`--kind xctrace`) or Android (`--kind simpleperf`, `--kind perfetto`) profiles and traces, and return artifact paths plus compact metadata; raw contents stay on disk. +- `perf trace stop` interprets the capture: Apple reports hangs, hitches, and hotspots. Each hang carries bounded `nextSteps` guidance; the CLI text prints at most five entries per list and JSON carries the full list. `perf trace` records with the Time Profiler template by default, so hitch tables need `--template "Animation Hitches"`. - `cdp` samples and snapshots the React Native JavaScript heap through Metro CDP; see [Debugging & Profiling](/docs/debugging-profiling#react-native-js-memory-through-cdp). - App startup duration is returned in `open`'s `startup` result. - Perf commands need an app session with a package or bundle ID; run `open ` first. diff --git a/website/docs/docs/debugging-profiling.md b/website/docs/docs/debugging-profiling.md index ee1131cf1b..4c3f26c89e 100644 --- a/website/docs/docs/debugging-profiling.md +++ b/website/docs/docs/debugging-profiling.md @@ -265,6 +265,7 @@ agent-device perf trace stop --kind perfetto --out app.perfetto-trace - `perf memory snapshot` escalates to file artifacts. Android supports Java HPROF capture for active app processes when the build/device allows heap dumping. iOS simulator and macOS app sessions support memgraph capture. On physical iOS devices, memgraph capture reports unavailable with a hint. - Heap and memgraph artifacts are returned as paths plus compact metadata. Example default output: `Memory artifact (android-hprof): /tmp/app.hprof (42MB)`. They are not printed or embedded in JSON by default. Native allocation tracing (heapprofd) is not supported. - `perf cpu profile ... --kind xctrace` collects an Apple native `.trace`; `report` aggregates every run, returns at most ten weighted top functions in JSON, and prints five. `perf trace ... --kind xctrace` keeps trace data as an artifact. +- `perf trace stop` interprets the finished trace before it returns. Apple captures report hangs with start offset, duration, thread, and top symbol, plus hitches and hotspots. Each hang carries rule-based `nextSteps`. CLI text prints at most five entries per list; JSON carries the full list. - On iOS simulators and macOS, process sampling and captures target the resolved app executable. Other running copies with the same executable name are excluded, including copies installed on another simulator. - Android native profiling uses `perf cpu profile ... --kind simpleperf`; its report likewise returns at most ten top functions and prints five. Android native trace capture uses `perf trace ... --kind perfetto`. These commands require an active Android app session and return artifact paths/summaries instead of dumping profile or trace contents. - Use the compact result as evidence. For example, a successful Perfetto stop may return `state: "stopped"`, `outPath: "/tmp/app.perfetto-trace"`, `sizeBytes: 5392410`, and `method: "adb-shell-perfetto"` while the 5.3 MB raw trace remains on disk as the artifact.