diff --git a/.nx/version-plans/version-plan-1792133861187.md b/.nx/version-plans/version-plan-1792133861187.md new file mode 100644 index 00000000..159f8713 --- /dev/null +++ b/.nx/version-plans/version-plan-1792133861187.md @@ -0,0 +1,5 @@ +--- +__default__: minor +--- + +Run diagnostics now include resource telemetry. Set `diagnostics` to `true` or to an object (`enabled`, `probes`, `sampleIntervalMs`) to sample host load, CPU and memory pressure, Harness process memory and event loop lag, per-milestone process listings on macOS, and the process count and last boot stage of iOS simulators. Entries are written to `.harness/diagnostics/.jsonl` as the run progresses, so cancelled or timed-out CI jobs keep their data. Metrics appear as graphed tracks in the Perfetto trace, and a key-number summary (boot wait, time to ready, peak load, peak compressed memory, swapouts, event loop lag) is printed, saved to `.summary.json` and added to the GitHub Actions job summary. diff --git a/packages/config/src/__tests__/diagnostics-config.test.ts b/packages/config/src/__tests__/diagnostics-config.test.ts new file mode 100644 index 00000000..0c318a83 --- /dev/null +++ b/packages/config/src/__tests__/diagnostics-config.test.ts @@ -0,0 +1,128 @@ +import { describe, expect, it } from 'vitest'; +import { + ConfigSchema, + isDiagnosticsEnabled, + resolveDiagnosticsOptions, +} from '../types.js'; + +const baseConfig = { + entryPoint: './index.js', + appRegistryComponentName: 'App', + runners: [ + { + name: 'test-runner', + config: {}, + runner: 'test-runner', + platformId: 'test-platform', + }, + ], +}; + +const parse = (diagnostics?: unknown) => + ConfigSchema.parse({ ...baseConfig, diagnostics }); + +describe('ConfigSchema diagnostics', () => { + it('defaults to false', () => { + expect(parse().diagnostics).toBe(false); + }); + + it('accepts the boolean form', () => { + expect(parse(true).diagnostics).toBe(true); + expect(parse(false).diagnostics).toBe(false); + }); + + it('accepts the object form', () => { + const diagnostics = { + enabled: true, + probes: { host: true, node: false, snapshots: false, platform: true }, + sampleIntervalMs: 2000, + }; + + expect(parse(diagnostics).diagnostics).toEqual(diagnostics); + expect(parse({}).diagnostics).toEqual({}); + }); + + it.each([ + ['an unknown key', { enable: true }], + ['an unknown probe', { probes: { cpu: true } }], + ['a non-boolean probe switch', { probes: { host: 'yes' } }], + ['a too small interval', { sampleIntervalMs: 10 }], + ['a fractional interval', { sampleIntervalMs: 1000.5 }], + ['a string', 'true'], + ])('rejects %s', (_name, diagnostics) => { + expect(() => parse(diagnostics)).toThrow(); + }); +}); + +describe('isDiagnosticsEnabled', () => { + it('is off without config or environment', () => { + expect(isDiagnosticsEnabled(undefined, {})).toBe(false); + expect(isDiagnosticsEnabled({ diagnostics: false }, {})).toBe(false); + }); + + it('is on for true and for an object unless it opts out', () => { + expect(isDiagnosticsEnabled({ diagnostics: true }, {})).toBe(true); + expect(isDiagnosticsEnabled({ diagnostics: {} }, {})).toBe(true); + expect( + isDiagnosticsEnabled({ diagnostics: { sampleIntervalMs: 1000 } }, {}) + ).toBe(true); + expect(isDiagnosticsEnabled({ diagnostics: { enabled: false } }, {})).toBe( + false + ); + }); + + it.each(['1', 'true', 'yes'])( + 'RN_HARNESS_DIAGNOSTICS=%s enables it', + (value) => { + expect( + isDiagnosticsEnabled( + { diagnostics: false }, + { RN_HARNESS_DIAGNOSTICS: value } + ) + ).toBe(true); + } + ); + + it.each(['', '0', 'false'])('RN_HARNESS_DIAGNOSTICS=%j does not', (value) => { + expect( + isDiagnosticsEnabled( + { diagnostics: false }, + { RN_HARNESS_DIAGNOSTICS: value } + ) + ).toBe(false); + }); +}); + +describe('resolveDiagnosticsOptions', () => { + const allOn = { host: true, node: true, snapshots: true, platform: true }; + + it('turns every probe on by default for every form', () => { + for (const diagnostics of [false, true, {}]) { + expect(resolveDiagnosticsOptions({ diagnostics })).toEqual({ + probes: allOn, + sampleIntervalMs: undefined, + }); + } + }); + + it('resolves defaults without a config', () => { + expect(resolveDiagnosticsOptions(undefined)).toEqual({ + probes: allOn, + sampleIntervalMs: undefined, + }); + }); + + it('applies overrides and keeps the rest on', () => { + expect( + resolveDiagnosticsOptions({ + diagnostics: { + probes: { snapshots: false }, + sampleIntervalMs: 1000, + }, + }) + ).toEqual({ + probes: { ...allOn, snapshots: false }, + sampleIntervalMs: 1000, + }); + }); +}); diff --git a/packages/config/src/index.ts b/packages/config/src/index.ts index 522bb8fc..de4f9834 100644 --- a/packages/config/src/index.ts +++ b/packages/config/src/index.ts @@ -1,9 +1,10 @@ export { getConfig } from './reader.js'; -export type { Config } from './types.js'; +export type { Config, ResolvedDiagnosticsOptions } from './types.js'; export { ConfigSchema, DEFAULT_METRO_PORT, isDiagnosticsEnabled, + resolveDiagnosticsOptions, resolveMetroCacheEnabled, resolveSkipAlreadyIncludedModules, } from './types.js'; diff --git a/packages/config/src/types.ts b/packages/config/src/types.ts index b55ed142..c2230441 100644 --- a/packages/config/src/types.ts +++ b/packages/config/src/types.ts @@ -224,14 +224,66 @@ export const ConfigSchema = z ), diagnostics: z - .boolean() + .union([ + z.boolean(), + z + .object({ + enabled: z + .boolean() + .optional() + .describe( + 'Turns diagnostics on or off. Defaults to true when the object form is used.' + ), + probes: z + .object({ + host: z + .boolean() + .optional() + .describe( + 'Sample host load, CPU split and memory pressure. Defaults to true.' + ), + node: z + .boolean() + .optional() + .describe( + 'Sample Harness process memory and event loop lag. Defaults to true.' + ), + snapshots: z + .boolean() + .optional() + .describe( + 'Record a process listing at run milestones (macOS). Defaults to true.' + ), + platform: z + .boolean() + .optional() + .describe( + 'Record platform specific measurements, such as the process count inside an iOS simulator. Defaults to true.' + ), + }) + .strict() + .optional(), + sampleIntervalMs: z + .number() + .int() + .min(250, 'sampleIntervalMs must be at least 250') + .optional() + .describe( + 'How often host and process metrics are sampled, in milliseconds. Defaults to 5000.' + ), + }) + .strict(), + ]) .optional() .default(false) .describe( - 'Enable diagnostics tracing for the harness session. Records spans for ' + - 'session setup, Metro bundling, bridge/client events, and per-file test runs, ' + - 'then writes a Chrome Trace Event JSON file and prints a summary after each run. ' + - 'Can also be enabled via the RN_HARNESS_DIAGNOSTICS environment variable.' + 'Enable diagnostics for the harness session. Records spans for session ' + + 'setup, Metro bundling, bridge/client events, and per-file test runs, ' + + 'samples host and process resource metrics, then writes a Chrome Trace ' + + 'Event JSON file, an incremental JSONL log and a KPI summary, and prints ' + + 'a summary after each run. Pass an object to tune the probes and the ' + + 'sampling interval. Can also be enabled via the RN_HARNESS_DIAGNOSTICS ' + + 'environment variable.' ), // Deprecated property - used for migration detection @@ -256,14 +308,19 @@ export type Config = z.infer; /** * Resolves whether diagnostics tracing is enabled: either explicitly via the - * `diagnostics` config option, or via the `RN_HARNESS_DIAGNOSTICS` environment - * variable (any value other than unset, `''`, `'0'`, or `'false'`). + * `diagnostics` config option (`true`, or an object that does not set + * `enabled: false`), or via the `RN_HARNESS_DIAGNOSTICS` environment variable + * (any value other than unset, `''`, `'0'`, or `'false'`). */ export const isDiagnosticsEnabled = ( config: Pick | undefined, env: NodeJS.ProcessEnv = process.env ): boolean => { - if (config?.diagnostics === true) { + const diagnostics = config?.diagnostics; + if (diagnostics === true) { + return true; + } + if (typeof diagnostics === 'object' && diagnostics.enabled !== false) { return true; } @@ -271,6 +328,39 @@ export const isDiagnosticsEnabled = ( return !!envValue && envValue !== '0' && envValue !== 'false'; }; +export type ResolvedDiagnosticsOptions = { + probes: { + host: boolean; + node: boolean; + snapshots: boolean; + platform: boolean; + }; + /** Undefined means "use the default sampling interval". */ + sampleIntervalMs: number | undefined; +}; + +/** + * Resolves the diagnostics tuning options. Every probe is on unless the object + * form of `diagnostics` switches it off, which is also what the boolean form + * and the `RN_HARNESS_DIAGNOSTICS` environment variable mean. + */ +export const resolveDiagnosticsOptions = ( + config: Pick | undefined +): ResolvedDiagnosticsOptions => { + const diagnostics = config?.diagnostics; + const options = typeof diagnostics === 'object' ? diagnostics : undefined; + + return { + probes: { + host: options?.probes?.host ?? true, + node: options?.probes?.node ?? true, + snapshots: options?.probes?.snapshots ?? true, + platform: options?.probes?.platform ?? true, + }, + sampleIntervalMs: options?.sampleIntervalMs, + }; +}; + /** * Resolves the effective value of `skipAlreadyIncludedModules`, reconciling * it with the deprecated `unstable__skipAlreadyIncludedModules` alias: diff --git a/packages/jest/src/__tests__/execute-run.test.ts b/packages/jest/src/__tests__/execute-run.test.ts index 3c234f1d..c34886d8 100644 --- a/packages/jest/src/__tests__/execute-run.test.ts +++ b/packages/jest/src/__tests__/execute-run.test.ts @@ -12,7 +12,11 @@ import { AppBridgeDisconnectedError, DeviceNotRespondingError, } from '@react-native-harness/bridge/server'; -import { createDiagnostics } from '@react-native-harness/tools'; +import { + createDiagnostics, + getEmitter, + type LifecycleEvent, +} from '@react-native-harness/tools'; import type { HarnessSession } from '../harness-session.js'; import { executeRun } from '../execute-run.js'; @@ -36,9 +40,15 @@ vi.mock('../run.js', () => ({ // asserting on them doesn't race with executeRun's own diagnostics.flush(). const mockPrintSummary = vi.hoisted(() => vi.fn()); const mockWriteTraceFile = vi.hoisted(() => vi.fn(async () => '/fake/trace.json')); -vi.mock('../diagnostics/index.js', () => ({ +const mockWriteSummaryFile = vi.hoisted(() => vi.fn(async () => '/fake/summary.json')); +const mockAppendStepSummary = vi.hoisted(() => vi.fn(async () => undefined)); +vi.mock('../diagnostics/index.js', async (importOriginal) => ({ + // summarizeRunKpis stays real: it is a pure reduction over the entries. + ...(await importOriginal()), printSummary: mockPrintSummary, writeTraceFile: mockWriteTraceFile, + writeSummaryFile: mockWriteSummaryFile, + appendStepSummary: mockAppendStepSummary, })); // --------------------------------------------------------------------------- @@ -125,6 +135,8 @@ const makeSession = (overrides: Partial = {}): HarnessSession => }, } as HarnessSession['context'], diagnostics: createDiagnostics({ enabled: false }), + sessionId: 'session-1', + lifecycle: getEmitter(), ensureAppReady: vi.fn(resolveUndefined), runTestFile: vi.fn(async () => makeHarnessResult()), restartApp: vi.fn(resolveUndefined), @@ -231,6 +243,22 @@ describe('executeRun', () => { expect(mockWriteTraceFile).toHaveBeenCalledWith(entries, expect.objectContaining({ runId: expect.any(String) })); }); + it('writes the KPI summary and step summary next to the trace', async () => { + mockWriteSummaryFile.mockClear(); + mockAppendStepSummary.mockClear(); + const diagnostics = createDiagnostics({ enabled: true }); + const session = makeSession({ diagnostics }); + + await executeRun(session, [makeTest('/a.ts')], makeWatcher(), makeEmitEvent().emitEvent, makeGlobalConfig()); + + const kpis = { testFileCount: 1, result: 'passed' }; + expect(mockWriteSummaryFile).toHaveBeenCalledWith( + expect.objectContaining(kpis), + expect.objectContaining({ runId: expect.any(String), sessionId: 'session-1' }), + ); + expect(mockAppendStepSummary).toHaveBeenCalledWith(expect.objectContaining(kpis)); + }); + it('still records run.total when a test throws', async () => { const diagnostics = createDiagnostics({ enabled: true }); const session = makeSession({ @@ -247,6 +275,24 @@ describe('executeRun', () => { }); }); + it('emits run and test-file lifecycle phases', async () => { + const session = makeSession(); + const phases: Array<[string, unknown]> = []; + session.lifecycle.addListener((event) => + phases.push([event.phase, event.attrs]), + ); + + await executeRun(session, [makeTest('/a.ts')], makeWatcher(), makeEmitEvent().emitEvent, makeGlobalConfig()); + + const file = path.join('..', 'a.ts'); + expect(phases).toEqual([ + ['run.start', { runId: expect.any(String) }], + ['test-file.start', { file }], + ['test-file.end', { file, status: 'passed' }], + ['run.end', { runId: expect.any(String), status: 'passed' }], + ]); + }); + it('is a no-op and does not generate a report when diagnostics is disabled', async () => { const diagnostics = createDiagnostics({ enabled: false }); const session = makeSession({ diagnostics }); diff --git a/packages/jest/src/__tests__/index.test.ts b/packages/jest/src/__tests__/index.test.ts index 9ddc4aa5..f9e9bb90 100644 --- a/packages/jest/src/__tests__/index.test.ts +++ b/packages/jest/src/__tests__/index.test.ts @@ -3,7 +3,12 @@ import type { Config, Test, TestEvents, TestRunnerOptions, TestWatcher } from 'j import type { TestSuiteResult } from '@react-native-harness/bridge'; import type { HarnessSession } from '../harness-session.js'; import type { executeRun as ExecuteRun } from '../execute-run.js'; -import { createDiagnostics, HarnessError } from '@react-native-harness/tools'; +import { + createDiagnostics, + getEmitter, + HarnessError, + type LifecycleEvent, +} from '@react-native-harness/tools'; import JestHarness from '../index.js'; const resolveUndefined = async () => undefined; @@ -16,6 +21,8 @@ const mockSession: HarnessSession = { config: { metroPort: 8081 } as HarnessSession['config'], context: {} as HarnessSession['context'], diagnostics: createDiagnostics({ enabled: false }), + sessionId: 'session-1', + lifecycle: getEmitter(), onTestRunnerEvent: vi.fn(() => () => undefined), ensureAppReady: vi.fn(resolveUndefined), runTestFile: vi.fn(async (): Promise => ({ diff --git a/packages/jest/src/diagnostics/__tests__/report.test.ts b/packages/jest/src/diagnostics/__tests__/report.test.ts index 52886042..92358770 100644 --- a/packages/jest/src/diagnostics/__tests__/report.test.ts +++ b/packages/jest/src/diagnostics/__tests__/report.test.ts @@ -1,9 +1,21 @@ +import fsSync from 'node:fs'; import fs from 'node:fs/promises'; import os from 'node:os'; import path from 'node:path'; -import { afterEach, beforeEach, describe, expect, it } from 'vitest'; -import type { DiagnosticEntry } from '@react-native-harness/tools'; -import { printSummary, writeTraceFile } from '../report.js'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { + createDiagnostics, + type DiagnosticEntry, +} from '@react-native-harness/tools'; +import { + appendStepSummary, + appendToTraceFile, + createDiagnosticsAppender, + printSummary, + summarizeRunKpis, + writeSummaryFile, + writeTraceFile, +} from '../report.js'; const makeSpanEntry = ( overrides: Partial = {}, @@ -16,6 +28,21 @@ const makeSpanEntry = ( ...overrides, }); +const makeGaugeEntry = ( + label: string, + value: number, + startTime = 1_000, + attrs?: DiagnosticEntry['attrs'], +): DiagnosticEntry => ({ + label, + startTime, + duration: 0, + status: 'ok', + kind: 'gauge', + value, + attrs, +}); + describe('writeTraceFile', () => { let projectRoot: string; @@ -68,6 +95,40 @@ describe('writeTraceFile', () => { }); }); + it('writes gauges as Chrome trace counter events', async () => { + const entries = [ + makeGaugeEntry('host.mem.compressed', 1234.5, 2_000), + makeGaugeEntry('host.load1', 7.25, 2_000, { phase: 'ignored' }), + ]; + + const filePath = await writeTraceFile(entries, { + projectRoot, + runId: 'run-gauges', + }); + + const parsed = JSON.parse(await fs.readFile(filePath, 'utf-8')) as { + traceEvents: Array>; + }; + expect(parsed.traceEvents).toEqual([ + { + name: 'host.mem.compressed', + ph: 'C', + ts: 2_000 * 1000, + pid: 1, + tid: 1, + args: { 'host.mem.compressed': 1234.5 }, + }, + { + name: 'host.load1', + ph: 'C', + ts: 2_000 * 1000, + pid: 1, + tid: 1, + args: { 'host.load1': 7.25 }, + }, + ]); + }); + it('creates the diagnostics directory recursively when missing', async () => { const filePath = await writeTraceFile([makeSpanEntry()], { projectRoot, @@ -125,4 +186,437 @@ describe('printSummary', () => { expect(lines.find((l) => l.includes('a.b'))).toContain('999ms'); expect(lines.find((l) => l.includes('a.c'))).toContain('1.5s'); }); + + it('leaves gauges out of the timing stats and prints the KPIs', () => { + const lines: string[] = []; + printSummary( + [ + makeSpanEntry({ label: 'platform.ios.simctl.waitForBoot', duration: 58_000 }), + makeGaugeEntry('host.load1', 12.34), + makeGaugeEntry('host.mem.compressed', 4096), + ], + (line) => lines.push(line), + ); + + expect(lines.some((l) => l.includes('host.load1'))).toBe(false); + expect(lines).toContain(' KPIs'); + expect(lines).toContain(' Boot wait: 58.0s'); + expect(lines).toContain(' Peak host load (1m): 12.3'); + expect(lines).toContain(' Peak compressed memory: 4096 MB'); + expect(lines).toContain(' Max event loop lag: n/a'); + }); +}); + +describe('summarizeRunKpis', () => { + it('derives every KPI from the entries', () => { + const entries: DiagnosticEntry[] = [ + makeSpanEntry({ label: 'session.config.load', startTime: 1_000, duration: 100 }), + makeSpanEntry({ + label: 'platform.ios.simctl.waitForBoot', + startTime: 1_200, + duration: 58_000, + }), + makeSpanEntry({ + label: 'app.ready.total', + startTime: 70_000, + duration: 5_000, + attrs: { reused: false }, + }), + makeSpanEntry({ + label: 'app.ready.total', + startTime: 90_000, + duration: 10, + attrs: { reused: true }, + }), + makeSpanEntry({ label: 'run.file', attrs: { file: 'a' } }), + makeSpanEntry({ label: 'run.file', attrs: { file: 'b' } }), + makeSpanEntry({ label: 'run.total', attrs: { status: 'failed' } }), + makeGaugeEntry('host.mem.compressed', 800), + makeGaugeEntry('host.mem.compressed', 2600), + makeGaugeEntry('host.mem.compressed', 1500), + makeGaugeEntry('host.load1', 3), + makeGaugeEntry('host.load1', 410.5), + makeGaugeEntry('host.mem.free', 900), + makeGaugeEntry('host.mem.free', 60), + makeGaugeEntry('host.mem.swapouts', 100), + makeGaugeEntry('host.mem.swapouts', 250), + makeGaugeEntry('host.mem.swapouts', 400), + makeGaugeEntry('node.event_loop.max_ms', 15), + makeGaugeEntry('node.event_loop.max_ms', 1900), + ]; + + expect(summarizeRunKpis(entries)).toEqual({ + bootWaitMs: 58_000, + timeToReadyMs: 74_000, + peakHostCompressedMb: 2600, + peakLoad1: 410.5, + minHostFreeMb: 60, + swapoutsDelta: 300, + maxEventLoopLagMs: 1900, + testFileCount: 2, + result: 'failed', + }); + }); + + it('reports null for anything it cannot derive', () => { + expect(summarizeRunKpis([])).toEqual({ + bootWaitMs: null, + timeToReadyMs: null, + peakHostCompressedMb: null, + peakLoad1: null, + minHostFreeMb: null, + swapoutsDelta: null, + maxEventLoopLagMs: null, + testFileCount: 0, + result: null, + }); + }); + + it('needs two samples to compute a swapouts delta and ignores failed app readiness', () => { + const kpis = summarizeRunKpis([ + makeSpanEntry({ label: 'session.config.load', startTime: 0 }), + makeSpanEntry({ label: 'app.ready.total', status: 'error' }), + makeGaugeEntry('host.mem.swapouts', 100), + ]); + + expect(kpis.swapoutsDelta).toBeNull(); + expect(kpis.timeToReadyMs).toBeNull(); + }); +}); + +describe('writeSummaryFile', () => { + let projectRoot: string; + + beforeEach(async () => { + projectRoot = await fs.mkdtemp(path.join(os.tmpdir(), 'harness-summary-test-')); + }); + + afterEach(async () => { + await fs.rm(projectRoot, { recursive: true, force: true }); + }); + + it('writes .summary.json with the run and session ids', async () => { + const kpis = summarizeRunKpis([makeSpanEntry({ label: 'run.file' })]); + + const filePath = await writeSummaryFile(kpis, { + projectRoot, + runId: 'run-1', + sessionId: 'session-1', + }); + + expect(filePath).toBe( + path.join(projectRoot, '.harness', 'diagnostics', 'run-1.summary.json'), + ); + expect(JSON.parse(await fs.readFile(filePath, 'utf-8'))).toEqual({ + runId: 'run-1', + sessionId: 'session-1', + ...kpis, + }); + }); +}); + +describe('appendStepSummary', () => { + let dir: string; + + beforeEach(async () => { + dir = await fs.mkdtemp(path.join(os.tmpdir(), 'harness-step-summary-test-')); + }); + + afterEach(async () => { + await fs.rm(dir, { recursive: true, force: true }); + }); + + const kpis = summarizeRunKpis([ + makeSpanEntry({ label: 'platform.ios.simctl.waitForBoot', duration: 143_000 }), + makeSpanEntry({ label: 'run.total', attrs: { status: 'passed' } }), + ]); + + it('appends a markdown table to GITHUB_STEP_SUMMARY', async () => { + const summaryPath = path.join(dir, 'summary.md'); + await fs.writeFile(summaryPath, '# Existing\n'); + + await appendStepSummary(kpis, { GITHUB_STEP_SUMMARY: summaryPath }); + + const content = await fs.readFile(summaryPath, 'utf-8'); + expect(content.startsWith('# Existing\n')).toBe(true); + expect(content).toContain('### Harness run KPIs'); + expect(content).toContain('| KPI | Value |'); + expect(content).toContain('| Boot wait | 143.0s |'); + expect(content).toContain('| Result | passed |'); + }); + + it('does nothing outside GitHub Actions', async () => { + await expect(appendStepSummary(kpis, {})).resolves.toBeUndefined(); + }); + + it('swallows write failures', async () => { + await expect( + appendStepSummary(kpis, { + GITHUB_STEP_SUMMARY: path.join(dir, 'missing-dir', 'summary.md'), + }), + ).resolves.toBeUndefined(); + }); +}); + +describe('createDiagnosticsAppender', () => { + let projectRoot: string; + + beforeEach(async () => { + vi.useFakeTimers({ toFake: ['setInterval', 'clearInterval'] }); + projectRoot = await fs.mkdtemp(path.join(os.tmpdir(), 'harness-appender-test-')); + }); + + afterEach(async () => { + vi.useRealTimers(); + vi.restoreAllMocks(); + await fs.rm(projectRoot, { recursive: true, force: true }); + }); + + const readLines = async (filePath: string) => + (await fs.readFile(filePath, 'utf-8')) + .split('\n') + .filter(Boolean) + .map((line) => JSON.parse(line) as DiagnosticEntry); + + const exists = (filePath: string) => + fs.stat(filePath).then( + () => true, + () => false, + ); + + it('writes entries as one JSON object per line, flushed on a timer', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'session-1', + }); + expect(appender.filePath).toBe( + path.join(projectRoot, '.harness', 'diagnostics', 'session-1.jsonl'), + ); + + diagnostics.mark('a'); + diagnostics.child('host').gauge('load1', 2.5); + expect(await exists(appender.filePath)).toBe(false); + + vi.advanceTimersByTime(2000); + await appender.dispose(); + + const entries = await readLines(appender.filePath); + expect(entries.map((e) => [e.label, e.kind, e.value])).toEqual([ + ['a', 'mark', undefined], + ['host.load1', 'gauge', 2.5], + ]); + }); + + it('does not block the recording call on disk when the buffer fills', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appendFileSync = vi.spyOn(fsSync, 'appendFileSync'); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'batch', + maxBufferedEntries: 3, + }); + + diagnostics.mark('1'); + diagnostics.mark('2'); + diagnostics.mark('3'); + + expect(appendFileSync).not.toHaveBeenCalled(); + await appender.dispose(); + expect(await readLines(appender.filePath)).toHaveLength(3); + expect(appendFileSync).not.toHaveBeenCalled(); + }); + + it('keeps chunks in order across several async writes', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'order', + maxBufferedEntries: 2, + }); + + for (let i = 0; i < 7; i += 1) { + diagnostics.mark(`m${i}`); + } + await appender.dispose(); + + expect((await readLines(appender.filePath)).map((e) => e.label)).toEqual( + Array.from({ length: 7 }, (_, i) => `m${i}`), + ); + }); + + it('replays entries recorded before the appender was created', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + diagnostics.record({ label: 'session.config.load', duration: 12 }); + + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'replay', + }); + diagnostics.mark('later'); + await appender.dispose(); + + expect((await readLines(appender.filePath)).map((e) => e.label)).toEqual([ + 'session.config.load', + 'later', + ]); + }); + + it('keeps entries that the run report flushes out of the diagnostics buffer', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'independent', + }); + + diagnostics.mark('a'); + expect(diagnostics.flush()).toHaveLength(1); + await appender.dispose(); + + expect(await readLines(appender.filePath)).toHaveLength(1); + }); + + it('stops observing after dispose', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'dispose', + }); + + diagnostics.mark('before'); + await appender.dispose(); + diagnostics.mark('after'); + appender.flush(); + + expect((await readLines(appender.filePath)).map((e) => e.label)).toEqual([ + 'before', + ]); + }); + + it('flushes synchronously on process exit, including writes still pending', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'exit', + maxBufferedEntries: 2, + }); + + diagnostics.mark('queued-1'); + diagnostics.mark('queued-2'); // handed to the async writer, not yet awaited + diagnostics.mark('buffered'); + process.emit('exit', 0); + + const labels = (await readLines(appender.filePath)).map((e) => e.label); + // The async writer may also have completed the first chunk by now, which + // is why a chunk can legitimately appear twice; nothing is lost. + expect(new Set(labels)).toEqual(new Set(['queued-1', 'queued-2', 'buffered'])); + await appender.dispose(); + }); + + it('does not install signal handlers', async () => { + const before = { + sigterm: process.listenerCount('SIGTERM'), + sigint: process.listenerCount('SIGINT'), + }; + const appender = createDiagnosticsAppender( + createDiagnostics({ enabled: true }), + { projectRoot, id: 'signals' }, + ); + + expect({ + sigterm: process.listenerCount('SIGTERM'), + sigint: process.listenerCount('SIGINT'), + }).toEqual(before); + await appender.dispose(); + }); + + it('removes its exit listener on dispose', async () => { + const before = process.listenerCount('exit'); + const appender = createDiagnosticsAppender( + createDiagnostics({ enabled: true }), + { projectRoot, id: 'listeners' }, + ); + expect(process.listenerCount('exit')).toBe(before + 1); + + await appender.dispose(); + + expect(process.listenerCount('exit')).toBe(before); + }); + + it('does nothing at all when diagnostics are disabled', async () => { + const setIntervalSpy = vi.spyOn(globalThis, 'setInterval'); + const before = process.listenerCount('exit'); + const diagnostics = createDiagnostics({ enabled: false }); + + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'disabled', + }); + diagnostics.mark('a'); + appender.flush(); + await appender.dispose(); + + expect(setIntervalSpy).not.toHaveBeenCalled(); + expect(process.listenerCount('exit')).toBe(before); + expect(await exists(path.join(projectRoot, '.harness'))).toBe(false); + }); + + it('never throws when the directory cannot be written', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot: '/dev/null/nope', + id: 'unwritable', + }); + + diagnostics.mark('a'); + expect(() => appender.flush()).not.toThrow(); + diagnostics.mark('b'); + await expect(appender.dispose()).resolves.toBeUndefined(); + }); +}); + +describe('appendToTraceFile', () => { + let projectRoot: string; + + beforeEach(async () => { + projectRoot = await fs.mkdtemp(path.join(os.tmpdir(), 'harness-append-trace-')); + }); + + afterEach(async () => { + await fs.rm(projectRoot, { recursive: true, force: true }); + }); + + it('adds late entries to the run trace that was already written', async () => { + await writeTraceFile([makeSpanEntry({ label: 'run.total' })], { + projectRoot, + runId: 'run-1', + }); + + const filePath = await appendToTraceFile( + [ + makeSpanEntry({ label: 'dispose.total' }), + makeGaugeEntry('host.process_count', 812), + ], + { projectRoot, runId: 'run-1' }, + ); + + const parsed = JSON.parse(await fs.readFile(filePath, 'utf-8')) as { + traceEvents: Array<{ name: string; ph: string }>; + }; + expect(parsed.traceEvents.map((e) => [e.name, e.ph])).toEqual([ + ['run.total', 'X'], + ['dispose.total', 'X'], + ['host.process_count', 'C'], + ]); + }); + + it('writes a new trace when none exists', async () => { + const filePath = await appendToTraceFile([makeSpanEntry()], { + projectRoot, + runId: 'fresh', + }); + + const parsed = JSON.parse(await fs.readFile(filePath, 'utf-8')); + expect(parsed.traceEvents).toHaveLength(1); + }); }); diff --git a/packages/jest/src/diagnostics/__tests__/telemetry.test.ts b/packages/jest/src/diagnostics/__tests__/telemetry.test.ts new file mode 100644 index 00000000..cb63b25b --- /dev/null +++ b/packages/jest/src/diagnostics/__tests__/telemetry.test.ts @@ -0,0 +1,232 @@ +import fs from 'node:fs/promises'; +import os from 'node:os'; +import path from 'node:path'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { createDiagnostics } from '@react-native-harness/tools'; +import type { HarnessPlatformRunner } from '@react-native-harness/platforms'; +import { writeTraceFile } from '../report.js'; +import { startSessionTelemetry } from '../telemetry.js'; + +const onlyPlatformProbe = { + diagnostics: { + probes: { host: false, node: false, snapshots: false, platform: true }, + }, +}; + +const makePlatform = ( + collect = vi + .fn() + .mockResolvedValue({ 'ios.simulator.guest_process_count': 312 }) +) => + ({ + createTelemetryCollector: () => ({ collect }), + } as unknown as HarnessPlatformRunner & { + createTelemetryCollector: () => { collect: typeof collect }; + }); + +describe('startSessionTelemetry', () => { + let projectRoot: string; + + beforeEach(async () => { + projectRoot = await fs.mkdtemp( + path.join(os.tmpdir(), 'harness-telemetry-test-') + ); + }); + + afterEach(async () => { + vi.restoreAllMocks(); + await fs.rm(projectRoot, { recursive: true, force: true }); + }); + + it('starts nothing when diagnostics are disabled', async () => { + const setIntervalSpy = vi.spyOn(globalThis, 'setInterval'); + const exitListeners = process.listenerCount('exit'); + const diagnostics = createDiagnostics({ enabled: false }); + const collect = vi.fn(); + + const telemetry = startSessionTelemetry({ + diagnostics, + config: { diagnostics: true }, + projectRoot, + }); + telemetry.attachPlatform( + makePlatform(collect) as unknown as HarnessPlatformRunner + ); + telemetry.phase('platform.ready'); + await telemetry.settled(); + await telemetry.dispose(); + + expect(collect).not.toHaveBeenCalled(); + expect(setIntervalSpy).not.toHaveBeenCalled(); + expect(process.listenerCount('exit')).toBe(exitListeners); + await expect(fs.stat(path.join(projectRoot, '.harness'))).rejects.toThrow(); + }); + + it('records the run context, drives the platform collector on lifecycle phases and persists everything', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const collect = vi + .fn() + .mockResolvedValue({ 'ios.simulator.guest_process_count': 312 }); + + const telemetry = startSessionTelemetry({ + diagnostics, + config: onlyPlatformProbe, + projectRoot, + }); + telemetry.attachPlatform( + makePlatform(collect) as unknown as HarnessPlatformRunner + ); + telemetry.phase('platform.ready'); + telemetry.phase('dispose'); + await telemetry.settled(); + await telemetry.dispose(); + + expect(collect.mock.calls.map(([phase]) => phase)).toEqual([ + 'platform.ready', + 'dispose', + ]); + + const jsonl = await fs.readFile( + path.join( + projectRoot, + '.harness', + 'diagnostics', + `${telemetry.sessionId}.jsonl` + ), + 'utf-8' + ); + const labels = jsonl + .split('\n') + .filter(Boolean) + .map((line) => (JSON.parse(line) as { label: string }).label); + expect(labels).toEqual([ + 'telemetry.context', + 'platform.ios.simulator.guest_process_count', + 'platform.ios.simulator.guest_process_count', + ]); + }); + + it('respects the probe switches', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const collect = vi.fn().mockResolvedValue({}); + + const telemetry = startSessionTelemetry({ + diagnostics, + config: { + diagnostics: { + probes: { + host: false, + node: false, + snapshots: false, + platform: false, + }, + }, + }, + projectRoot, + }); + telemetry.attachPlatform( + makePlatform(collect) as unknown as HarnessPlatformRunner + ); + telemetry.phase('platform.ready'); + await telemetry.settled(); + await telemetry.dispose(); + + expect(collect).not.toHaveBeenCalled(); + expect(diagnostics.flush().map((e) => e.label)).toEqual([ + 'telemetry.context', + ]); + }); + + it('samples host and node metrics on the configured interval and stops on dispose', async () => { + vi.useFakeTimers(); + try { + const diagnostics = createDiagnostics({ enabled: true }); + const telemetry = startSessionTelemetry({ + diagnostics, + config: { + diagnostics: { + sampleIntervalMs: 1000, + probes: { snapshots: false, platform: false }, + }, + }, + projectRoot, + }); + + await vi.advanceTimersByTimeAsync(2000); + const samples = () => + diagnostics.flush().filter((e) => e.label === 'node.rss_mb').length; + expect(samples()).toBe(3); + + await telemetry.dispose(); + await vi.advanceTimersByTimeAsync(5000); + expect(samples()).toBe(0); + } finally { + vi.useRealTimers(); + } + }); + + it('adds entries recorded after the run report to that run trace on dispose', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const telemetry = startSessionTelemetry({ + diagnostics, + config: onlyPlatformProbe, + projectRoot, + }); + telemetry.attachPlatform( + makePlatform() as unknown as HarnessPlatformRunner + ); + telemetry.trackRun('run-1'); + + // What executeRun does when the run ends: report, then flush. + diagnostics.start('run.total').end(); + const reported = diagnostics.flush(); + await writeTraceFile(reported, { projectRoot, runId: 'run-1' }); + + // Teardown: an end-of-run collection and the dispose span. + telemetry.phase('dispose'); + await telemetry.settled(); + diagnostics.start('dispose.total').end(); + await telemetry.dispose(); + + const trace = JSON.parse( + await fs.readFile( + path.join(projectRoot, '.harness', 'diagnostics', 'run-1.json'), + 'utf-8' + ) + ) as { traceEvents: Array<{ name: string }> }; + expect(trace.traceEvents.map((e) => e.name)).toEqual([ + 'telemetry.context', + 'run.total', + 'platform.ios.simulator.guest_process_count', + 'dispose.total', + ]); + }); + + it('writes no trace on dispose when no run ever started', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const telemetry = startSessionTelemetry({ + diagnostics, + config: onlyPlatformProbe, + projectRoot, + }); + + await telemetry.dispose(); + + const files = await fs.readdir( + path.join(projectRoot, '.harness', 'diagnostics') + ); + expect(files).toEqual([`${telemetry.sessionId}.jsonl`]); + }); + + it('dispose is idempotent', async () => { + const telemetry = startSessionTelemetry({ + diagnostics: createDiagnostics({ enabled: true }), + config: onlyPlatformProbe, + projectRoot, + }); + + const first = telemetry.dispose(); + expect(telemetry.dispose()).toBe(first); + await first; + }); +}); diff --git a/packages/jest/src/diagnostics/index.ts b/packages/jest/src/diagnostics/index.ts index 60714b9b..5ce02fff 100644 --- a/packages/jest/src/diagnostics/index.ts +++ b/packages/jest/src/diagnostics/index.ts @@ -1,2 +1,13 @@ export { observeMetroEvents, observeBridgeEvents } from './derivers.js'; -export { writeTraceFile, printSummary } from './report.js'; +export { + writeTraceFile, + appendToTraceFile, + printSummary, + createDiagnosticsAppender, + summarizeRunKpis, + writeSummaryFile, + appendStepSummary, +} from './report.js'; +export type { DiagnosticsAppender, RunKpis } from './report.js'; +export { startSessionTelemetry } from './telemetry.js'; +export type { SessionTelemetry } from './telemetry.js'; diff --git a/packages/jest/src/diagnostics/report.ts b/packages/jest/src/diagnostics/report.ts index ecbf0f47..3455ec98 100644 --- a/packages/jest/src/diagnostics/report.ts +++ b/packages/jest/src/diagnostics/report.ts @@ -1,11 +1,14 @@ +import fsSync from 'node:fs'; import fs from 'node:fs/promises'; import path from 'node:path'; -import type { DiagnosticEntry } from '@react-native-harness/tools'; -import { getHarnessRootPath } from '@react-native-harness/tools'; +import type { DiagnosticEntry, Diagnostics } from '@react-native-harness/tools'; +import { getHarnessRootPath, logger, unrefTimer } from '@react-native-harness/tools'; + +const reportLogger = logger.child('diagnostics'); type TraceEvent = { name: string; - ph: 'X' | 'i'; + ph: 'X' | 'i' | 'C'; ts: number; dur?: number; s?: 'g'; @@ -17,7 +20,20 @@ type TraceEvent = { const TRACE_PID = 1; const TRACE_TID = 1; -const toTraceEvent = (entry: DiagnosticEntry): TraceEvent => { +export const toTraceEvent = (entry: DiagnosticEntry): TraceEvent => { + if (entry.kind === 'gauge') { + // Counter events become graphed tracks in Perfetto / chrome://tracing, + // one per distinct name, so each gauge label is its own series. + return { + name: entry.label, + ph: 'C', + ts: entry.startTime * 1000, + pid: TRACE_PID, + tid: TRACE_TID, + args: { [entry.label]: entry.value ?? 0 }, + }; + } + if (entry.kind === 'mark') { return { name: entry.label, @@ -45,7 +61,7 @@ export const writeTraceFile = async ( entries: DiagnosticEntry[], options: { projectRoot: string; runId: string } ): Promise => { - const dir = path.join(getHarnessRootPath(options.projectRoot), 'diagnostics'); + const dir = getDiagnosticsDir(options.projectRoot); await fs.mkdir(dir, { recursive: true }); const filePath = path.join(dir, `${options.runId}.json`); @@ -56,6 +72,303 @@ export const writeTraceFile = async ( return filePath; }; +const getDiagnosticsDir = (projectRoot: string): string => + path.join(getHarnessRootPath(projectRoot), 'diagnostics'); + +export type DiagnosticsAppender = { + readonly filePath: string; + /** Synchronously writes everything not yet on disk. For `exit` handlers. */ + flush(): void; + /** Waits for in-flight writes, then writes the rest and detaches. */ + dispose(): Promise; +}; + +/** + * Persists diagnostics entries as they are recorded, one JSON object per line + * in `.harness/diagnostics/.jsonl`. The final trace is only written when a + * run finishes, so a job that is cancelled or killed mid-run (the case where + * the data matters most) would otherwise leave nothing behind. + * + * Entries are batched (every `flushIntervalMs` or `maxBufferedEntries`) and + * appended asynchronously, one write at a time, so recording an entry never + * blocks on disk, which matters most when the machine is overloaded. Only the + * `exit` handler writes synchronously: a process that is going away cannot + * wait for the event loop. The session already owns SIGINT/SIGTERM and leaves + * through `process.exit`, which emits `exit`; installing signal handlers here + * would depend on listener order and fight other handlers about who re-raises. + * + * Entries recorded before the appender was created are replayed, so the log + * starts at the beginning of the session. + */ +export const createDiagnosticsAppender = ( + diagnostics: Diagnostics, + options: { + projectRoot: string; + id: string; + flushIntervalMs?: number; + maxBufferedEntries?: number; + } +): DiagnosticsAppender => { + const filePath = path.join( + getDiagnosticsDir(options.projectRoot), + `${options.id}.jsonl` + ); + + if (!diagnostics.enabled) { + return { + filePath, + flush: () => undefined, + dispose: async () => undefined, + }; + } + + const maxBufferedEntries = options.maxBufferedEntries ?? 100; + let buffer: string[] = []; + // Chunks handed to the async writer and not yet confirmed on disk, kept so + // the `exit` handler can write them if the process leaves first. In the + // rare race where one was also completed by the writer, a chunk ends up in + // the file twice; losing it would be worse for a log whose purpose is + // surviving abrupt termination. + let pending: string[][] = []; + let writeChain: Promise = Promise.resolve(); + let directoryReady = false; + + const render = (lines: string[]) => `${lines.join('\n')}\n`; + + const flushAsync = () => { + if (buffer.length === 0) { + return; + } + + const lines = buffer; + buffer = []; + pending.push(lines); + writeChain = writeChain.then(async () => { + try { + if (!directoryReady) { + await fs.mkdir(path.dirname(filePath), { recursive: true }); + directoryReady = true; + } + await fs.appendFile(filePath, render(lines), 'utf-8'); + } catch (error) { + reportLogger.debug('failed to append diagnostics: %s', error); + } finally { + pending = pending.filter((chunk) => chunk !== lines); + } + }); + }; + + const flushSync = () => { + const lines = [...pending.flat(), ...buffer]; + pending = []; + buffer = []; + if (lines.length === 0) { + return; + } + + try { + fsSync.mkdirSync(path.dirname(filePath), { recursive: true }); + fsSync.appendFileSync(filePath, render(lines), 'utf-8'); + } catch (error) { + reportLogger.debug('failed to append diagnostics: %s', error); + } + }; + + const unsubscribe = diagnostics.subscribe( + (entry) => { + buffer.push(JSON.stringify(entry)); + if (buffer.length >= maxBufferedEntries) { + flushAsync(); + } + }, + { replay: true } + ); + + const timer = setInterval(flushAsync, options.flushIntervalMs ?? 2000); + unrefTimer(timer); + process.on('exit', flushSync); + + const dispose = async () => { + unsubscribe(); + clearInterval(timer); + process.off('exit', flushSync); + flushAsync(); + await writeChain; + }; + + return { filePath, flush: flushSync, dispose }; +}; + +export type RunKpis = { + bootWaitMs: number | null; + timeToReadyMs: number | null; + peakHostCompressedMb: number | null; + peakLoad1: number | null; + minHostFreeMb: number | null; + /** Memory swapped out during the run, in MB. */ + swapoutsDelta: number | null; + maxEventLoopLagMs: number | null; + testFileCount: number; + result: 'passed' | 'failed' | null; +}; + +const maxOf = (values: number[]): number | null => + values.length > 0 ? Math.max(...values) : null; + +const minOf = (values: number[]): number | null => + values.length > 0 ? Math.min(...values) : null; + +/** + * Reduces a run's entries to the handful of numbers worth comparing between + * runs. Anything that cannot be derived from the entries is null, never a + * guess, so a missing probe shows up as "n/a" rather than as a misleading 0. + */ +export const summarizeRunKpis = (entries: DiagnosticEntry[]): RunKpis => { + const gaugeValues = (label: string): number[] => + entries + .filter((entry) => entry.kind === 'gauge' && entry.label === label) + .map((entry) => entry.value) + .filter((value): value is number => typeof value === 'number'); + + const spans = (label: string): DiagnosticEntry[] => + entries.filter((entry) => entry.kind === 'span' && entry.label === label); + + const bootSpans = entries.filter( + (entry) => entry.kind === 'span' && entry.label.endsWith('.waitForBoot') + ); + + const sessionStart = spans('session.config.load')[0]?.startTime; + const firstReady = spans('app.ready.total').find( + (entry) => entry.status === 'ok' + ); + + const swapouts = gaugeValues('host.mem.swapouts'); + const runStatus = spans('run.total')[0]?.attrs?.status; + + return { + bootWaitMs: + bootSpans.length > 0 + ? bootSpans.reduce((total, entry) => total + entry.duration, 0) + : null, + timeToReadyMs: + sessionStart !== undefined && firstReady + ? firstReady.startTime + firstReady.duration - sessionStart + : null, + peakHostCompressedMb: maxOf(gaugeValues('host.mem.compressed')), + peakLoad1: maxOf(gaugeValues('host.load1')), + minHostFreeMb: minOf(gaugeValues('host.mem.free')), + swapoutsDelta: + swapouts.length >= 2 + ? (swapouts[swapouts.length - 1] as number) - (swapouts[0] as number) + : null, + maxEventLoopLagMs: maxOf(gaugeValues('node.event_loop.max_ms')), + testFileCount: spans('run.file').length, + result: + runStatus === 'passed' || runStatus === 'failed' ? runStatus : null, + }; +}; + +export const writeSummaryFile = async ( + kpis: RunKpis, + options: { projectRoot: string; runId: string; sessionId?: string } +): Promise => { + const dir = getDiagnosticsDir(options.projectRoot); + await fs.mkdir(dir, { recursive: true }); + + const filePath = path.join(dir, `${options.runId}.summary.json`); + const summary = { + runId: options.runId, + ...(options.sessionId ? { sessionId: options.sessionId } : {}), + ...kpis, + }; + await fs.writeFile(filePath, JSON.stringify(summary, null, 2), 'utf-8'); + + return filePath; +}; + +const formatNumber = (value: number | null, unit: string, digits = 0) => + value === null ? 'n/a' : `${value.toFixed(digits)}${unit}`; + +const formatKpiDuration = (ms: number | null) => + ms === null ? 'n/a' : formatDuration(ms); + +/** The KPIs as label/value pairs, in display order. */ +export const formatRunKpis = (kpis: RunKpis): Array<[string, string]> => [ + ['Result', kpis.result ?? 'n/a'], + ['Test files', String(kpis.testFileCount)], + ['Boot wait', formatKpiDuration(kpis.bootWaitMs)], + ['Time to ready', formatKpiDuration(kpis.timeToReadyMs)], + ['Peak host load (1m)', formatNumber(kpis.peakLoad1, '', 1)], + ['Peak compressed memory', formatNumber(kpis.peakHostCompressedMb, ' MB')], + ['Min free memory', formatNumber(kpis.minHostFreeMb, ' MB')], + ['Swapped out during run', formatNumber(kpis.swapoutsDelta, ' MB')], + ['Max event loop lag', formatNumber(kpis.maxEventLoopLagMs, ' ms')], +]; + +/** + * Appends the KPIs as a markdown table to the GitHub Actions job summary when + * running there. Best effort: a failure here must never fail the run. + */ +export const appendStepSummary = async ( + kpis: RunKpis, + env: NodeJS.ProcessEnv = process.env +): Promise => { + const summaryPath = env.GITHUB_STEP_SUMMARY; + if (!summaryPath) { + return; + } + + const rows = formatRunKpis(kpis).map(([label, value]) => `| ${label} | ${value} |`); + const markdown = [ + '### Harness run KPIs', + '', + '| KPI | Value |', + '| --- | --- |', + ...rows, + '', + '', + ].join('\n'); + + try { + await fs.appendFile(summaryPath, markdown, 'utf-8'); + } catch (error) { + reportLogger.debug('failed to write GitHub step summary: %s', error); + } +}; + +/** + * Adds entries recorded after a run's trace was written (session teardown) to + * that trace, or writes a new trace if there is none yet. + */ +export const appendToTraceFile = async ( + entries: DiagnosticEntry[], + options: { projectRoot: string; runId: string } +): Promise => { + const filePath = path.join( + getDiagnosticsDir(options.projectRoot), + `${options.runId}.json` + ); + + let existing: TraceEvent[] = []; + try { + const parsed = JSON.parse(await fs.readFile(filePath, 'utf-8')) as { + traceEvents?: TraceEvent[]; + }; + existing = parsed.traceEvents ?? []; + } catch { + // No trace yet (or an unreadable one): start a fresh file. + } + + await fs.mkdir(path.dirname(filePath), { recursive: true }); + await fs.writeFile( + filePath, + JSON.stringify({ traceEvents: [...existing, ...entries.map(toTraceEvent)] }), + 'utf-8' + ); + + return filePath; +}; + const formatDuration = (ms: number): string => { if (ms >= 1000) { return `${(ms / 1000).toFixed(1)}s`; @@ -82,6 +395,10 @@ export const printSummary = ( const statsByLabel = new Map(); for (const entry of entries) { + // Gauges are samples, not timings; they are summarised as KPIs below. + if (entry.kind === 'gauge') { + continue; + } const existing = statsByLabel.get(entry.label); if (existing) { existing.count += 1; @@ -121,4 +438,8 @@ export const printSummary = ( ); } } + log(' KPIs'); + for (const [label, value] of formatRunKpis(summarizeRunKpis(entries))) { + log(` ${label}: ${value}`); + } }; diff --git a/packages/jest/src/diagnostics/telemetry.ts b/packages/jest/src/diagnostics/telemetry.ts new file mode 100644 index 00000000..fe9c590e --- /dev/null +++ b/packages/jest/src/diagnostics/telemetry.ts @@ -0,0 +1,133 @@ +import { randomUUID } from 'node:crypto'; +import { + logger, + createDefaultProbes, + createLifecycleEmitter, + DEFAULT_SAMPLE_INTERVAL_MS, + startTelemetryProbes, + type Diagnostics, + type DiagnosticAttrs, + type LifecyclePhase, +} from '@react-native-harness/tools'; +import { + resolveDiagnosticsOptions, + type Config as HarnessConfig, +} from '@react-native-harness/config'; +import type { HarnessPlatformRunner } from '@react-native-harness/platforms'; +import { appendToTraceFile, createDiagnosticsAppender } from './report.js'; + +const telemetryLogger = logger.child('diagnostics'); + +export type SessionTelemetry = { + /** Identifies the session; names the incremental `.jsonl` log. */ + readonly sessionId: string; + /** Session code emits phases here; probes listen. */ + readonly lifecycle: ReturnType; + /** Emits a lifecycle phase. */ + phase(phase: LifecyclePhase, attrs?: DiagnosticAttrs): void; + /** Makes the platform runner available to the platform collector probe. */ + attachPlatform(platform: HarnessPlatformRunner): void; + /** Records the run that is current, so teardown data can join its trace. */ + trackRun(runId: string): void; + /** Resolves once lifecycle driven collection started so far has finished. */ + settled(): Promise; + /** + * Stops probes and the incremental log. Entries recorded since the last + * run's report was written (the end-of-run snapshot, teardown spans) are + * added to that run's trace. Safe to call more than once. + */ + dispose(): Promise; +}; + +/** + * The single composition point for run telemetry: it wires the incremental + * log and the probes to the one diagnostics sink. Session code only emits + * lifecycle phases; it never calls a probe. Everything is a no-op, with no + * timers, listeners or spawned processes, when diagnostics are disabled. + */ +export const startSessionTelemetry = ({ + diagnostics, + config, + projectRoot, +}: { + diagnostics: Diagnostics; + config: Pick; + projectRoot: string; +}): SessionTelemetry => { + const sessionId = randomUUID(); + const lifecycle = createLifecycleEmitter(); + const abortController = new AbortController(); + const options = resolveDiagnosticsOptions(config); + + let platform: HarnessPlatformRunner | undefined; + let lastRunId: string | undefined; + + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: sessionId, + }); + + const run = startTelemetryProbes( + createDefaultProbes({ + host: options.probes.host, + node: options.probes.node, + snapshots: options.probes.snapshots, + platform: options.probes.platform + ? { getCollector: () => platform?.createTelemetryCollector?.() } + : undefined, + }), + { + diagnostics, + signal: abortController.signal, + lifecycle, + sampleIntervalMs: options.sampleIntervalMs ?? DEFAULT_SAMPLE_INTERVAL_MS, + } + ); + + const phase = (name: LifecyclePhase, attrs?: DiagnosticAttrs) => { + if (!diagnostics.enabled) { + return; + } + lifecycle.emit({ type: 'phase', phase: name, attrs }); + }; + + let disposed: Promise | null = null; + + return { + sessionId, + lifecycle, + phase, + attachPlatform: (runner) => { + platform = runner; + }, + trackRun: (runId) => { + lastRunId = runId; + }, + settled: run.settled, + dispose: () => { + disposed ??= (async () => { + try { + abortController.abort(); + await run.dispose(); + if (diagnostics.enabled && lastRunId) { + const leftover = diagnostics.flush(); + if (leftover.length > 0) { + await appendToTraceFile(leftover, { + projectRoot, + runId: lastRunId, + }); + } + } + } catch (error) { + telemetryLogger.debug( + 'failed to finalize diagnostics trace: %s', + error + ); + } finally { + await appender.dispose(); + } + })(); + return disposed; + }, + }; +}; diff --git a/packages/jest/src/execute-run.ts b/packages/jest/src/execute-run.ts index 04a14e8f..dddf3cf4 100644 --- a/packages/jest/src/execute-run.ts +++ b/packages/jest/src/execute-run.ts @@ -31,7 +31,13 @@ import { } from './test-file-platform-filter.js'; import { formatHarnessErrorMessage } from './format-harness-error.js'; import { logger } from '@react-native-harness/tools'; -import { printSummary, writeTraceFile } from './diagnostics/index.js'; +import { + appendStepSummary, + printSummary, + summarizeRunKpis, + writeSummaryFile, + writeTraceFile, +} from './diagnostics/index.js'; import { toJestStatus } from './toJestStatus.js'; const diagnosticsLogger = logger.child('diagnostics'); @@ -177,6 +183,11 @@ export const executeRun = async ( }; updateRunState(); + session.lifecycle.emit({ + type: 'phase', + phase: 'run.start', + attrs: { runId }, + }); await session.callHook('run:started', { runId, @@ -227,6 +238,11 @@ export const executeRun = async ( await session.callHook('test-file:started', { runId, file: relativeTestPath }); const fileSpan = diagnostics.start('run.file', { file: relativeTestPath }); + session.lifecycle.emit({ + type: 'phase', + phase: 'test-file.start', + attrs: { file: relativeTestPath }, + }); let fileStatus: 'passed' | 'failed' | 'skipped' | 'todo' = 'failed'; try { @@ -336,6 +352,11 @@ export const executeRun = async ( } } finally { fileSpan.end({ status: fileStatus }); + session.lifecycle.emit({ + type: 'phase', + phase: 'test-file.end', + attrs: { file: relativeTestPath, status: fileStatus }, + }); } } } catch (err) { @@ -358,6 +379,12 @@ export const executeRun = async ( await caseEventChain; unsubscribe(); runSpan.end({ runId, status: finalStatus }); + // Idle time between runs (watch mode) is not part of any run's metrics. + session.lifecycle.emit({ + type: 'phase', + phase: 'run.end', + attrs: { runId, status: finalStatus }, + }); if (session.diagnostics.enabled) { const entries = session.diagnostics.flush(); @@ -365,6 +392,14 @@ export const executeRun = async ( printSummary(entries, (line) => diagnosticsLogger.info(line)); const tracePath = await writeTraceFile(entries, { projectRoot: rootDir, runId }); diagnosticsLogger.info(`wrote diagnostics trace to ${tracePath}`); + const kpis = summarizeRunKpis(entries); + const summaryPath = await writeSummaryFile(kpis, { + projectRoot: rootDir, + runId, + sessionId: session.sessionId, + }); + diagnosticsLogger.info(`wrote diagnostics summary to ${summaryPath}`); + await appendStepSummary(kpis); } catch (reportError) { diagnosticsLogger.warn('failed to write diagnostics report: %s', reportError); } diff --git a/packages/jest/src/harness-session.ts b/packages/jest/src/harness-session.ts index 0764c1e4..746f4b23 100644 --- a/packages/jest/src/harness-session.ts +++ b/packages/jest/src/harness-session.ts @@ -75,7 +75,12 @@ import { type ResourceLockManager, type ResourceLease, } from './resource-lock.js'; -import { observeBridgeEvents, observeMetroEvents } from './diagnostics/index.js'; +import { + observeBridgeEvents, + observeMetroEvents, + startSessionTelemetry, + type SessionTelemetry, +} from './diagnostics/index.js'; import { resolveHarnessMetroPort } from './metro-port.js'; import { getAdditionalCliArgs } from './cli-args.js'; import { @@ -96,6 +101,8 @@ const isBridgeDisconnectError = (error: unknown) => error instanceof Error && error.message === 'App bridge disconnected'; const TEST_RUN_BRIDGE_STABILITY_WAIT_MS = 500; const DISPOSE_HOOK_TIMEOUT_MS = 5_000; +// Upper bound on waiting for end-of-run telemetry before tearing resources down. +const DISPOSE_TELEMETRY_TIMEOUT_MS = 10_000; const waitForBoundedSettlement = async ( promise: Promise, @@ -194,6 +201,10 @@ export type HarnessSession = { readonly config: HarnessConfig; readonly context: HarnessContext; readonly diagnostics: Diagnostics; + /** Identifies this session; names its incremental diagnostics log. */ + readonly sessionId: string; + /** Run lifecycle phases, for telemetry probes (see `SessionTelemetry`). */ + readonly lifecycle: SessionTelemetry['lifecycle']; onTestRunnerEvent: (listener: (event: TestRunnerEvents) => void) => () => void; runTestFile: (path: string, options: HarnessRunTestsOptions) => Promise; ensureAppReady: (testFilePath: string) => Promise; @@ -497,6 +508,22 @@ export const createHarnessSession = async ( duration: Date.now() - setupStartedAt, }); + // The one composition point for run telemetry. Everything below only emits + // lifecycle phases; probes translate them and polled data into diagnostics. + const telemetry = startSessionTelemetry({ + diagnostics, + config: harnessConfig, + projectRoot, + }); + telemetry.phase('session.created'); + // Telemetry runs timers and listens on `exit`, so a setup failure before the + // main try/catch below must still stop it. + const disposeTelemetryOnFailure = (work: Promise): Promise => + work.catch(async (error) => { + await telemetry.dispose(); + throw error; + }); + sessionLogger.debug( 'creating session for runner=%s platform=%s', platform.name, @@ -518,13 +545,15 @@ export const createHarnessSession = async ( process.once('SIGTERM', onEarlySignal); process.once('SIGINT', onEarlySignal); - const resourceLockKey = await (platform.getResourceLockKey?.() ?? getDefaultResourceLockKey(platform)); + const resourceLockKey = await disposeTelemetryOnFailure( + Promise.resolve(platform.getResourceLockKey?.() ?? getDefaultResourceLockKey(platform)) + ); let didWaitForResourceLock = false; let lastStillWaitingLogAt = 0; logTestRunHeader(platform); - const resourceLease = await diagnostics.measure( + const resourceLease = await disposeTelemetryOnFailure(diagnostics.measure( 'session.lock.wait', () => lockManager.acquire(resourceLockKey, { @@ -542,7 +571,7 @@ export const createHarnessSession = async ( }, }), { lockKey: resourceLockKey } - ); + )); if (didWaitForResourceLock) logRunnerStarting(platform); sessionLogger.debug('resource lock acquired for runner=%s key=%s', platform.name, resourceLockKey); @@ -641,6 +670,7 @@ export const createHarnessSession = async ( } initialized.metro = instance; sessionLogger.debug('Metro initialized'); + telemetry.phase('metro.ready'); // Attach the Metro diagnostics deriver before the eager prewarm // fires so its bundle build/request events land in the trace. disposeMetroDiagnostics = observeMetroEvents(instance.events, diagnostics); @@ -682,6 +712,8 @@ export const createHarnessSession = async ( } initialized.platform = instance; sessionLogger.debug('platform runner initialized'); + telemetry.attachPlatform(instance); + telemetry.phase('platform.ready'); return instance; }); }, @@ -811,6 +843,7 @@ export const createHarnessSession = async ( // Abort only cancels finite/in-flight work. Ownership remains explicit // below, so this cannot race a platform or app-session disposal path. sessionController.abort(); + telemetry.phase('dispose'); const hookWork = (async () => { await hooks.drain(); @@ -843,6 +876,13 @@ export const createHarnessSession = async ( hookError = hookResult.reason; } + // End-of-run telemetry has to observe the platform before it is torn + // down, but must never be able to hold teardown up for long. + await waitForBoundedSettlement( + telemetry.settled(), + DISPOSE_TELEMETRY_TIMEOUT_MS + ); + if (runtimeConfig.forwardClientLogs) { metroInstance.events.removeListener(clientLogListener); } @@ -903,7 +943,7 @@ export const createHarnessSession = async ( }; const dispose = (reason: 'normal' | 'abort' | 'error' = 'normal') => { - disposePromise ??= disposeOnce(reason); + disposePromise ??= disposeOnce(reason).finally(() => telemetry.dispose()); return disposePromise; }; @@ -969,6 +1009,7 @@ export const createHarnessSession = async ( await hooks.drain(); sessionLogger.debug('app is ready for %s', testFilePath); appReadySpan.end({ file: testFilePath, reused: false }); + telemetry.phase('app.ready', { file: testFilePath }); }; // Shared by restartApp (crash/timeout recovery) and the 'process' reset @@ -1121,6 +1162,8 @@ export const createHarnessSession = async ( config: runtimeConfig, context, diagnostics, + sessionId: telemetry.sessionId, + lifecycle: telemetry.lifecycle, onTestRunnerEvent: (listener) => { testRunnerEventListeners.add(listener); return () => { @@ -1144,6 +1187,9 @@ export const createHarnessSession = async ( }, setRunState: (state) => { currentRun = state; + if (state) { + telemetry.trackRun(state.runId); + } }, dispose: async (reason = 'normal') => { try { @@ -1160,6 +1206,7 @@ export const createHarnessSession = async ( // Cancels any inflight init work still holding sessionController.signal // (e.g. a platform init call abandoned after a readiness timeout race). sessionController.abort(); + await telemetry.dispose(); await Promise.allSettled([resourceLease.release(), metroPortLease?.release()]); if (receivedEarlySignal) { process.exit(1); diff --git a/packages/platform-ios/src/__tests__/instance.test.ts b/packages/platform-ios/src/__tests__/instance.test.ts index 4c7804a1..4056d6c2 100644 --- a/packages/platform-ios/src/__tests__/instance.test.ts +++ b/packages/platform-ios/src/__tests__/instance.test.ts @@ -10,6 +10,7 @@ import { import * as simctl from '../xcrun/simctl.js'; import * as devicectl from '../xcrun/devicectl.js'; import { HarnessAppPathError } from '../errors.js'; +import { createDiagnostics } from '@react-native-harness/tools'; import { mkdtempSync, mkdirSync, rmSync } from 'node:fs'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; @@ -258,6 +259,82 @@ describe('iOS platform instance dependency validation', () => { expect(shutdownSimulator).not.toHaveBeenCalled(); }); + it('reports the guest process count through the telemetry collector', async () => { + vi.spyOn(simctl, 'getSimulatorId').mockResolvedValue('sim-udid'); + vi.spyOn(simctl, 'getSimulatorStatus').mockResolvedValue('Booted'); + vi.spyOn(simctl, 'isAppInstalled').mockResolvedValue(true); + vi.spyOn(simctl, 'applyHarnessJsLocationOverride').mockResolvedValue( + undefined, + ); + const getGuestProcessCount = vi + .spyOn(simctl, 'getGuestProcessCount') + .mockResolvedValue(312); + + const instance = await getAppleSimulatorPlatformInstance( + { + name: 'ios', + device: { + type: 'simulator', + name: 'iPhone 16 Pro', + systemVersion: '18.0', + }, + bundleId: 'com.harnessplayground', + }, + harnessConfig, + init, + ); + const collector = instance.createTelemetryCollector?.(); + + const signal = new AbortController().signal; + await expect(collector?.collect('platform.ready', signal)).resolves.toEqual({ + 'ios.simulator.guest_process_count': 312, + }); + await expect(collector?.collect('dispose', signal)).resolves.toEqual({ + 'ios.simulator.guest_process_count': 312, + }); + await expect(collector?.collect('app.ready', signal)).resolves.toEqual({}); + await expect(collector?.collect('test-file.start', signal)).resolves.toEqual({}); + expect(getGuestProcessCount).toHaveBeenCalledTimes(2); + expect(getGuestProcessCount).toHaveBeenCalledWith('sim-udid', signal); + }); + + it('records the last bootstatus stage on the waitForBoot span', async () => { + vi.spyOn(simctl, 'getSimulatorId').mockResolvedValue('sim-udid'); + vi.spyOn(simctl, 'getSimulatorStatus').mockResolvedValue('Booting'); + vi.spyOn(simctl, 'waitForBoot').mockResolvedValue({ + lastStatusLine: 'Waiting on System App', + elapsedSeconds: 143, + }); + vi.spyOn(simctl, 'isAppInstalled').mockResolvedValue(true); + vi.spyOn(simctl, 'applyHarnessJsLocationOverride').mockResolvedValue( + undefined, + ); + const diagnostics = createDiagnostics({ enabled: true }); + + await getAppleSimulatorPlatformInstance( + { + name: 'ios', + device: { + type: 'simulator', + name: 'iPhone 16 Pro', + systemVersion: '18.0', + }, + bundleId: 'com.harnessplayground', + }, + harnessConfig, + { ...init, diagnostics }, + ); + await new Promise((resolve) => setTimeout(resolve, 0)); + + const span = diagnostics + .flush() + .find((entry) => entry.label === 'platform.ios.simctl.waitForBoot'); + expect(span?.attrs).toEqual({ + bootLastStatus: 'Waiting on System App', + bootElapsedSeconds: 143, + }); + }); + it('boots a shutdown simulator and shuts it down on dispose', async () => { vi.spyOn(simctl, 'getSimulatorId').mockResolvedValue('sim-udid'); vi.spyOn(simctl, 'getSimulatorStatus').mockResolvedValue('Shutdown'); @@ -266,7 +343,7 @@ describe('iOS platform instance dependency validation', () => { .mockResolvedValue(undefined); const waitForBoot = vi .spyOn(simctl, 'waitForBoot') - .mockResolvedValue(undefined); + .mockResolvedValue({ lastStatusLine: 'Finished', elapsedSeconds: 6 }); vi.spyOn(simctl, 'isAppInstalled').mockResolvedValue(true); vi.spyOn(simctl, 'applyHarnessJsLocationOverride').mockResolvedValue( undefined, @@ -309,7 +386,7 @@ describe('iOS platform instance dependency validation', () => { .mockResolvedValue(undefined); const waitForBoot = vi .spyOn(simctl, 'waitForBoot') - .mockResolvedValue(undefined); + .mockResolvedValue({ lastStatusLine: 'Finished', elapsedSeconds: 6 }); vi.spyOn(simctl, 'isAppInstalled').mockResolvedValue(true); vi.spyOn(simctl, 'applyHarnessJsLocationOverride').mockResolvedValue( undefined, @@ -352,7 +429,7 @@ describe('iOS platform instance dependency validation', () => { .mockResolvedValue(undefined); const waitForBoot = vi .spyOn(simctl, 'waitForBoot') - .mockResolvedValue(undefined); + .mockResolvedValue({ lastStatusLine: 'Finished', elapsedSeconds: 6 }); vi.spyOn(simctl, 'isAppInstalled').mockResolvedValue(true); vi.spyOn(simctl, 'applyHarnessJsLocationOverride').mockResolvedValue( undefined, diff --git a/packages/platform-ios/src/__tests__/simctl.test.ts b/packages/platform-ios/src/__tests__/simctl.test.ts index 5a59c0e8..23357c4e 100644 --- a/packages/platform-ios/src/__tests__/simctl.test.ts +++ b/packages/platform-ios/src/__tests__/simctl.test.ts @@ -1,6 +1,31 @@ import { describe, expect, it, vi, beforeEach } from 'vitest'; import * as tools from '@react-native-harness/tools'; -import { diagnose, streamLogs, waitForBoot } from '../xcrun/simctl.js'; +import { + diagnose, + getGuestProcessCount, + parseBootStatus, + streamLogs, + waitForBoot, +} from '../xcrun/simctl.js'; +import { + simctlErrorAttrs, + simctlResultAttrs, +} from '../xcrun/simctl-diagnostics.js'; + +// Trimmed from a real `xcrun simctl bootstatus -b` run. +const BOOTSTATUS_OUTPUT = `Monitoring boot status for iPhone 17e (0461A3FF-A9E3-4DEB-BA20-13E75B01B530). +[2026-10-16 06:47:07 +0000] Status=1, isTerminal=NO, Elapsed=00:03. +\u251c\u2500\u2500\u2524Waiting on BackBoard + +[2026-10-16 06:47:08 +0000] Status=2, isTerminal=NO, Elapsed=00:05. +\u251c\u2500\u2500\u2524Waiting on Data Migration +\u251c\u2500\u2500\u2524\u251c\u2500\u2500\u2524Reason:Running plugin com.apple.MobileContainerManager.ContainerMigrator +\u251c\u2500\u2500\u2524\u251c\u2500\u2500\u2524Migration Elapsed:00:00 seconds + +[2026-10-16 06:47:59 +0000] Status=4, isTerminal=NO, Elapsed=01:56. +\tWaiting on System App +`; + describe('simctl startup', () => { beforeEach(() => { @@ -22,6 +47,19 @@ describe('simctl startup', () => { ); }); + it('returns the last reported stage and elapsed time from bootstatus', async () => { + vi.spyOn(tools, 'spawn').mockResolvedValue({ + stdout: BOOTSTATUS_OUTPUT, + } as Awaited>); + + await expect( + waitForBoot('sim-udid', new AbortController().signal), + ).resolves.toEqual({ + lastStatusLine: 'Waiting on System App', + elapsedSeconds: 116, + }); + }); + it('runs simctl diagnose into the provided directory', async () => { const spawnSpy = vi .spyOn(tools, 'spawn') @@ -77,4 +115,65 @@ describe('simctl startup', () => { } ); }); + + it('counts only running guest processes, not loaded jobs without a PID', async () => { + const signal = new AbortController().signal; + const spawnSpy = vi.spyOn(tools, 'spawn').mockResolvedValue({ + stdout: + 'PID\tStatus\tLabel\n-\t0\tcom.apple.progressd\n95823\t0\tcom.apple.homed\n-\t78\tcom.apple.cloudphotod\n402\t0\tcom.apple.backboardd\n', + } as Awaited>); + + await expect(getGuestProcessCount('sim-udid', signal)).resolves.toBe(2); + expect(spawnSpy).toHaveBeenCalledWith( + 'xcrun', + ['simctl', 'spawn', 'sim-udid', 'launchctl', 'list'], + { timeout: 30_000, signal }, + ); + }); +}); + +describe('parseBootStatus', () => { + it('handles empty and unrecognised output', () => { + expect(parseBootStatus(undefined)).toEqual({ + lastStatusLine: null, + elapsedSeconds: null, + }); + expect(parseBootStatus('something else\n')).toEqual({ + lastStatusLine: null, + elapsedSeconds: null, + }); + }); + + it('reports the terminal stage once the boot has finished', () => { + expect( + parseBootStatus( + '[2026-10-16 06:48:02 +0000] Status=4294967295, isTerminal=YES, Elapsed=00:58.\n\tFinished\n', + ), + ).toEqual({ lastStatusLine: 'Finished', elapsedSeconds: 58 }); + }); +}); + +describe('simctl diagnostics attrs', () => { + it('describes a waitForBoot result and nothing else', () => { + expect( + simctlResultAttrs('waitForBoot', { + lastStatusLine: 'Finished', + elapsedSeconds: 58, + }), + ).toEqual({ bootLastStatus: 'Finished', bootElapsedSeconds: 58 }); + expect(simctlResultAttrs('bootSimulator', undefined)).toBeUndefined(); + }); + + it('recovers the stage a timed-out waitForBoot was stuck on', () => { + const error = Object.assign(Object.create(tools.SubprocessError.prototype), { + stdout: BOOTSTATUS_OUTPUT, + }); + + expect(simctlErrorAttrs('waitForBoot', error)).toEqual({ + bootLastStatus: 'Waiting on System App', + bootElapsedSeconds: 116, + }); + expect(simctlErrorAttrs('waitForBoot', new Error('x'))).toBeUndefined(); + expect(simctlErrorAttrs('bootSimulator', error)).toBeUndefined(); + }); }); diff --git a/packages/platform-ios/src/instance.ts b/packages/platform-ios/src/instance.ts index 429e9cf0..5aefeea3 100644 --- a/packages/platform-ios/src/instance.ts +++ b/packages/platform-ios/src/instance.ts @@ -15,6 +15,10 @@ import { assertAppleDeviceSimulator, } from './config.js'; import * as simctlModule from './xcrun/simctl.js'; +import { + simctlErrorAttrs, + simctlResultAttrs, +} from './xcrun/simctl-diagnostics.js'; import * as devicectlModule from './xcrun/devicectl.js'; import { getDeviceName } from './utils.js'; import { HarnessAppPathError } from './errors.js'; @@ -58,7 +62,8 @@ export const getAppleSimulatorPlatformInstance = async ( const simctl = instrumented( simctlModule, 'platform.ios.simctl', - init.diagnostics ?? noopDiagnostics + init.diagnostics ?? noopDiagnostics, + { resultAttrs: simctlResultAttrs, errorAttrs: simctlErrorAttrs } ); const permissionsEnabled = harnessConfig.permissions ?? false; @@ -234,6 +239,20 @@ export const getAppleSimulatorPlatformInstance = async ( outputDir: options.outputDir, }); }, + createTelemetryCollector: () => ({ + collect: async (phase, signal): Promise> => { + // Listing guest services costs a simctl round trip, so only do it at + // the boundaries where the guest's state is worth recording. + if (phase !== 'platform.ready' && phase !== 'dispose') { + return {}; + } + + return { + 'ios.simulator.guest_process_count': + await simctl.getGuestProcessCount(udid, signal), + }; + }, + }), }; }; diff --git a/packages/platform-ios/src/xcrun/simctl-diagnostics.ts b/packages/platform-ios/src/xcrun/simctl-diagnostics.ts new file mode 100644 index 00000000..7203c924 --- /dev/null +++ b/packages/platform-ios/src/xcrun/simctl-diagnostics.ts @@ -0,0 +1,29 @@ +import { SubprocessError, type DiagnosticAttrs } from '@react-native-harness/tools'; +import { parseBootStatus, type BootStatusSummary } from './simctl.js'; + +/** + * Describes simctl results and failures as span attrs. Handed to + * `instrumented()` so the simctl module itself stays free of diagnostics code. + */ +const toBootAttrs = (summary: BootStatusSummary): DiagnosticAttrs => ({ + bootLastStatus: summary.lastStatusLine ?? undefined, + bootElapsedSeconds: summary.elapsedSeconds ?? undefined, +}); + +export const simctlResultAttrs = ( + method: string, + result: unknown, +): DiagnosticAttrs | undefined => + method === 'waitForBoot' ? toBootAttrs(result as BootStatusSummary) : undefined; + +/** + * A boot that never finishes (timeout, abort) is the interesting case: the + * output captured up to that point still says which stage it was stuck on. + */ +export const simctlErrorAttrs = ( + method: string, + error: unknown, +): DiagnosticAttrs | undefined => + method === 'waitForBoot' && error instanceof SubprocessError + ? toBootAttrs(parseBootStatus(error.stdout)) + : undefined; diff --git a/packages/platform-ios/src/xcrun/simctl.ts b/packages/platform-ios/src/xcrun/simctl.ts index 720fd3b0..a602b689 100644 --- a/packages/platform-ios/src/xcrun/simctl.ts +++ b/packages/platform-ios/src/xcrun/simctl.ts @@ -340,13 +340,72 @@ export const bootSimulator = async (udid: string): Promise => { await spawn('xcrun', ['simctl', 'boot', udid]); }; +export type BootStatusSummary = { + /** The stage `simctl bootstatus` last reported, e.g. "Waiting on System App" or "Finished". */ + lastStatusLine: string | null; + /** The elapsed boot time (seconds) `simctl bootstatus` last reported. */ + elapsedSeconds: number | null; +}; + +const BOOT_STATUS_HEADER = + /^\[[^\]]*\]\s+Status=\d+,\s+isTerminal=\w+,\s+Elapsed=(\d+):(\d+)\./; + +/** + * Summarises the progress log printed by `simctl bootstatus`. It prints one + * block per update: a `[timestamp] Status=…, Elapsed=mm:ss.` header followed by + * indented lines, the first of which names the stage being waited on. + */ +export const parseBootStatus = (output: string | undefined): BootStatusSummary => { + let lastStatusLine: string | null = null; + let elapsedSeconds: number | null = null; + let expectStage = false; + + for (const line of (output ?? '').split('\n')) { + const header = BOOT_STATUS_HEADER.exec(line); + if (header) { + elapsedSeconds = Number(header[1]) * 60 + Number(header[2]); + expectStage = true; + continue; + } + + const stage = line.replace(/^[\s├─┤]+/u, '').trim(); + if (expectStage && stage) { + lastStatusLine = stage; + expectStage = false; + } + } + + return { lastStatusLine, elapsedSeconds }; +}; + export const waitForBoot = async ( udid: string, signal: AbortSignal, -): Promise => { - await spawn('xcrun', ['simctl', 'bootstatus', udid, '-b'], { +): Promise => { + const { stdout } = await spawn('xcrun', ['simctl', 'bootstatus', udid, '-b'], { signal, }); + return parseBootStatus(stdout); +}; + +const GUEST_PROCESS_LIST_TIMEOUT_MS = 30_000; + +/** + * Counts the processes running inside the simulator. `launchctl list` also + * lists loaded jobs that are not running (PID `-`); only rows with a numeric + * PID are live processes. A guest that is overloaded or still migrating shows + * up here long before anything fails. + */ +export const getGuestProcessCount = async ( + udid: string, + signal?: AbortSignal, +): Promise => { + const { stdout } = await spawn( + 'xcrun', + ['simctl', 'spawn', udid, 'launchctl', 'list'], + { timeout: GUEST_PROCESS_LIST_TIMEOUT_MS, signal }, + ); + return stdout.split('\n').filter((line) => /^\d+\s/.test(line)).length; }; export const diagnose = async ( diff --git a/packages/platforms/src/index.ts b/packages/platforms/src/index.ts index f15048bc..343ab3f7 100644 --- a/packages/platforms/src/index.ts +++ b/packages/platforms/src/index.ts @@ -21,6 +21,7 @@ export type { HarnessPlatformRunnerFactory, CollectNativeCoverageOptions, HarnessPlatformRunner, + TelemetryCollector, RunTarget, VegaAppLaunchOptions, WebAppLaunchOptions, diff --git a/packages/platforms/src/types.ts b/packages/platforms/src/types.ts index 6eb1ebcc..afdc0b38 100644 --- a/packages/platforms/src/types.ts +++ b/packages/platforms/src/types.ts @@ -1,4 +1,6 @@ -import type { Diagnostics } from '@react-native-harness/tools'; +import type { Diagnostics, TelemetryCollector } from '@react-native-harness/tools'; + +export type { TelemetryCollector }; export type CrashArtifactKind = | 'logcat' @@ -125,6 +127,12 @@ export type HarnessPlatformRunner = { collectNativeCoverage?: ( options: CollectNativeCoverageOptions ) => Promise; + /** + * Optional. Supplies platform-specific run telemetry (for example the number + * of processes inside a simulator). Harness calls it at run lifecycle phases + * when diagnostics are enabled; runners never record diagnostics themselves. + */ + createTelemetryCollector?: () => TelemetryCollector; }; export type HarnessPlatformInitOptions = { diff --git a/packages/tools/src/__tests__/diagnostics.test.ts b/packages/tools/src/__tests__/diagnostics.test.ts index f0f6f901..2d7c5220 100644 --- a/packages/tools/src/__tests__/diagnostics.test.ts +++ b/packages/tools/src/__tests__/diagnostics.test.ts @@ -110,6 +110,85 @@ describe('createDiagnostics (enabled)', () => { expect(diagnostics.flush()).toHaveLength(1); expect(diagnostics.flush()).toHaveLength(0); }); + + it('gauge() records a numeric sample with namespace, attrs and unit', () => { + const diagnostics = createDiagnostics({ enabled: true }); + diagnostics + .child('host') + .child({ runId: 'run-1' }) + .gauge('load1', 4.5, { source: 'os' }, 'load'); + + const entries = diagnostics.flush(); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + label: 'host.load1', + kind: 'gauge', + value: 4.5, + unit: 'load', + duration: 0, + status: 'ok', + attrs: { runId: 'run-1', source: 'os' }, + }); + }); + + it('gauge() omits unit when none is given', () => { + const diagnostics = createDiagnostics({ enabled: true }); + diagnostics.gauge('x', 1); + + expect(diagnostics.flush()[0]).not.toHaveProperty('unit'); + }); + + it('subscribe() observes entries from children without consuming them', () => { + const diagnostics = createDiagnostics({ enabled: true }); + const seen: string[] = []; + const unsubscribe = diagnostics.subscribe((entry) => seen.push(entry.label)); + + diagnostics.mark('a'); + diagnostics.child('ns').gauge('b', 2); + diagnostics.start('c').end(); + unsubscribe(); + diagnostics.mark('after-unsubscribe'); + + expect(seen).toEqual(['a', 'ns.b', 'c']); + expect(diagnostics.flush()).toHaveLength(4); + }); + + it('subscribe({ replay }) delivers already recorded, unflushed entries first', () => { + const diagnostics = createDiagnostics({ enabled: true }); + diagnostics.mark('flushed'); + diagnostics.flush(); + diagnostics.mark('early-1'); + diagnostics.child('ns').gauge('early-2', 1); + const seen: string[] = []; + + diagnostics.subscribe((entry) => seen.push(entry.label), { replay: true }); + diagnostics.mark('late'); + + expect(seen).toEqual(['early-1', 'ns.early-2', 'late']); + }); + + it('subscribe() without replay only sees later entries', () => { + const diagnostics = createDiagnostics({ enabled: true }); + diagnostics.mark('early'); + const seen: string[] = []; + + diagnostics.subscribe((entry) => seen.push(entry.label)); + + expect(seen).toEqual([]); + }); + + it('subscribe() isolates listener failures from the observed code', () => { + const diagnostics = createDiagnostics({ enabled: true }); + const seen: string[] = []; + diagnostics.subscribe(() => { + throw new Error('sink down'); + }); + diagnostics.subscribe((entry) => seen.push(entry.label)); + + expect(() => diagnostics.mark('a')).not.toThrow(); + expect(seen).toEqual(['a']); + expect(diagnostics.flush()).toHaveLength(1); + }); }); describe('createDiagnostics (disabled)', () => { @@ -125,10 +204,21 @@ describe('createDiagnostics (disabled)', () => { span.end(); span.fail(new Error('x')); diagnostics.mark('foo'); + diagnostics.gauge('foo', 1); diagnostics.record({ label: 'foo', duration: 10 }); expect(diagnostics.flush()).toEqual([]); }); + it('subscribe() never calls the listener and returns a callable disposer', () => { + const diagnostics = createDiagnostics({ enabled: false }); + const listener = vi.fn(); + const dispose = diagnostics.subscribe(listener); + + diagnostics.mark('foo'); + expect(listener).not.toHaveBeenCalled(); + expect(() => dispose()).not.toThrow(); + }); + it('defaults to disabled when no options are passed', () => { const diagnostics = createDiagnostics(); expect(diagnostics.enabled).toBe(false); @@ -271,4 +361,61 @@ describe('instrumented()', () => { expect(spy).toHaveBeenCalledTimes(2); }); + + it('adds attrs derived from the resolved value of an async method', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const target = { wait: async () => ({ lastStatusLine: 'Finished' }) }; + const wrapped = instrumented(target, 'ns', diagnostics, { + resultAttrs: (method, result) => + method === 'wait' + ? { last: (result as { lastStatusLine: string }).lastStatusLine } + : undefined, + }); + + await wrapped.wait(); + await wait(1); + + expect(diagnostics.flush()[0]?.attrs).toEqual({ last: 'Finished' }); + }); + + it('adds attrs derived from the result of a sync method', () => { + const diagnostics = createDiagnostics({ enabled: true }); + const wrapped = instrumented({ count: () => 3 }, 'ns', diagnostics, { + resultAttrs: (_method, result) => ({ count: result as number }), + }); + + wrapped.count(); + + expect(diagnostics.flush()[0]?.attrs).toEqual({ count: 3 }); + }); + + it('adds attrs derived from a rejection and tolerates a throwing deriver', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const target = { + failing: async () => { + throw new Error('timed out'); + }, + other: async () => 'x', + }; + const wrapped = instrumented(target, 'ns', diagnostics, { + errorAttrs: (method) => { + if (method === 'other') { + throw new Error('deriver bug'); + } + return { stage: 'Waiting on Data Migration' }; + }, + resultAttrs: () => { + throw new Error('deriver bug'); + }, + }); + + await expect(wrapped.failing()).rejects.toThrow('timed out'); + await expect(wrapped.other()).resolves.toBe('x'); + await wait(1); + + const [failed, ok] = diagnostics.flush(); + expect(failed?.status).toBe('error'); + expect(failed?.attrs).toMatchObject({ stage: 'Waiting on Data Migration' }); + expect(ok?.status).toBe('ok'); + }); }); diff --git a/packages/tools/src/diagnostics.ts b/packages/tools/src/diagnostics.ts index 382a287e..ea66e7bd 100644 --- a/packages/tools/src/diagnostics.ts +++ b/packages/tools/src/diagnostics.ts @@ -6,9 +6,15 @@ export type DiagnosticEntry = { duration: number; // ms attrs?: DiagnosticAttrs; status: 'ok' | 'error'; - kind: 'span' | 'mark'; + kind: 'span' | 'mark' | 'gauge'; + /** Numeric sample, set only on `gauge` entries. */ + value?: number; + /** Optional unit of `value` (for example `MB` or `%`), `gauge` entries only. */ + unit?: string; }; +export type DiagnosticEntryListener = (entry: DiagnosticEntry) => void; + export type DiagnosticSpan = { end(attrs?: DiagnosticAttrs): void; fail(error: unknown, attrs?: DiagnosticAttrs): void; @@ -26,8 +32,22 @@ export type Diagnostics = { start(label: string, attrs?: DiagnosticAttrs): DiagnosticSpan; measure(label: string, fn: () => T | Promise, attrs?: DiagnosticAttrs): Promise; mark(label: string, attrs?: DiagnosticAttrs): void; + /** Records a numeric sample (a point on a time series) at the current time. */ + gauge(label: string, value: number, attrs?: DiagnosticAttrs, unit?: string): void; record(entry: DiagnosticRecordInput): void; child(nsOrAttrs: string | DiagnosticAttrs): Diagnostics; + /** + * Observes every entry as it is recorded, including entries recorded through + * child instances. Unlike `flush()`, subscribing does not consume entries, so + * a sink can persist them incrementally. With `replay`, entries already + * recorded and not yet flushed are delivered to the listener first, so a sink + * attached late still sees the start of the session. Returns a function that + * unsubscribes. + */ + subscribe( + listener: DiagnosticEntryListener, + options?: { replay?: boolean } + ): () => void; flush(): DiagnosticEntry[]; }; @@ -64,8 +84,10 @@ const createNoopDiagnostics = (): Diagnostics => { start: () => noopSpan, measure: async (_label, fn) => fn(), mark: noop, + gauge: noop, record: noop, child: () => diagnostics, + subscribe: () => noop, flush: () => [], }; @@ -76,6 +98,7 @@ export const noopDiagnostics: Diagnostics = createNoopDiagnostics(); type RootState = { entries: DiagnosticEntry[]; + listeners: Set; epochAnchor: number; perfAnchor: number; }; @@ -93,6 +116,13 @@ const createEnabledDiagnostics = ( const pushEntry = (entry: DiagnosticEntry) => { state.entries.push(entry); + for (const listener of state.listeners) { + try { + listener(entry); + } catch { + // A faulty sink must never break the code being observed. + } + } }; const start = (label: string, attrs?: DiagnosticAttrs): DiagnosticSpan => { @@ -162,6 +192,24 @@ const createEnabledDiagnostics = ( }); }; + const gauge = ( + label: string, + value: number, + attrs?: DiagnosticAttrs, + unit?: string + ): void => { + pushEntry({ + label: prefixLabel(label), + startTime: now(state), + duration: 0, + attrs: mergeAttrs(inheritedAttrs, attrs), + status: 'ok', + kind: 'gauge', + value, + ...(unit === undefined ? {} : { unit }), + }); + }; + const record = (entry: DiagnosticRecordInput): void => { pushEntry({ label: prefixLabel(entry.label), @@ -186,6 +234,21 @@ const createEnabledDiagnostics = ( ); }; + const subscribe = ( + listener: DiagnosticEntryListener, + options?: { replay?: boolean } + ): (() => void) => { + if (options?.replay) { + for (const entry of [...state.entries]) { + listener(entry); + } + } + state.listeners.add(listener); + return () => { + state.listeners.delete(listener); + }; + }; + const flush = (): DiagnosticEntry[] => { const flushed = state.entries; state.entries = []; @@ -197,8 +260,10 @@ const createEnabledDiagnostics = ( start, measure, mark, + gauge, record, child, + subscribe, flush, }; }; @@ -210,6 +275,7 @@ export const createDiagnostics = (options?: { enabled?: boolean }): Diagnostics const state: RootState = { entries: [], + listeners: new Set(), epochAnchor: Date.now(), perfAnchor: performance.now(), }; @@ -217,10 +283,38 @@ export const createDiagnostics = (options?: { enabled?: boolean }): Diagnostics return createEnabledDiagnostics(state, '', undefined); }; +export type InstrumentedOptions = { + /** + * Derives extra span attrs from a method's resolved return value, so a + * wrapped module can surface facts about its result (for example the last + * status line of a long wait) without calling diagnostics itself. + */ + resultAttrs?: (method: string, result: unknown) => DiagnosticAttrs | undefined; + /** Same as `resultAttrs`, for the error a method rejected or threw with. */ + errorAttrs?: (method: string, error: unknown) => DiagnosticAttrs | undefined; +}; + +const safeAttrs = ( + derive: ((method: string, value: TValue) => DiagnosticAttrs | undefined) | undefined, + method: string, + value: TValue +): DiagnosticAttrs | undefined => { + if (!derive) { + return undefined; + } + + try { + return derive(method, value); + } catch { + return undefined; + } +}; + export const instrumented = ( target: T, ns: string, - diagnostics: Diagnostics + diagnostics: Diagnostics, + options?: InstrumentedOptions ): T => { if (!diagnostics.enabled) { return target; @@ -242,13 +336,14 @@ export const instrumented = ( } const wrappedFn = (...args: unknown[]) => { - const span = diagnostics.start(`${ns}.${String(prop)}`); + const method = String(prop); + const span = diagnostics.start(`${ns}.${method}`); let result: unknown; try { result = value.apply(obj, args); } catch (error) { - span.fail(error); + span.fail(error, safeAttrs(options?.errorAttrs, method, error)); throw error; } @@ -265,13 +360,15 @@ export const instrumented = ( // and silently drop that shape, so track the span as a side // effect and always return the original object untouched. (result as Promise).then( - () => span.end(), - (error: unknown) => span.fail(error) + (value: unknown) => + span.end(safeAttrs(options?.resultAttrs, method, value)), + (error: unknown) => + span.fail(error, safeAttrs(options?.errorAttrs, method, error)) ); return result; } - span.end(); + span.end(safeAttrs(options?.resultAttrs, method, result)); return result; }; diff --git a/packages/tools/src/index.ts b/packages/tools/src/index.ts index bfc0823b..7aaf52ac 100644 --- a/packages/tools/src/index.ts +++ b/packages/tools/src/index.ts @@ -19,4 +19,6 @@ export * from './isInteractive.js'; export * from './diagnostics.js'; export * from './device-core-budget.js'; export * from './host-capabilities.js'; +export * from './unref-timer.js'; export * from './harness-context.js'; +export * from './telemetry/index.js'; diff --git a/packages/tools/src/telemetry/__tests__/helpers.ts b/packages/tools/src/telemetry/__tests__/helpers.ts new file mode 100644 index 00000000..e2304390 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/helpers.ts @@ -0,0 +1,37 @@ +import { vi } from 'vitest'; +import { createDiagnostics } from '../../diagnostics.js'; +import { getEmitter } from '../../events.js'; +import type { LifecycleEvent, ProbeContext } from '../types.js'; + +export const createProbeContext = ( + overrides: Partial = {} +): ProbeContext & { + controller: AbortController; + pending: Set>; +} => { + const controller = new AbortController(); + const pending = new Set>(); + + return { + diagnostics: createDiagnostics({ enabled: true }), + signal: controller.signal, + lifecycle: getEmitter(), + sampleIntervalMs: 5000, + track: (work) => { + pending.add(work); + return work; + }, + controller, + pending, + ...overrides, + }; +}; + +/** Waits for all work registered through `ctx.track`. */ +export const settle = async (ctx: { pending: Set> }) => { + await Promise.allSettled([...ctx.pending]); +}; + +export const setPlatform = (platform: NodeJS.Platform) => { + vi.spyOn(process, 'platform', 'get').mockReturnValue(platform); +}; diff --git a/packages/tools/src/telemetry/__tests__/host-resources.test.ts b/packages/tools/src/telemetry/__tests__/host-resources.test.ts new file mode 100644 index 00000000..58e896cd --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/host-resources.test.ts @@ -0,0 +1,301 @@ +import os from 'node:os'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { + diffCpuTimes, + hostResourcesProbe, + parseProcMeminfo, + parseVmStat, +} from '../host-resources.js'; +import { spawn } from '../../spawn.js'; +import { createProbeContext, setPlatform } from './helpers.js'; + +vi.mock('../../spawn.js', () => ({ spawn: vi.fn() })); + +// Captured from a real macOS 26 machine under load. +const VM_STAT_FIXTURE = `Mach Virtual Memory Statistics: (page size of 16384 bytes) +Pages free: 86397. +Pages active: 504004. +Pages inactive: 502069. +Pages speculative: 1676. +Pages throttled: 0. +Pages wired down: 273327. +Pages purgeable: 7910. +"Translation faults": 18231809846. +Pages copy-on-write: 662114877. +Pages zero filled: 6415585096. +Pages reactivated: 3744162215. +Pages purged: 372034680. +File-backed pages: 343914. +Anonymous pages: 663835. +Pages stored in compressor: 2682589. +Pages occupied by compressor: 938001. +Decompressions: 4366165984. +Compressions: 4681060812. +Pageins: 537224043. +Pageouts: 9405118. +Swapins: 23243815. +Swapouts: 27729919. +`; + +const pagesToMb = (pages: number, pageSize = 16384) => + (pages * pageSize) / (1024 * 1024); + +describe('parseVmStat', () => { + it('derives MB values using the page size from the header', () => { + expect(parseVmStat(VM_STAT_FIXTURE)).toEqual({ + freeMb: pagesToMb(86397), + anonymousMb: pagesToMb(663835), + wiredMb: pagesToMb(273327), + compressedMb: pagesToMb(938001), + demandMb: pagesToMb(663835 + 273327 + 938001), + swapoutsMb: pagesToMb(27729919), + compressionsMb: pagesToMb(4681060812), + }); + }); + + it('honours a 4 KiB page size', () => { + const output = VM_STAT_FIXTURE.replace('16384', '4096'); + expect(parseVmStat(output)?.freeMb).toBe(pagesToMb(86397, 4096)); + }); + + it('returns null for unrecognised or incomplete output', () => { + expect(parseVmStat('')).toBeNull(); + expect(parseVmStat('vm_stat: command not found')).toBeNull(); + expect( + parseVmStat( + 'Mach Virtual Memory Statistics: (page size of 16384 bytes)\nPages free: 1.' + ) + ).toBeNull(); + }); +}); + +describe('parseProcMeminfo', () => { + it('reads free and available memory in MB', () => { + const content = + 'MemTotal: 16384000 kB\nMemFree: 2048 kB\nMemAvailable: 4096 kB\n'; + expect(parseProcMeminfo(content)).toEqual({ freeMb: 2, availableMb: 4 }); + }); + + it('tolerates a missing MemAvailable and returns null without MemFree', () => { + expect(parseProcMeminfo('MemFree: 1024 kB\n')).toEqual({ + freeMb: 1, + availableMb: null, + }); + expect(parseProcMeminfo('nope')).toBeNull(); + }); +}); + +describe('diffCpuTimes', () => { + it('splits the interval into user, sys and idle percentages', () => { + const usage = diffCpuTimes( + { user: 100, sys: 50, idle: 850 }, + { user: 200, sys: 100, idle: 1700 } + ); + expect(usage?.userPct).toBeCloseTo((100 / 1000) * 100); + expect(usage?.sysPct).toBeCloseTo(5); + expect(usage?.idlePct).toBeCloseTo(85); + }); + + it('returns null when no time elapsed', () => { + const times = { user: 1, sys: 1, idle: 1 }; + expect(diffCpuTimes(times, times)).toBeNull(); + }); +}); + +describe('hostResourcesProbe', () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.mocked(spawn).mockReset(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + const gaugeLabels = (ctx: ReturnType) => + ctx.diagnostics.flush().map((entry) => entry.label); + + it('samples load, cpu and vm_stat memory on darwin, on every interval', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: VM_STAT_FIXTURE } as never); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + // The first sample has no CPU baseline to diff against, so no cpu gauges. + const first = gaugeLabels(ctx); + expect(first).toEqual([ + 'host.load1', + 'host.mem.free', + 'host.mem.anonymous', + 'host.mem.wired', + 'host.mem.compressed', + 'host.mem.demand', + 'host.mem.swapouts', + 'host.mem.compressions', + ]); + + await vi.advanceTimersByTimeAsync(5000); + expect(spawn).toHaveBeenCalledTimes(2); + expect(vi.mocked(spawn).mock.calls[0]?.[0]).toBe('vm_stat'); + + stop(); + }); + + it('emits memory values as MB gauges with a demand metric', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: VM_STAT_FIXTURE } as never); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + const gauges = Object.fromEntries( + ctx.diagnostics.flush().map((entry) => [entry.label, entry.value]) + ); + expect(gauges['host.mem.compressed']).toBe(pagesToMb(938001)); + expect(gauges['host.mem.demand']).toBe( + (gauges['host.mem.anonymous'] as number) + + (gauges['host.mem.wired'] as number) + + (gauges['host.mem.compressed'] as number) + ); + stop(); + }); + + it('skips a tick while the previous sample is still running', async () => { + setPlatform('darwin'); + let resolveSpawn: (value: unknown) => void = () => undefined; + vi.mocked(spawn).mockImplementation( + () => new Promise((resolve) => (resolveSpawn = resolve)) as never + ); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(20_000); + expect(spawn).toHaveBeenCalledTimes(1); + + resolveSpawn({ stdout: VM_STAT_FIXTURE }); + await vi.advanceTimersByTimeAsync(5000); + expect(spawn).toHaveBeenCalledTimes(2); + stop(); + }); + + it('emits cpu split gauges from the second sample on', async () => { + setPlatform('win32'); + const cpu = (user: number, sys: number, idle: number) => + [{ times: { user, nice: 0, sys, idle, irq: 0 } }] as never; + vi.spyOn(os, 'cpus') + .mockReturnValueOnce(cpu(100, 50, 850)) + .mockReturnValueOnce(cpu(200, 100, 1700)); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + expect(gaugeLabels(ctx)).not.toContain('host.cpu.user_pct'); + + await vi.advanceTimersByTimeAsync(5000); + const gauges = Object.fromEntries( + ctx.diagnostics.flush().map((entry) => [entry.label, entry.value]) + ); + expect(gauges['host.cpu.user_pct']).toBeCloseTo(10); + expect(gauges['host.cpu.sys_pct']).toBeCloseTo(5); + expect(gauges['host.cpu.idle_pct']).toBeCloseTo(85); + stop(); + }); + + it('pauses between runs and resumes with a fresh cpu baseline', async () => { + setPlatform('win32'); + const cpu = (user: number, sys: number, idle: number) => + [{ times: { user, nice: 0, sys, idle, irq: 0 } }] as never; + vi.spyOn(os, 'cpus') + .mockReturnValueOnce(cpu(100, 50, 850)) + .mockReturnValueOnce(cpu(300, 100, 1000)) + .mockReturnValueOnce(cpu(10_000, 5_000, 90_000)); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + ctx.lifecycle.emit({ type: 'phase', phase: 'run.end' }); + ctx.diagnostics.flush(); + + await vi.advanceTimersByTimeAsync(60_000); + expect(ctx.diagnostics.flush()).toEqual([]); + + ctx.lifecycle.emit({ type: 'phase', phase: 'run.start' }); + await vi.advanceTimersByTimeAsync(0); + // First sample after the pause: no cpu gauges (the gap was idle time). + expect(gaugeLabels(ctx)).toEqual(['host.load1', 'host.mem.free']); + + stop(); + }); + + it('resumes sampling on dispose, so teardown is still observed', async () => { + setPlatform('win32'); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + ctx.lifecycle.emit({ type: 'phase', phase: 'run.end' }); + ctx.diagnostics.flush(); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await vi.advanceTimersByTimeAsync(0); + + expect(gaugeLabels(ctx)).toContain('host.load1'); + stop(); + }); + + it('stops sampling after the returned stop function is called', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: VM_STAT_FIXTURE } as never); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + stop(); + ctx.diagnostics.flush(); + + await vi.advanceTimersByTimeAsync(30_000); + expect(spawn).toHaveBeenCalledTimes(1); + expect(ctx.diagnostics.flush()).toEqual([]); + }); + + it('stops sampling when the signal aborts', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: VM_STAT_FIXTURE } as never); + const ctx = createProbeContext(); + + hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + ctx.controller.abort(); + + await vi.advanceTimersByTimeAsync(30_000); + expect(spawn).toHaveBeenCalledTimes(1); + }); + + it('falls back to os.freemem and never spawns on other platforms', async () => { + setPlatform('win32'); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + expect(spawn).not.toHaveBeenCalled(); + expect(gaugeLabels(ctx)).toEqual(['host.load1', 'host.mem.free']); + stop(); + }); + + it('falls back to os.freemem when vm_stat fails', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockRejectedValue(new Error('spawn vm_stat ENOENT')); + const ctx = createProbeContext(); + + const stop = hostResourcesProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + expect(gaugeLabels(ctx)).toEqual(['host.load1', 'host.mem.free']); + stop(); + }); +}); diff --git a/packages/tools/src/telemetry/__tests__/index.test.ts b/packages/tools/src/telemetry/__tests__/index.test.ts new file mode 100644 index 00000000..85c022ea --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/index.test.ts @@ -0,0 +1,183 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { createDiagnostics } from '../../diagnostics.js'; +import { createDefaultProbes, startTelemetryProbes } from '../index.js'; +import { spawn } from '../../spawn.js'; +import type { TelemetryProbe } from '../types.js'; +import { createProbeContext } from './helpers.js'; + +vi.mock('../../spawn.js', () => ({ spawn: vi.fn() })); + +describe('startTelemetryProbes', () => { + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it('starts nothing when diagnostics are disabled', async () => { + const setIntervalSpy = vi.spyOn(globalThis, 'setInterval'); + const { signal, lifecycle } = createProbeContext(); + const start = vi.fn(() => () => undefined); + + const run = startTelemetryProbes( + [ + { name: 'spy', start }, + ...createDefaultProbes({ platform: { getCollector: () => undefined } }), + ], + { + diagnostics: createDiagnostics({ enabled: false }), + signal, + lifecycle, + sampleIntervalMs: 5000, + } + ); + lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await run.settled(); + await run.dispose(); + + expect(start).not.toHaveBeenCalled(); + expect(setIntervalSpy).not.toHaveBeenCalled(); + expect(spawn).not.toHaveBeenCalled(); + }); + + it('starts every probe and stops them all on dispose, once', async () => { + const stopA = vi.fn(); + const stopB = vi.fn().mockResolvedValue(undefined); + const probes: TelemetryProbe[] = [ + { name: 'a', start: () => stopA }, + { name: 'b', start: () => stopB }, + ]; + const ctx = createProbeContext(); + + const run = startTelemetryProbes(probes, ctx); + await run.dispose(); + await run.dispose(); + + expect(stopA).toHaveBeenCalledTimes(1); + expect(stopB).toHaveBeenCalledTimes(1); + }); + + it('isolates probes that fail to start or to stop', async () => { + const goodStop = vi.fn(); + const probes: TelemetryProbe[] = [ + { + name: 'broken-start', + start: () => { + throw new Error('nope'); + }, + }, + { + name: 'broken-stop', + start: () => () => { + throw new Error('nope'); + }, + }, + { name: 'good', start: () => goodStop }, + ]; + const ctx = createProbeContext(); + + const run = startTelemetryProbes(probes, ctx); + await expect(run.dispose()).resolves.toBeUndefined(); + + expect(goodStop).toHaveBeenCalled(); + }); + + it('exposes in-flight tracked work through settled()', async () => { + vi.useFakeTimers(); + let finished = false; + const probe: TelemetryProbe = { + name: 'slow', + start: (ctx) => { + void ctx.track( + new Promise((resolve) => + setTimeout(() => { + finished = true; + resolve(); + }, 10) + ) + ); + return () => undefined; + }, + }; + const ctx = createProbeContext(); + + const run = startTelemetryProbes([probe], ctx); + expect(finished).toBe(false); + const settled = run.settled(); + await vi.advanceTimersByTimeAsync(10); + await settled; + + expect(finished).toBe(true); + }); + + const slowProbe = (durationMs: number): TelemetryProbe => ({ + name: 'slow', + start: (ctx) => { + void ctx.track( + new Promise((resolve) => setTimeout(resolve, durationMs)) + ); + return () => undefined; + }, + }); + + it('dispose() does not wait for work that was already aborted', async () => { + vi.useFakeTimers(); + const ctx = createProbeContext(); + const run = startTelemetryProbes([slowProbe(4_000)], ctx); + + ctx.controller.abort(); + let disposed = false; + void run.dispose().then(() => (disposed = true)); + await vi.advanceTimersByTimeAsync(0); + + expect(disposed).toBe(true); + }); + + it('dispose() bounds how long it waits for work that was not aborted', async () => { + vi.useFakeTimers(); + const ctx = createProbeContext(); + const run = startTelemetryProbes([slowProbe(600_000)], ctx); + + let disposed = false; + void run.dispose().then(() => (disposed = true)); + await vi.advanceTimersByTimeAsync(4_000); + expect(disposed).toBe(false); + await vi.advanceTimersByTimeAsync(1_500); + expect(disposed).toBe(true); + }); + + it('does not start probes for an already aborted signal', () => { + const start = vi.fn(() => () => undefined); + const ctx = createProbeContext(); + const { controller } = ctx; + controller.abort(); + + startTelemetryProbes([{ name: 'x', start }], ctx); + + expect(start).not.toHaveBeenCalled(); + }); +}); + +describe('createDefaultProbes', () => { + const names = (options?: Parameters[0]) => + createDefaultProbes(options).map((probe) => probe.name); + + it('enables the generic probes by default and leaves the platform one out', () => { + expect(names()).toEqual([ + 'run-context', + 'host-resources', + 'node-runtime', + 'process-snapshot', + ]); + }); + + it('honours per-probe switches and adds the platform collector on request', () => { + expect( + names({ + host: false, + node: false, + snapshots: false, + platform: { getCollector: () => undefined }, + }) + ).toEqual(['run-context', 'platform-collector']); + }); +}); diff --git a/packages/tools/src/telemetry/__tests__/node-runtime.test.ts b/packages/tools/src/telemetry/__tests__/node-runtime.test.ts new file mode 100644 index 00000000..deae4fce --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/node-runtime.test.ts @@ -0,0 +1,90 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { nodeRuntimeProbe } from '../node-runtime.js'; +import { createProbeContext } from './helpers.js'; + +const histogram = vi.hoisted(() => ({ + enable: vi.fn(), + disable: vi.fn(), + reset: vi.fn(), + percentile: vi.fn(), + count: 0, + max: 0, +})); + +vi.mock('node:perf_hooks', () => ({ + monitorEventLoopDelay: () => histogram, +})); + +describe('nodeRuntimeProbe', () => { + beforeEach(() => { + vi.useFakeTimers(); + histogram.count = 10; + histogram.max = 270e6; // 270ms between ticks = 250ms of lag at a 20ms resolution + histogram.percentile.mockImplementation((p: number) => + p === 50 ? 21e6 : 120e6 + ); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.clearAllMocks(); + }); + + it('emits process memory and event loop lag gauges every interval', async () => { + const ctx = createProbeContext(); + + const stop = nodeRuntimeProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + const gauges = Object.fromEntries( + ctx.diagnostics.flush().map((entry) => [entry.label, entry.value]) + ); + expect(Object.keys(gauges)).toEqual([ + 'node.rss_mb', + 'node.heap_used_mb', + 'node.heap_total_mb', + 'node.external_mb', + 'node.event_loop.p50_ms', + 'node.event_loop.p99_ms', + 'node.event_loop.max_ms', + ]); + expect(gauges['node.rss_mb']).toBeGreaterThan(0); + expect(gauges['node.event_loop.p50_ms']).toBeCloseTo(1); + expect(gauges['node.event_loop.p99_ms']).toBeCloseTo(100); + expect(gauges['node.event_loop.max_ms']).toBeCloseTo(250); + + await vi.advanceTimersByTimeAsync(5000); + expect(histogram.reset).toHaveBeenCalledTimes(2); + expect(ctx.diagnostics.flush().length).toBe(7); + + stop(); + }); + + it('omits lag gauges while the histogram has no data', async () => { + histogram.count = 0; + const ctx = createProbeContext(); + + const stop = nodeRuntimeProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + + expect( + ctx.diagnostics + .flush() + .filter((e) => e.label.startsWith('node.event_loop')) + ).toEqual([]); + stop(); + }); + + it('disables the histogram and stops sampling when stopped', async () => { + const ctx = createProbeContext(); + + const stop = nodeRuntimeProbe.start(ctx); + await vi.advanceTimersByTimeAsync(0); + stop(); + ctx.diagnostics.flush(); + + await vi.advanceTimersByTimeAsync(20_000); + expect(histogram.disable).toHaveBeenCalled(); + expect(ctx.diagnostics.flush()).toEqual([]); + }); +}); diff --git a/packages/tools/src/telemetry/__tests__/platform-collector.test.ts b/packages/tools/src/telemetry/__tests__/platform-collector.test.ts new file mode 100644 index 00000000..ec03e0a2 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/platform-collector.test.ts @@ -0,0 +1,134 @@ +import { describe, expect, it, vi } from 'vitest'; +import { createPlatformCollectorProbe } from '../platform-collector.js'; +import type { TelemetryCollector } from '../types.js'; +import { createProbeContext, settle } from './helpers.js'; + +describe('platform collector probe', () => { + it('emits numeric values as platform gauges and strings as mark attrs', async () => { + const collector: TelemetryCollector = { + collect: vi.fn().mockResolvedValue({ + 'ios.simulator.guest_process_count': 312, + 'ios.simulator.runtime': 'iOS 26.4', + }), + }; + const ctx = createProbeContext(); + createPlatformCollectorProbe({ getCollector: () => collector }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + await settle(ctx); + + expect(collector.collect).toHaveBeenCalledWith( + 'platform.ready', + expect.any(AbortSignal) + ); + const [gauge, mark] = ctx.diagnostics.flush(); + expect(gauge).toMatchObject({ + label: 'platform.ios.simulator.guest_process_count', + kind: 'gauge', + value: 312, + attrs: { phase: 'platform.ready' }, + }); + expect(mark).toMatchObject({ + label: 'telemetry.platform', + kind: 'mark', + attrs: { phase: 'platform.ready', 'ios.simulator.runtime': 'iOS 26.4' }, + }); + }); + + it('resolves the collector lazily, once, and only on collector phases', async () => { + const collector: TelemetryCollector = { + collect: vi.fn().mockResolvedValue({ a: 1 }), + }; + const getCollector = vi.fn(() => collector); + const ctx = createProbeContext(); + createPlatformCollectorProbe({ getCollector }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'metro.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'test-file.start' }); + await settle(ctx); + expect(getCollector).not.toHaveBeenCalled(); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + await settle(ctx); + + expect(getCollector).toHaveBeenCalledTimes(1); + expect(collector.collect).toHaveBeenCalledTimes(2); + }); + + it('does nothing when the platform has no collector', async () => { + const ctx = createProbeContext(); + createPlatformCollectorProbe({ getCollector: () => undefined }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + + expect(ctx.diagnostics.flush()).toEqual([]); + }); + + it('survives a failing collector and disposes it when stopped', async () => { + const collector: TelemetryCollector = { + collect: vi.fn().mockRejectedValue(new Error('simctl down')), + dispose: vi.fn(), + }; + const ctx = createProbeContext(); + const stop = createPlatformCollectorProbe({ + getCollector: () => collector, + }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + await settle(ctx); + expect(ctx.diagnostics.flush()).toEqual([]); + + await stop(); + expect(collector.dispose).toHaveBeenCalled(); + }); + + it('aborts the signal handed to collect when stopped, and never collects afterwards', async () => { + let received: AbortSignal | undefined; + const collect = vi.fn( + (_phase: string, signal: AbortSignal) => + new Promise>((resolve) => { + received = signal; + signal.addEventListener('abort', () => resolve({ a: 1 })); + }) + ); + const collector: TelemetryCollector = { collect, dispose: vi.fn() }; + const ctx = createProbeContext(); + const stop = createPlatformCollectorProbe({ + getCollector: () => collector, + }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await Promise.resolve(); + expect(received?.aborted).toBe(false); + + await stop(); + await settle(ctx); + + expect(received?.aborted).toBe(true); + // The queued dispose collection never ran, and the aborted one reported nothing. + expect(collect).toHaveBeenCalledTimes(1); + expect(ctx.diagnostics.flush()).toEqual([]); + }); + + it('aborts the collect signal when the context signal aborts', async () => { + let received: AbortSignal | undefined; + const collector: TelemetryCollector = { + collect: vi.fn(async (_phase, signal) => { + received = signal; + return {}; + }), + }; + const ctx = createProbeContext(); + createPlatformCollectorProbe({ getCollector: () => collector }).start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + await settle(ctx); + ctx.controller.abort(); + + expect(received?.aborted).toBe(true); + }); +}); diff --git a/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts b/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts new file mode 100644 index 00000000..a0d90fb6 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts @@ -0,0 +1,242 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { parseTopOutput, processSnapshotProbe } from '../process-snapshot.js'; +import { spawn } from '../../spawn.js'; +import { createProbeContext, setPlatform, settle } from './helpers.js'; + +vi.mock('../../spawn.js', () => ({ spawn: vi.fn() })); + +// Captured from `top -l 1 -o mem -stats pid,mem,command -n 8` on macOS 26. +const TOP_FIXTURE = `Processes: 937 total, 4 running, 933 sleeping, 7907 threads +2026/10/16 08:41:16 +Load Avg: 8.81, 5.21, 4.67 +CPU usage: 23.55% user, 22.0% sys, 54.44% idle +SharedLibs: 750M resident, 109M data, 105M linkedit. +MemRegions: 703996 total, 9356M resident, 90M private, 3058M shared. +PhysMem: 34G used (4423M wired, 14G compressor), 1288M unused. +VM: 428T vsize, 6144M framework vsize, 23243815(0) swapins, 27729919(0) swapouts. +Networks: packets: 390438705/1106G in, 191447031/913G out. +Disks: 834043493/11T read, 526855368/8667G written. + +PID MEM COMMAND +33711 4803M qemu-system-aarc +44281 1966M Codex (Renderer) +98945 1497M+ Claude Helper (R +424 648M- WindowServer +501 2G big-process +77 512K launchd +`; + +describe('parseTopOutput', () => { + it('parses the process total and memory rows in MB', () => { + expect(parseTopOutput(TOP_FIXTURE)).toEqual({ + totalProcesses: 937, + top: [ + { pid: 33711, mem_mb: 4803, command: 'qemu-system-aarc' }, + { pid: 44281, mem_mb: 1966, command: 'Codex (Renderer)' }, + { pid: 98945, mem_mb: 1497, command: 'Claude Helper (R' }, + { pid: 424, mem_mb: 648, command: 'WindowServer' }, + { pid: 501, mem_mb: 2048, command: 'big-process' }, + { pid: 77, mem_mb: 0.5, command: 'launchd' }, + ], + }); + }); + + it('keeps at most the top 40 rows', () => { + const rows = Array.from( + { length: 60 }, + (_, i) => `${i + 1} ${100 - i}M proc${i}` + ); + const output = `Processes: 60 total\n\nPID MEM COMMAND\n${rows.join( + '\n' + )}\n`; + + expect(parseTopOutput(output).top).toHaveLength(40); + }); + + it('throws on output it does not recognise', () => { + expect(() => parseTopOutput('command not found')).toThrow(); + }); +}); + +describe('processSnapshotProbe', () => { + beforeEach(() => { + vi.mocked(spawn).mockReset(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it('takes no snapshot until a lifecycle phase arrives', () => { + setPlatform('darwin'); + const ctx = createProbeContext(); + + processSnapshotProbe.start(ctx); + + expect(spawn).not.toHaveBeenCalled(); + }); + + it.each(['platform.ready', 'app.ready', 'dispose'] as const)( + 'emits a snapshot mark and process count on %s', + async (phase) => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: TOP_FIXTURE } as never); + const ctx = createProbeContext(); + processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase }); + await settle(ctx); + + expect(spawn).toHaveBeenCalledWith( + 'top', + ['-l', '1', '-o', 'mem', '-stats', 'pid,mem,command', '-n', '40'], + expect.objectContaining({ signal: ctx.signal }) + ); + const entries = ctx.diagnostics.flush(); + const mark = entries.find( + (e) => e.label === 'telemetry.process_snapshot' + ); + expect(mark?.kind).toBe('mark'); + expect(mark?.attrs).toMatchObject({ phase, total_processes: 937 }); + expect(JSON.parse(mark?.attrs?.top as string)).toHaveLength(6); + expect( + entries.find((e) => e.label === 'host.process_count') + ).toMatchObject({ + kind: 'gauge', + value: 937, + attrs: { phase }, + }); + } + ); + + it('ignores phases that are not snapshot boundaries', async () => { + setPlatform('darwin'); + const ctx = createProbeContext(); + processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'test-file.start' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'metro.ready' }); + await settle(ctx); + + expect(spawn).not.toHaveBeenCalled(); + }); + + it('runs back to back phases one after another', async () => { + vi.useFakeTimers(); + setPlatform('darwin'); + let active = 0; + let maxActive = 0; + vi.mocked(spawn).mockImplementation((async () => { + active += 1; + maxActive = Math.max(maxActive, active); + await new Promise((resolve) => setTimeout(resolve, 5_000)); + active -= 1; + return { stdout: TOP_FIXTURE }; + }) as never); + const ctx = createProbeContext(); + processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'app.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await vi.advanceTimersByTimeAsync(20_000); + await settle(ctx); + + expect(spawn).toHaveBeenCalledTimes(2); + expect(maxActive).toBe(1); + }); + + it('snapshots only the first app.ready, not every relaunch', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockResolvedValue({ stdout: TOP_FIXTURE } as never); + const ctx = createProbeContext(); + processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'app.ready' }); + await settle(ctx); + ctx.lifecycle.emit({ type: 'phase', phase: 'app.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'app.ready' }); + await settle(ctx); + expect(spawn).toHaveBeenCalledTimes(1); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + expect(spawn).toHaveBeenCalledTimes(2); + }); + + it('skips queued snapshots once stopped or aborted, without error marks', async () => { + vi.useFakeTimers(); + setPlatform('darwin'); + vi.mocked(spawn).mockImplementation( + (() => + new Promise((resolve) => + setTimeout(() => resolve({ stdout: TOP_FIXTURE }), 1_000) + )) as never + ); + const ctx = createProbeContext(); + const stop = processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await vi.advanceTimersByTimeAsync(0); + stop(); + await vi.advanceTimersByTimeAsync(10_000); + await settle(ctx); + + // The running job finishes; the queued one never starts. + expect(spawn).toHaveBeenCalledTimes(1); + + const ctx2 = createProbeContext(); + processSnapshotProbe.start(ctx2); + ctx2.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); + ctx2.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + vi.mocked(spawn).mockClear(); + ctx2.controller.abort(); + await vi.advanceTimersByTimeAsync(10_000); + await settle(ctx2); + + expect(spawn).toHaveBeenCalledTimes(0); + expect( + ctx2.diagnostics.flush().filter((e) => e.attrs?.error !== undefined) + ).toEqual([]); + }); + + it('records an error mark instead of throwing when top fails', async () => { + setPlatform('darwin'); + vi.mocked(spawn).mockRejectedValue(new Error('top exploded')); + const ctx = createProbeContext(); + processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + + const [mark] = ctx.diagnostics.flush(); + expect(mark?.label).toBe('telemetry.process_snapshot'); + expect(mark?.attrs?.error).toContain('top exploded'); + }); + + it('does nothing outside darwin', async () => { + setPlatform('linux'); + const ctx = createProbeContext(); + const stop = processSnapshotProbe.start(ctx); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + + expect(spawn).not.toHaveBeenCalled(); + expect(ctx.diagnostics.flush()).toEqual([]); + stop(); + }); + + it('stops listening once stopped', async () => { + setPlatform('darwin'); + const ctx = createProbeContext(); + const stop = processSnapshotProbe.start(ctx); + stop(); + + ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); + await settle(ctx); + + expect(spawn).not.toHaveBeenCalled(); + }); +}); diff --git a/packages/tools/src/telemetry/__tests__/run-context.test.ts b/packages/tools/src/telemetry/__tests__/run-context.test.ts new file mode 100644 index 00000000..80a03d35 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/run-context.test.ts @@ -0,0 +1,62 @@ +import { describe, expect, it } from 'vitest'; +import { collectRunContext, runContextProbe } from '../run-context.js'; +import { createProbeContext } from './helpers.js'; + +describe('collectRunContext', () => { + it('describes the machine', () => { + const attrs = collectRunContext({}); + + expect(attrs.cpuCount).toBeGreaterThan(0); + expect(attrs.totalMemoryBytes).toBeGreaterThan(0); + expect(attrs.platform).toBe(process.platform); + expect(attrs.arch).toBe(process.arch); + expect(attrs.nodeVersion).toBe(process.version); + expect(attrs.ci).toBe(false); + expect(attrs.harnessVersion).toMatch(/^\d+\.\d+\.\d+/); + }); + + it('includes GitHub runner details when present and nothing else from env', () => { + const attrs = collectRunContext({ + CI: 'true', + RUNNER_OS: 'macOS', + RUNNER_ARCH: 'ARM64', + ImageOS: 'macos15', + ImageVersion: '20251001.1', + GITHUB_RUN_ID: '42', + GITHUB_JOB: 'e2e-ios', + GITHUB_TOKEN: 'secret-token', + NPM_TOKEN: 'secret-npm', + }); + + expect(attrs).toMatchObject({ + ci: true, + RUNNER_OS: 'macOS', + RUNNER_ARCH: 'ARM64', + ImageOS: 'macos15', + ImageVersion: '20251001.1', + GITHUB_RUN_ID: '42', + GITHUB_JOB: 'e2e-ios', + }); + expect(JSON.stringify(attrs)).not.toContain('secret'); + }); + + it('treats CI=false as not CI', () => { + expect(collectRunContext({ CI: 'false' }).ci).toBe(false); + }); +}); + +describe('runContextProbe', () => { + it('emits a single telemetry.context mark at start', () => { + const ctx = createProbeContext(); + + runContextProbe.start(ctx); + + const entries = ctx.diagnostics.flush(); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + label: 'telemetry.context', + kind: 'mark', + }); + expect(entries[0]?.attrs?.cpuCount).toBeGreaterThan(0); + }); +}); diff --git a/packages/tools/src/telemetry/host-resources.ts b/packages/tools/src/telemetry/host-resources.ts new file mode 100644 index 00000000..b9c86457 --- /dev/null +++ b/packages/tools/src/telemetry/host-resources.ts @@ -0,0 +1,243 @@ +import fs from 'node:fs/promises'; +import os from 'node:os'; +import { spawn } from '../spawn.js'; +import type { Diagnostics } from '../diagnostics.js'; +import type { TelemetryProbe } from './types.js'; +import { startSampler } from './probe-utils.js'; + +const BYTES_PER_MB = 1024 * 1024; +const VM_STAT_TIMEOUT_MS = 10_000; + +export type CpuTimes = { user: number; sys: number; idle: number }; + +export const readCpuTimes = ( + cpus: readonly os.CpuInfo[] = os.cpus() +): CpuTimes => + cpus.reduce( + (total, { times }) => ({ + user: total.user + times.user + times.nice, + sys: total.sys + times.sys + times.irq, + idle: total.idle + times.idle, + }), + { user: 0, sys: 0, idle: 0 } + ); + +/** CPU usage split over the interval between two `readCpuTimes` readings. */ +export const diffCpuTimes = ( + previous: CpuTimes, + current: CpuTimes +): { userPct: number; sysPct: number; idlePct: number } | null => { + const user = current.user - previous.user; + const sys = current.sys - previous.sys; + const idle = current.idle - previous.idle; + const total = user + sys + idle; + + if (total <= 0) { + return null; + } + + return { + userPct: (user / total) * 100, + sysPct: (sys / total) * 100, + idlePct: (idle / total) * 100, + }; +}; + +export type VmStatMemory = { + freeMb: number; + anonymousMb: number; + wiredMb: number; + compressedMb: number; + /** + * Memory that cannot be reclaimed without compressing or swapping: + * anonymous + wired + compressor-occupied pages. Free memory on macOS is + * almost always near zero because the OS fills it with file cache, so + * `free` alone cannot tell a healthy machine from a starved one; demand + * compared against physical memory can. + */ + demandMb: number; + /** Cumulative since boot, converted from pages to MB. */ + swapoutsMb: number; + /** Cumulative since boot, converted from pages to MB. */ + compressionsMb: number; +}; + +/** Parses `vm_stat` output. Returns null if it is not recognisable. */ +export const parseVmStat = (output: string): VmStatMemory | null => { + const pageSize = /page size of (\d+) bytes/.exec(output)?.[1]; + if (!pageSize) { + return null; + } + + const pages = new Map(); + for (const line of output.split('\n')) { + const match = /^"?([^":]+)"?:\s+(\d+)\.?\s*$/.exec(line.trim()); + if (match) { + pages.set(match[1] as string, Number(match[2])); + } + } + + const toMb = (key: string): number | null => { + const count = pages.get(key); + return count === undefined + ? null + : (count * Number(pageSize)) / BYTES_PER_MB; + }; + + const freeMb = toMb('Pages free'); + const anonymousMb = toMb('Anonymous pages'); + const wiredMb = toMb('Pages wired down'); + const compressedMb = toMb('Pages occupied by compressor'); + const swapoutsMb = toMb('Swapouts'); + const compressionsMb = toMb('Compressions'); + + if ( + freeMb === null || + anonymousMb === null || + wiredMb === null || + compressedMb === null || + swapoutsMb === null || + compressionsMb === null + ) { + return null; + } + + return { + freeMb, + anonymousMb, + wiredMb, + compressedMb, + demandMb: anonymousMb + wiredMb + compressedMb, + swapoutsMb, + compressionsMb, + }; +}; + +/** Extracts free and available memory (MB) from `/proc/meminfo` content. */ +export const parseProcMeminfo = ( + content: string +): { freeMb: number; availableMb: number | null } | null => { + const kb = (key: string): number | null => { + const match = new RegExp(`^${key}:\\s+(\\d+) kB`, 'm').exec(content); + return match ? Number(match[1]) / 1024 : null; + }; + + const freeMb = kb('MemFree'); + return freeMb === null ? null : { freeMb, availableMb: kb('MemAvailable') }; +}; + +const sampleDarwinMemory = async ( + diagnostics: Diagnostics, + signal: AbortSignal +): Promise => { + const { stdout } = await spawn('vm_stat', [], { + signal, + timeout: VM_STAT_TIMEOUT_MS, + }); + const memory = parseVmStat(stdout); + if (!memory || signal.aborted) { + return; + } + + diagnostics.gauge('host.mem.free', memory.freeMb, undefined, 'MB'); + diagnostics.gauge('host.mem.anonymous', memory.anonymousMb, undefined, 'MB'); + diagnostics.gauge('host.mem.wired', memory.wiredMb, undefined, 'MB'); + diagnostics.gauge( + 'host.mem.compressed', + memory.compressedMb, + undefined, + 'MB' + ); + diagnostics.gauge('host.mem.demand', memory.demandMb, undefined, 'MB'); + diagnostics.gauge('host.mem.swapouts', memory.swapoutsMb, undefined, 'MB'); + diagnostics.gauge( + 'host.mem.compressions', + memory.compressionsMb, + undefined, + 'MB' + ); +}; + +const sampleLinuxMemory = async (diagnostics: Diagnostics): Promise => { + const parsed = parseProcMeminfo(await fs.readFile('/proc/meminfo', 'utf-8')); + if (!parsed) { + diagnostics.gauge( + 'host.mem.free', + os.freemem() / BYTES_PER_MB, + undefined, + 'MB' + ); + return; + } + + diagnostics.gauge('host.mem.free', parsed.freeMb, undefined, 'MB'); + if (parsed.availableMb !== null) { + diagnostics.gauge( + 'host.mem.available', + parsed.availableMb, + undefined, + 'MB' + ); + } +}; + +const sampleMemory = async ( + diagnostics: Diagnostics, + signal: AbortSignal +): Promise => { + try { + if (process.platform === 'darwin') { + await sampleDarwinMemory(diagnostics, signal); + return; + } + if (process.platform === 'linux') { + await sampleLinuxMemory(diagnostics); + return; + } + } catch { + if (signal.aborted) { + return; + } + } + + // Portable fallback, also used when the platform specific source failed. + diagnostics.gauge( + 'host.mem.free', + os.freemem() / BYTES_PER_MB, + undefined, + 'MB' + ); +}; + +/** + * Samples host-wide resource pressure. Only cheap sources are used on the + * timer (`os.loadavg`, `os.cpus` deltas and, on macOS, one `vm_stat` spawn per + * sample): measuring must not add to the load it is trying to observe. + */ +export const hostResourcesProbe: TelemetryProbe = { + name: 'host-resources', + start: (ctx) => { + const { diagnostics } = ctx; + let previousCpu: CpuTimes | null = null; + + return startSampler(ctx, async (signal, { afterPause }) => { + if (afterPause) { + // The interval since the last sample was idle time; do not blend it in. + previousCpu = null; + } + + diagnostics.gauge('host.load1', os.loadavg()[0] ?? 0, undefined, 'load'); + + const currentCpu = readCpuTimes(); + const usage = previousCpu && diffCpuTimes(previousCpu, currentCpu); + previousCpu = currentCpu; + if (usage) { + diagnostics.gauge('host.cpu.user_pct', usage.userPct, undefined, '%'); + diagnostics.gauge('host.cpu.sys_pct', usage.sysPct, undefined, '%'); + diagnostics.gauge('host.cpu.idle_pct', usage.idlePct, undefined, '%'); + } + + await sampleMemory(diagnostics, signal); + }); + }, +}; diff --git a/packages/tools/src/telemetry/index.ts b/packages/tools/src/telemetry/index.ts new file mode 100644 index 00000000..6565bcb1 --- /dev/null +++ b/packages/tools/src/telemetry/index.ts @@ -0,0 +1,145 @@ +import { logger } from '../logger.js'; +import { getEmitter } from '../events.js'; +import type { LifecycleEvent, ProbeContext, TelemetryProbe } from './types.js'; +import { runContextProbe } from './run-context.js'; +import { hostResourcesProbe } from './host-resources.js'; +import { nodeRuntimeProbe } from './node-runtime.js'; +import { processSnapshotProbe } from './process-snapshot.js'; +import { + createPlatformCollectorProbe, + type PlatformCollectorProbeOptions, +} from './platform-collector.js'; + +export type { + LifecycleEvent, + LifecyclePhase, + ProbeContext, + TelemetryCollector, + TelemetryProbe, +} from './types.js'; +export type { PlatformCollectorProbeOptions } from './platform-collector.js'; + +const telemetryLogger = logger.child('telemetry'); + +export const DEFAULT_SAMPLE_INTERVAL_MS = 5000; + +export const createLifecycleEmitter = () => getEmitter(); + +export type DefaultProbeOptions = { + /** Load, CPU split and memory pressure of the host. Default: on. */ + host?: boolean; + /** Memory and event loop lag of the Harness process. Default: on. */ + node?: boolean; + /** Process listings at lifecycle boundaries (macOS). Default: on. */ + snapshots?: boolean; + /** Platform specific measurements. Omit to leave them out. */ + platform?: PlatformCollectorProbeOptions; +}; + +/** The one place that decides which probes make up a standard run. */ +export const createDefaultProbes = ( + options: DefaultProbeOptions = {} +): TelemetryProbe[] => { + const probes: TelemetryProbe[] = [runContextProbe]; + + if (options.host ?? true) { + probes.push(hostResourcesProbe); + } + if (options.node ?? true) { + probes.push(nodeRuntimeProbe); + } + if (options.snapshots ?? true) { + probes.push(processSnapshotProbe); + } + if (options.platform) { + probes.push(createPlatformCollectorProbe(options.platform)); + } + + return probes; +}; + +// Upper bound on how long dispose() lets in-flight work finish when the +// caller has not already aborted it. +const DISPOSE_SETTLE_TIMEOUT_MS = 5000; + +export type TelemetryRun = { + /** Resolves once all lifecycle driven work started so far has finished. */ + settled(): Promise; + /** + * Stops every probe. Safe to call more than once. In-flight work is only + * waited for (bounded) if the context's signal has not been aborted: an + * aborted run has no use for results that are still pending. + */ + dispose(): Promise; +}; + +const noopRun: TelemetryRun = { + settled: async () => undefined, + dispose: async () => undefined, +}; + +/** + * Starts probes against the diagnostics sink. When diagnostics are disabled + * nothing starts: no timers, no listeners, no spawned processes. A probe that + * fails to start is skipped without affecting the others. + */ +export const startTelemetryProbes = ( + probes: readonly TelemetryProbe[], + ctx: Omit +): TelemetryRun => { + if (!ctx.diagnostics.enabled || ctx.signal.aborted) { + return noopRun; + } + + const pending = new Set>(); + const track = (work: Promise): Promise => { + pending.add(work); + const forget = () => { + pending.delete(work); + }; + work.then(forget, forget); + return work; + }; + + const stops: Array<{ name: string; stop: () => void | Promise }> = []; + for (const probe of probes) { + try { + stops.push({ name: probe.name, stop: probe.start({ ...ctx, track }) }); + } catch (error) { + telemetryLogger.debug('probe %s failed to start: %s', probe.name, error); + } + } + + const settled = async () => { + while (pending.size > 0) { + await Promise.allSettled([...pending]); + } + }; + + let disposed: Promise | null = null; + const dispose = () => { + disposed ??= (async () => { + for (const { name, stop } of stops) { + try { + await stop(); + } catch (error) { + telemetryLogger.debug('probe %s failed to stop: %s', name, error); + } + } + if (!ctx.signal.aborted) { + let timer: ReturnType | undefined; + const timeout = new Promise((resolve) => { + timer = setTimeout(resolve, DISPOSE_SETTLE_TIMEOUT_MS); + }); + try { + await Promise.race([settled(), timeout]); + } finally { + clearTimeout(timer); + } + } + })(); + return disposed; + }; + + return { settled, dispose }; +}; diff --git a/packages/tools/src/telemetry/node-runtime.ts b/packages/tools/src/telemetry/node-runtime.ts new file mode 100644 index 00000000..ecca534a --- /dev/null +++ b/packages/tools/src/telemetry/node-runtime.ts @@ -0,0 +1,87 @@ +import { monitorEventLoopDelay } from 'node:perf_hooks'; +import type { TelemetryProbe } from './types.js'; +import { startSampler } from './probe-utils.js'; + +const BYTES_PER_MB = 1024 * 1024; +const NS_PER_MS = 1e6; +// The histogram records the full interval between timer ticks, so an idle loop +// reads as the resolution itself. Subtract it to report actual lag. +const RESOLUTION_MS = 20; + +const toLagMs = (nanoseconds: number): number => + Math.max(0, nanoseconds / NS_PER_MS - RESOLUTION_MS); + +/** + * Samples the Harness (Node) process: memory and event loop lag. Event loop + * lag is the early warning that the host is too busy for Harness itself to + * schedule work, and the histogram is reset after every sample so each point + * describes only its own interval. + */ +export const nodeRuntimeProbe: TelemetryProbe = { + name: 'node-runtime', + start: (ctx) => { + const { diagnostics } = ctx; + const histogram = monitorEventLoopDelay({ resolution: RESOLUTION_MS }); + histogram.enable(); + + const stopSampling = startSampler(ctx, (_signal, { afterPause }) => { + if (afterPause) { + histogram.reset(); + } + + const memory = process.memoryUsage(); + diagnostics.gauge( + 'node.rss_mb', + memory.rss / BYTES_PER_MB, + undefined, + 'MB' + ); + diagnostics.gauge( + 'node.heap_used_mb', + memory.heapUsed / BYTES_PER_MB, + undefined, + 'MB' + ); + diagnostics.gauge( + 'node.heap_total_mb', + memory.heapTotal / BYTES_PER_MB, + undefined, + 'MB' + ); + diagnostics.gauge( + 'node.external_mb', + memory.external / BYTES_PER_MB, + undefined, + 'MB' + ); + + // An empty histogram reports NaN percentiles; skip until it has data. + if (histogram.count > 0) { + diagnostics.gauge( + 'node.event_loop.p50_ms', + toLagMs(histogram.percentile(50)), + undefined, + 'ms' + ); + diagnostics.gauge( + 'node.event_loop.p99_ms', + toLagMs(histogram.percentile(99)), + undefined, + 'ms' + ); + diagnostics.gauge( + 'node.event_loop.max_ms', + toLagMs(histogram.max), + undefined, + 'ms' + ); + } + histogram.reset(); + }); + + return () => { + stopSampling(); + histogram.disable(); + }; + }, +}; diff --git a/packages/tools/src/telemetry/platform-collector.ts b/packages/tools/src/telemetry/platform-collector.ts new file mode 100644 index 00000000..e859e939 --- /dev/null +++ b/packages/tools/src/telemetry/platform-collector.ts @@ -0,0 +1,76 @@ +import type { DiagnosticAttrs } from '../diagnostics.js'; +import type { + LifecyclePhase, + TelemetryCollector, + TelemetryProbe, +} from './types.js'; +import { createSerialQueue, onLifecyclePhases } from './probe-utils.js'; + +const COLLECTOR_PHASES: readonly LifecyclePhase[] = [ + 'platform.ready', + 'app.ready', + 'dispose', +]; + +export type PlatformCollectorProbeOptions = { + /** + * Resolves the collector lazily: the platform runner usually does not exist + * yet when probes start. Returns undefined when the platform has none. + */ + getCollector: () => TelemetryCollector | undefined; +}; + +/** + * Bridges platform-specific measurements into diagnostics. The platform + * decides what to measure; this probe decides when (lifecycle phases) and + * how it is recorded: numbers as `platform.` gauges, strings as attrs of + * a `telemetry.platform` mark. + */ +export const createPlatformCollectorProbe = ({ + getCollector, +}: PlatformCollectorProbeOptions): TelemetryProbe => ({ + name: 'platform-collector', + start: (ctx) => { + const { diagnostics } = ctx; + const queue = createSerialQueue(); + const controller = new AbortController(); + const abort = () => controller.abort(); + ctx.signal.addEventListener('abort', abort, { once: true }); + let collector: TelemetryCollector | undefined; + + const stop = onLifecyclePhases(ctx, COLLECTOR_PHASES, ({ phase }) => + queue.run(async () => { + collector ??= getCollector(); + if (!collector) { + return; + } + + const values = await collector.collect(phase, controller.signal); + if (controller.signal.aborted) { + return; + } + + const strings: DiagnosticAttrs = {}; + for (const [key, value] of Object.entries(values)) { + if (typeof value === 'number') { + diagnostics.gauge(`platform.${key}`, value, { phase }); + } else { + strings[key] = value; + } + } + + if (Object.keys(strings).length > 0) { + diagnostics.mark('telemetry.platform', { phase, ...strings }); + } + }) + ); + + return () => { + stop(); + queue.close(); + controller.abort(); + ctx.signal.removeEventListener('abort', abort); + collector?.dispose?.(); + }; + }, +}); diff --git a/packages/tools/src/telemetry/probe-utils.ts b/packages/tools/src/telemetry/probe-utils.ts new file mode 100644 index 00000000..8c035e90 --- /dev/null +++ b/packages/tools/src/telemetry/probe-utils.ts @@ -0,0 +1,141 @@ +import { unrefTimer } from '../unref-timer.js'; +import type { LifecycleEvent, LifecyclePhase, ProbeContext } from './types.js'; + +export type SampleInfo = { + /** True for the first sample after sampling was paused between runs. */ + afterPause: boolean; +}; + +/** + * Runs `sample` on a fixed cadence (first sample immediately) and never lets + * two samples overlap: if the previous one is still running when the timer + * fires, that tick is skipped. This keeps sampling from piling up on a slow or + * overloaded machine, which is exactly where it must stay cheap. + * + * Sampling pauses on `run.end` and resumes (with an immediate sample) on the + * next `run.start` or on `dispose`. A single run therefore samples + * continuously from session start to teardown, while a watch-mode session + * that sits idle between runs does not accumulate samples nobody asked for. + * + * The timer is unref'd so it can never keep the process alive. The returned + * function stops sampling and aborts the signal handed to an in-flight sample. + */ +export const startSampler = ( + ctx: Pick< + ProbeContext, + 'signal' | 'track' | 'sampleIntervalMs' | 'lifecycle' + >, + sample: (signal: AbortSignal, info: SampleInfo) => void | Promise +): (() => void) => { + const controller = new AbortController(); + let running = false; + let paused = false; + let afterPause = false; + + const tick = () => { + if (running || paused || controller.signal.aborted) { + return; + } + running = true; + const info = { afterPause }; + afterPause = false; + const work = (async () => { + try { + await sample(controller.signal, info); + } catch { + // A failed sample is dropped; the next tick tries again. + } finally { + running = false; + } + })(); + void ctx.track(work); + }; + + const onPhase = (event: LifecycleEvent) => { + if (event.phase === 'run.end') { + paused = true; + } else if ( + paused && + (event.phase === 'run.start' || event.phase === 'dispose') + ) { + paused = false; + afterPause = true; + tick(); + } + }; + + const stop = () => { + clearInterval(timer); + controller.abort(); + ctx.lifecycle.removeListener(onPhase); + ctx.signal.removeEventListener('abort', stop); + }; + + const timer = setInterval(tick, ctx.sampleIntervalMs); + unrefTimer(timer); + ctx.signal.addEventListener('abort', stop, { once: true }); + ctx.lifecycle.addListener(onPhase); + tick(); + + return stop; +}; + +/** + * Subscribes to selected lifecycle phases. Handlers run as tracked work, so + * the owner can wait for them, and a handler failure never propagates to the + * code that emitted the phase. + */ +export const onLifecyclePhases = ( + ctx: Pick, + phases: readonly LifecyclePhase[], + handler: (event: LifecycleEvent) => void | Promise +): (() => void) => { + const listener = (event: LifecycleEvent) => { + if (event.type !== 'phase' || !phases.includes(event.phase)) { + return; + } + void ctx.track( + (async () => { + try { + await handler(event); + } catch { + // Telemetry is best effort. + } + })() + ); + }; + + ctx.lifecycle.addListener(listener); + return () => ctx.lifecycle.removeListener(listener); +}; + +export type SerialQueue = { + /** Queues `job`; resolves undefined if it failed or the queue was closed. */ + run(job: () => Promise): Promise; + /** Jobs still waiting are skipped from now on; a running job is not interrupted. */ + close(): void; +}; + +/** + * Runs queued jobs one after another. Lifecycle phases can fire back to back + * (for example `app.ready` right before `dispose`); serialising keeps heavy + * collectors from overlapping while still running every job. Closing the + * queue (when the probe stops) turns the remaining jobs into no-ops, so + * nothing runs, or reports, after teardown began. + */ +export const createSerialQueue = (): SerialQueue => { + let tail: Promise = Promise.resolve(); + let closed = false; + + return { + run: (job) => { + const guarded = async () => (closed ? undefined : job()); + const result = tail.then(guarded, guarded); + tail = result.catch(() => undefined); + return result.catch(() => undefined); + }, + close: () => { + closed = true; + }, + }; +}; diff --git a/packages/tools/src/telemetry/process-snapshot.ts b/packages/tools/src/telemetry/process-snapshot.ts new file mode 100644 index 00000000..f3c7be84 --- /dev/null +++ b/packages/tools/src/telemetry/process-snapshot.ts @@ -0,0 +1,140 @@ +import { spawn } from '../spawn.js'; +import type { TelemetryProbe } from './types.js'; +import { createSerialQueue, onLifecyclePhases } from './probe-utils.js'; + +const TOP_PROCESS_LIMIT = 40; +const TOP_TIMEOUT_MS = 60_000; + +export type ProcessMemoryRow = { pid: number; mem_mb: number; command: string }; + +export type ProcessSnapshot = { + totalProcesses: number | null; + top: ProcessMemoryRow[]; +}; + +const UNIT_TO_MB: Record = { + B: 1 / (1024 * 1024), + K: 1 / 1024, + M: 1, + G: 1024, + T: 1024 * 1024, +}; + +/** + * Parses the output of `top -l 1 -o mem -stats pid,mem,command`. `top` prints + * memory as a number with a unit suffix and an optional trend marker (`4803M`, + * `720K+`). Returns rows in the order `top` listed them (largest first). + */ +export const parseTopOutput = (output: string): ProcessSnapshot => { + const totalProcesses = /^Processes:\s+(\d+) total/m.exec(output)?.[1]; + const top: ProcessMemoryRow[] = []; + + let inTable = false; + for (const line of output.split('\n')) { + if (!inTable) { + inTable = /^\s*PID\s+MEM\s+COMMAND/.test(line); + continue; + } + + const match = /^\s*(\d+)\s+(\d+(?:\.\d+)?)([BKMGT])[+-]?\s+(.*?)\s*$/.exec( + line + ); + if (match) { + top.push({ + pid: Number(match[1]), + mem_mb: + Math.round( + Number(match[2]) * (UNIT_TO_MB[match[3] as string] ?? 0) * 10 + ) / 10, + command: match[4] as string, + }); + } + } + + if (totalProcesses === undefined && top.length === 0) { + throw new Error('unrecognised top output'); + } + + return { + totalProcesses: + totalProcesses === undefined ? null : Number(totalProcesses), + top: top.slice(0, TOP_PROCESS_LIMIT), + }; +}; + +/** + * On macOS, takes one process listing at selected lifecycle boundaries. It + * answers "what was eating the memory" after the fact. `top` is expensive, so + * it runs only on lifecycle phases, never on a timer. + */ +export const processSnapshotProbe: TelemetryProbe = { + name: 'process-snapshot', + start: (ctx) => { + if (process.platform !== 'darwin') { + return () => undefined; + } + + const { diagnostics, signal } = ctx; + const queue = createSerialQueue(); + // `app.ready` fires after every app relaunch, which can be once per test + // file; only the first one is a milestone worth the cost of `top`. + let appReadySeen = false; + + const stop = onLifecyclePhases( + ctx, + ['platform.ready', 'app.ready', 'dispose'], + ({ phase }) => { + if (phase === 'app.ready') { + if (appReadySeen) { + return; + } + appReadySeen = true; + } + + return queue.run(async () => { + if (signal.aborted) { + return; + } + try { + const { stdout } = await spawn( + 'top', + [ + '-l', + '1', + '-o', + 'mem', + '-stats', + 'pid,mem,command', + '-n', + String(TOP_PROCESS_LIMIT), + ], + { signal, timeout: TOP_TIMEOUT_MS } + ); + const snapshot = parseTopOutput(stdout); + + diagnostics.mark('telemetry.process_snapshot', { + phase, + total_processes: snapshot.totalProcesses ?? undefined, + top: JSON.stringify(snapshot.top), + }); + if (snapshot.totalProcesses !== null) { + diagnostics.gauge('host.process_count', snapshot.totalProcesses, { + phase, + }); + } + } catch (error) { + diagnostics.mark('telemetry.process_snapshot', { + phase, + error: String(error).slice(0, 200), + }); + } + }); + } + ); + + return () => { + stop(); + queue.close(); + }; + }, +}; diff --git a/packages/tools/src/telemetry/run-context.ts b/packages/tools/src/telemetry/run-context.ts new file mode 100644 index 00000000..0b6a0b21 --- /dev/null +++ b/packages/tools/src/telemetry/run-context.ts @@ -0,0 +1,61 @@ +import { createRequire } from 'node:module'; +import os from 'node:os'; +import type { DiagnosticAttrs } from '../diagnostics.js'; +import type { TelemetryProbe } from './types.js'; + +const GITHUB_RUNNER_ENV = [ + 'RUNNER_OS', + 'RUNNER_ARCH', + 'ImageOS', + 'ImageVersion', + 'GITHUB_RUN_ID', + 'GITHUB_JOB', +] as const; + +const getHarnessVersion = (): string | undefined => { + try { + // All Harness packages are released in lockstep, so the version of this + // package is the version of the Harness in use. + const require = createRequire(import.meta.url); + return (require('../../package.json') as { version?: string }).version; + } catch { + return undefined; + } +}; + +/** + * Describes the machine and CI environment. Only an allowlist of + * non-sensitive variables is read; nothing else from `env` is recorded. + */ +export const collectRunContext = ( + env: NodeJS.ProcessEnv = process.env +): DiagnosticAttrs => { + const attrs: DiagnosticAttrs = { + cpuCount: os.availableParallelism(), + totalMemoryBytes: os.totalmem(), + platform: process.platform, + arch: process.arch, + osRelease: os.release(), + nodeVersion: process.version, + ci: !!env.CI && env.CI !== 'false' && env.CI !== '0', + harnessVersion: getHarnessVersion(), + }; + + for (const key of GITHUB_RUNNER_ENV) { + const value = env[key]; + if (value) { + attrs[key] = value; + } + } + + return attrs; +}; + +/** Emits a single `telemetry.context` mark describing the host. */ +export const runContextProbe: TelemetryProbe = { + name: 'run-context', + start: ({ diagnostics }) => { + diagnostics.mark('telemetry.context', collectRunContext()); + return () => undefined; + }, +}; diff --git a/packages/tools/src/telemetry/types.ts b/packages/tools/src/telemetry/types.ts new file mode 100644 index 00000000..04d88fee --- /dev/null +++ b/packages/tools/src/telemetry/types.ts @@ -0,0 +1,61 @@ +import type { DiagnosticAttrs, Diagnostics } from '../diagnostics.js'; +import type { EventEmitter } from '../events.js'; + +/** + * Points in a run's life that probes can react to. Session code emits these; + * probes only listen. They are the boundaries at which heavier measurements + * (process listings, guest process counts) are allowed to run. + */ +export type LifecyclePhase = + | 'session.created' + | 'run.start' + | 'run.end' + | 'metro.ready' + | 'platform.ready' + | 'app.ready' + | 'test-file.start' + | 'test-file.end' + | 'dispose'; + +export type LifecycleEvent = { + type: 'phase'; + phase: LifecyclePhase; + attrs?: DiagnosticAttrs; +}; + +export type ProbeContext = { + /** The single sink every probe writes to. */ + diagnostics: Diagnostics; + /** Aborts when telemetry is shutting down; probes must stop all work. */ + signal: AbortSignal; + lifecycle: EventEmitter; + sampleIntervalMs: number; + /** + * Registers in-flight asynchronous work so that the owner can wait for it + * (for example a `dispose` snapshot that must finish before teardown). + */ + track: (work: Promise) => Promise; +}; + +export type TelemetryProbe = { + name: string; + /** Starts the probe and returns the function that stops it. */ + start(ctx: ProbeContext): () => void | Promise; +}; + +/** + * Platform-specific measurements, supplied by a platform runner and driven by + * the generic `platform-collector` probe at lifecycle phases. Numeric values + * become gauges named `platform.`; strings become attrs of a mark. + */ +export type TelemetryCollector = { + /** + * `signal` aborts when telemetry stops; collectors must pass it to whatever + * they spawn so teardown never waits on a measurement nobody will read. + */ + collect( + phase: LifecyclePhase, + signal: AbortSignal + ): Promise>; + dispose?(): void; +}; diff --git a/packages/tools/src/unref-timer.ts b/packages/tools/src/unref-timer.ts new file mode 100644 index 00000000..10aef9ec --- /dev/null +++ b/packages/tools/src/unref-timer.ts @@ -0,0 +1,11 @@ +/** + * Lets a timer stop keeping the process alive. Node timers expose `unref()`; + * consumers compiled against DOM typings see timers as numbers, so the call + * is guarded instead of typed against `NodeJS.Timeout`. + */ +export const unrefTimer = (timer: unknown): void => { + const candidate = timer as { unref?: () => unknown } | null | undefined; + if (candidate && typeof candidate.unref === 'function') { + candidate.unref(); + } +}; diff --git a/website/src/docs/getting-started/configuration.mdx b/website/src/docs/getting-started/configuration.mdx index 7f140f07..78d9f133 100644 --- a/website/src/docs/getting-started/configuration.mdx +++ b/website/src/docs/getting-started/configuration.mdx @@ -111,6 +111,7 @@ For Expo projects, the `entryPoint` should be set to the path specified in the ` | `coverage.root` | Root directory for coverage instrumentation (default: `process.cwd()`). | | `coverage.native.ios.pods` | Experimental list of CocoaPods target names to instrument for iOS native coverage. | | `forwardClientLogs` | Forward console logs from the app to the terminal (default: `false`). | +| `diagnostics` | Record a timing trace and resource metrics for the run: `true`, or an object with `enabled`, `probes` and `sampleIntervalMs` (default: `false`). See [Diagnostics](#diagnostics). | | `cache` | Cache configuration object. | | `cache.metro` | Enable persistent Metro transform and file-map caching under `.harness/cache` (default: `true`). | | `cache.version` | User-controlled salt folded into the Metro cache version. Bump it to force-invalidate previously cached transforms. | @@ -282,6 +283,57 @@ Increase this value if your app occasionally needs another launch attempt before Set it to `0` if you want startup failures to fail immediately without any automatic retry. +## Diagnostics + +Diagnostics record where a run spends its time and how loaded the machine is while it does. They are most useful on slow or flaky CI runners, where you need data to tell a slow simulator boot from a slow bundle or an overloaded host. + +Turn them on with `diagnostics: true`, or set `RN_HARNESS_DIAGNOSTICS=1` for a single run without touching your config. Pass an object to tune what is collected: + +```javascript +{ + diagnostics: { + probes: { + host: true, // load, CPU split and memory pressure of the machine + node: true, // memory and event loop lag of the Harness process + snapshots: true, // process listing at run milestones (macOS only) + platform: true, // platform-specific data, such as the process count inside an iOS simulator + }, + sampleIntervalMs: 5000, + }, +} +``` + +With the object form, diagnostics are on unless you set `enabled: false`. Every probe is on by default, and `sampleIntervalMs` defaults to `5000` (minimum `250`). Nothing is started, sampled or written when diagnostics are off. + +### What is recorded + +Besides timings for session setup, Metro bundling, app startup and each test file, Harness samples these metrics every `sampleIntervalMs`: + +| Metric | Meaning | +| :------------------------------------------------------------------- | :---------------------------------------------------------------------------------------------------------------------------- | +| `host.load1` | One-minute load average. | +| `host.cpu.user_pct`, `host.cpu.sys_pct`, `host.cpu.idle_pct` | How the machine's CPU time was split since the previous sample. | +| `host.mem.free`, `host.mem.compressed`, `host.mem.demand` (MB) | macOS memory pressure. `demand` is anonymous + wired + compressed memory, the part the OS cannot simply reclaim. | +| `host.mem.swapouts`, `host.mem.compressions` (MB) | Cumulative memory swapped out or compressed since boot. A rising `swapouts` during a run means the machine is out of memory. | +| `node.rss_mb`, `node.heap_used_mb` | Memory of the Harness process. | +| `node.event_loop.p50_ms`, `node.event_loop.p99_ms`, `node.event_loop.max_ms` | How late Harness's own timers fire. Large values mean the machine is too busy to schedule work. | + +On macOS, Harness also records a process listing (`telemetry.process_snapshot`, the 40 largest processes by memory plus the total process count as `host.process_count`) when the platform becomes ready, the first time the app becomes ready, and at the end of the run (later app relaunches are not listed again, to keep sampling cheap). For iOS simulators it records `platform.ios.simulator.guest_process_count`, the number of processes running inside the simulator, at platform ready and at the end of the run, and the `platform.ios.simctl.waitForBoot` span carries the last boot stage reported by the simulator (`bootLastStatus`), which shows what a slow or timed-out boot was waiting on. + +### Output + +Everything is written to `.harness/diagnostics/` in your project root: + +| File | Contents | +| :------------------------- | :---------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `.jsonl` | One entry per line, written while the run is in progress (and when the process exits), so a job that is cancelled or times out still leaves its data behind. | +| `.json` | A Chrome Trace Event file written when the run finishes. Open it in [Perfetto](https://ui.perfetto.dev) to see the timeline and a graph for each sampled metric. | +| `.summary.json` | The key numbers of the run, for comparing runs: boot wait, time to ready, peak load, peak compressed memory, minimum free memory, memory swapped out, longest event loop lag, number of test files and the result. A value that could not be measured is `null`. | + +Sampling is paused between runs in watch mode, so idle time does not show up in a run's metrics. Entries recorded while the session shuts down (the end-of-run process listing, for example) are added to the trace of the last run; the key numbers cover the run itself. + +The same key numbers are printed at the end of the run. When running in GitHub Actions, they are also added to the job summary as a table. + ## Plugins You can register Harness plugins with the `plugins` option.