From 41efb57bc02bbb0c0062b488b136b47581abfef4 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:40:57 +0200 Subject: [PATCH 01/10] feat(tools): add gauge entries, entry subscription and result attrs to diagnostics --- .../tools/src/__tests__/diagnostics.test.ts | 123 ++++++++++++++++++ packages/tools/src/diagnostics.ts | 97 +++++++++++++- 2 files changed, 213 insertions(+), 7 deletions(-) diff --git a/packages/tools/src/__tests__/diagnostics.test.ts b/packages/tools/src/__tests__/diagnostics.test.ts index f0f6f901..cc9f357f 100644 --- a/packages/tools/src/__tests__/diagnostics.test.ts +++ b/packages/tools/src/__tests__/diagnostics.test.ts @@ -110,6 +110,61 @@ 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() 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 +180,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 +337,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..0e868edd 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,16 @@ 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. Returns a function that unsubscribes. + */ + subscribe(listener: DiagnosticEntryListener): () => void; flush(): DiagnosticEntry[]; }; @@ -64,8 +78,10 @@ const createNoopDiagnostics = (): Diagnostics => { start: () => noopSpan, measure: async (_label, fn) => fn(), mark: noop, + gauge: noop, record: noop, child: () => diagnostics, + subscribe: () => noop, flush: () => [], }; @@ -76,6 +92,7 @@ export const noopDiagnostics: Diagnostics = createNoopDiagnostics(); type RootState = { entries: DiagnosticEntry[]; + listeners: Set; epochAnchor: number; perfAnchor: number; }; @@ -93,6 +110,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 +186,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 +228,13 @@ const createEnabledDiagnostics = ( ); }; + const subscribe = (listener: DiagnosticEntryListener): (() => void) => { + state.listeners.add(listener); + return () => { + state.listeners.delete(listener); + }; + }; + const flush = (): DiagnosticEntry[] => { const flushed = state.entries; state.entries = []; @@ -197,8 +246,10 @@ const createEnabledDiagnostics = ( start, measure, mark, + gauge, record, child, + subscribe, flush, }; }; @@ -210,6 +261,7 @@ export const createDiagnostics = (options?: { enabled?: boolean }): Diagnostics const state: RootState = { entries: [], + listeners: new Set(), epochAnchor: Date.now(), perfAnchor: performance.now(), }; @@ -217,10 +269,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 +322,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 +346,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; }; From 245246e067cfe071f30aac1aae34074133e7d724 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:45:27 +0200 Subject: [PATCH 02/10] feat(tools): add generic run telemetry probes Adds packages/tools/src/telemetry with probes that translate polled host and process data into the existing Diagnostics sink: run context, host resources (load, CPU split, vm_stat memory pressure), Node runtime (memory, event loop lag), lifecycle driven process snapshots and a platform collector bridge. Probes are started through one composition point and cost nothing when diagnostics are disabled. --- packages/tools/src/index.ts | 1 + .../tools/src/telemetry/__tests__/helpers.ts | 37 +++ .../__tests__/host-resources.test.ts | 259 ++++++++++++++++++ .../src/telemetry/__tests__/index.test.ts | 143 ++++++++++ .../telemetry/__tests__/node-runtime.test.ts | 90 ++++++ .../__tests__/platform-collector.test.ts | 84 ++++++ .../__tests__/process-snapshot.test.ts | 186 +++++++++++++ .../telemetry/__tests__/run-context.test.ts | 62 +++++ .../tools/src/telemetry/host-resources.ts | 238 ++++++++++++++++ packages/tools/src/telemetry/index.ts | 127 +++++++++ packages/tools/src/telemetry/node-runtime.ts | 83 ++++++ .../tools/src/telemetry/platform-collector.ts | 70 +++++ packages/tools/src/telemetry/probe-utils.ts | 94 +++++++ .../tools/src/telemetry/process-snapshot.ts | 121 ++++++++ packages/tools/src/telemetry/run-context.ts | 61 +++++ packages/tools/src/telemetry/types.ts | 52 ++++ 16 files changed, 1708 insertions(+) create mode 100644 packages/tools/src/telemetry/__tests__/helpers.ts create mode 100644 packages/tools/src/telemetry/__tests__/host-resources.test.ts create mode 100644 packages/tools/src/telemetry/__tests__/index.test.ts create mode 100644 packages/tools/src/telemetry/__tests__/node-runtime.test.ts create mode 100644 packages/tools/src/telemetry/__tests__/platform-collector.test.ts create mode 100644 packages/tools/src/telemetry/__tests__/process-snapshot.test.ts create mode 100644 packages/tools/src/telemetry/__tests__/run-context.test.ts create mode 100644 packages/tools/src/telemetry/host-resources.ts create mode 100644 packages/tools/src/telemetry/index.ts create mode 100644 packages/tools/src/telemetry/node-runtime.ts create mode 100644 packages/tools/src/telemetry/platform-collector.ts create mode 100644 packages/tools/src/telemetry/probe-utils.ts create mode 100644 packages/tools/src/telemetry/process-snapshot.ts create mode 100644 packages/tools/src/telemetry/run-context.ts create mode 100644 packages/tools/src/telemetry/types.ts diff --git a/packages/tools/src/index.ts b/packages/tools/src/index.ts index bfc0823b..6de4aeeb 100644 --- a/packages/tools/src/index.ts +++ b/packages/tools/src/index.ts @@ -20,3 +20,4 @@ export * from './diagnostics.js'; export * from './device-core-budget.js'; export * from './host-capabilities.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..9f470900 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/host-resources.test.ts @@ -0,0 +1,259 @@ +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('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..c3274a2a --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/index.test.ts @@ -0,0 +1,143 @@ +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.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 () => { + 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); + await run.settled(); + + expect(finished).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..6e78a101 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/platform-collector.test.ts @@ -0,0 +1,84 @@ +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'); + 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(); + }); +}); 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..86548f20 --- /dev/null +++ b/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts @@ -0,0 +1,186 @@ +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.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 () => { + 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)); + 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 settle(ctx); + await new Promise((resolve) => setTimeout(resolve, 30)); + await settle(ctx); + + expect(spawn).toHaveBeenCalledTimes(2); + expect(maxActive).toBe(1); + }); + + 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..6648e5fd --- /dev/null +++ b/packages/tools/src/telemetry/host-resources.ts @@ -0,0 +1,238 @@ +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) => { + 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..776b49c7 --- /dev/null +++ b/packages/tools/src/telemetry/index.ts @@ -0,0 +1,127 @@ +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; +}; + +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. */ + 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); + } + } + await settled(); + })(); + 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..e74fc9b4 --- /dev/null +++ b/packages/tools/src/telemetry/node-runtime.ts @@ -0,0 +1,83 @@ +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, () => { + 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..eebe5e02 --- /dev/null +++ b/packages/tools/src/telemetry/platform-collector.ts @@ -0,0 +1,70 @@ +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 enqueue = createSerialQueue(); + let collector: TelemetryCollector | undefined; + + const stop = onLifecyclePhases(ctx, COLLECTOR_PHASES, ({ phase }) => + enqueue(async () => { + collector ??= getCollector(); + if (!collector) { + return; + } + + const values = await collector.collect(phase); + if (ctx.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(); + 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..f365b1f9 --- /dev/null +++ b/packages/tools/src/telemetry/probe-utils.ts @@ -0,0 +1,94 @@ +import type { LifecycleEvent, LifecyclePhase, ProbeContext } from './types.js'; + +/** + * 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. + * + * 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, + sample: (signal: AbortSignal) => void | Promise +): (() => void) => { + const controller = new AbortController(); + let running = false; + + const stop = () => { + clearInterval(timer); + controller.abort(); + ctx.signal.removeEventListener('abort', stop); + }; + + const tick = () => { + if (running || controller.signal.aborted) { + return; + } + running = true; + const work = (async () => { + try { + await sample(controller.signal); + } catch { + // A failed sample is dropped; the next tick tries again. + } finally { + running = false; + } + })(); + void ctx.track(work); + }; + + const timer = setInterval(tick, ctx.sampleIntervalMs); + timer.unref(); + ctx.signal.addEventListener('abort', stop, { once: true }); + 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); +}; + +/** + * 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. + */ +export const createSerialQueue = (): (( + job: () => Promise +) => Promise) => { + let tail: Promise = Promise.resolve(); + + return (job) => { + const result = tail.then(job, job); + tail = result.catch(() => undefined); + return result.catch(() => undefined); + }; +}; diff --git a/packages/tools/src/telemetry/process-snapshot.ts b/packages/tools/src/telemetry/process-snapshot.ts new file mode 100644 index 00000000..14d9c971 --- /dev/null +++ b/packages/tools/src/telemetry/process-snapshot.ts @@ -0,0 +1,121 @@ +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 enqueue = createSerialQueue(); + + return onLifecyclePhases( + ctx, + ['platform.ready', 'app.ready', 'dispose'], + ({ phase }) => + enqueue(async () => { + 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), + }); + } + }) + ); + }, +}; 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..053da8b9 --- /dev/null +++ b/packages/tools/src/telemetry/types.ts @@ -0,0 +1,52 @@ +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' + | '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 = { + collect(phase: LifecyclePhase): Promise>; + dispose?(): void; +}; From 7755f7fcb641bff3040de81c1b09d12ebbd284c0 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:50:53 +0200 Subject: [PATCH 03/10] feat(platform-ios): report simulator boot stage and guest process count waitForBoot now returns the last stage and elapsed time that simctl bootstatus reported. Rather than adding diagnostics calls to the runner, instrumented() accepts optional resultAttrs/errorAttrs derivers; the simctl module is wrapped with ones that attach the stage to the platform.ios.simctl.waitForBoot span, including when the wait times out or is aborted (the case that matters most). Platform runners can expose an optional createTelemetryCollector(); the simulator runner implements it to count guest launchd services at platform.ready and dispose through the (instrumented) simctl module. --- .../src/__tests__/instance.test.ts | 82 ++++++++++++++- .../platform-ios/src/__tests__/simctl.test.ts | 99 ++++++++++++++++++- packages/platform-ios/src/instance.ts | 21 +++- .../src/xcrun/simctl-diagnostics.ts | 29 ++++++ packages/platform-ios/src/xcrun/simctl.ts | 59 ++++++++++- packages/platforms/src/index.ts | 1 + packages/platforms/src/types.ts | 10 +- 7 files changed, 293 insertions(+), 8 deletions(-) create mode 100644 packages/platform-ios/src/xcrun/simctl-diagnostics.ts diff --git a/packages/platform-ios/src/__tests__/instance.test.ts b/packages/platform-ios/src/__tests__/instance.test.ts index 4c7804a1..1b0724fe 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,81 @@ 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?.(); + + await expect(collector?.collect('platform.ready')).resolves.toEqual({ + 'ios.simulator.guest_process_count': 312, + }); + await expect(collector?.collect('dispose')).resolves.toEqual({ + 'ios.simulator.guest_process_count': 312, + }); + await expect(collector?.collect('app.ready')).resolves.toEqual({}); + await expect(collector?.collect('test-file.start')).resolves.toEqual({}); + expect(getGuestProcessCount).toHaveBeenCalledTimes(2); + expect(getGuestProcessCount).toHaveBeenCalledWith('sim-udid'); + }); + + 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 +342,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 +385,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 +428,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..d6057935 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,63 @@ describe('simctl startup', () => { } ); }); + + it('counts guest launchd services without the header line', async () => { + const spawnSpy = vi.spyOn(tools, 'spawn').mockResolvedValue({ + stdout: 'PID\tStatus\tLabel\n-\t0\tcom.apple.progressd\n95823\t0\tcom.apple.homed\n', + } as Awaited>); + + await expect(getGuestProcessCount('sim-udid')).resolves.toBe(2); + expect(spawnSpy).toHaveBeenCalledWith( + 'xcrun', + ['simctl', 'spawn', 'sim-udid', 'launchctl', 'list'], + { timeout: 30_000 }, + ); + }); +}); + +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..63e38cd5 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): 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), + }; + }, + }), }; }; 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..1d3e95f9 100644 --- a/packages/platform-ios/src/xcrun/simctl.ts +++ b/packages/platform-ios/src/xcrun/simctl.ts @@ -340,13 +340,68 @@ 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 services the simulator's own `launchd` is managing. A guest that + * is overloaded or still migrating shows up here long before anything fails. + */ +export const getGuestProcessCount = async (udid: string): Promise => { + const { stdout } = await spawn( + 'xcrun', + ['simctl', 'spawn', udid, 'launchctl', 'list'], + { timeout: GUEST_PROCESS_LIST_TIMEOUT_MS }, + ); + // The first line is the column header (PID Status Label). + return Math.max(0, stdout.split('\n').filter((line) => line.trim()).length - 1); }; 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 d1908d9c..5075e3e0 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 = { From 64a68d399a020644d341ba264efde800f0873df4 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:51:47 +0200 Subject: [PATCH 04/10] feat(config): accept an object form for the diagnostics option diagnostics can now be a boolean or an object with enabled, probes (host, node, snapshots, platform) and sampleIntervalMs. isDiagnosticsEnabled keeps its semantics (true, an object that does not opt out, or RN_HARNESS_DIAGNOSTICS), and resolveDiagnosticsOptions fills in defaults. --- .../src/__tests__/diagnostics-config.test.ts | 128 ++++++++++++++++++ packages/config/src/index.ts | 3 +- packages/config/src/types.ts | 106 +++++++++++++-- 3 files changed, 228 insertions(+), 9 deletions(-) create mode 100644 packages/config/src/__tests__/diagnostics-config.test.ts 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 965c6f53..16e1a636 100644 --- a/packages/config/src/types.ts +++ b/packages/config/src/types.ts @@ -221,14 +221,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 @@ -253,14 +305,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; } @@ -268,6 +325,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: From 02f0dd4c6e81dc7bf3454bc4d3dc799cc0f59e9d Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:56:20 +0200 Subject: [PATCH 05/10] feat(jest): persist run telemetry incrementally and summarise run KPIs The session now starts telemetry through one composition point (startSessionTelemetry) and only emits lifecycle phases (session.created, metro.ready, platform.ready, app.ready, test-file.start/end, dispose); probes translate them into diagnostics entries. End-of-run collection is awaited, with a bound, before the platform is torn down. Entries are appended to .harness/diagnostics/.jsonl as they arrive (batched, flushed on exit and on SIGINT/SIGTERM) so a cancelled CI job keeps its data. Gauges are written to the Chrome trace as counter events so Perfetto graphs them. summarizeRunKpis reduces a run to boot wait, time to ready, host pressure peaks and the result; it is printed, written to .summary.json and appended to GITHUB_STEP_SUMMARY when set. --- .../jest/src/__tests__/execute-run.test.ts | 48 +- packages/jest/src/__tests__/index.test.ts | 9 +- .../src/diagnostics/__tests__/report.test.ts | 438 +++++++++++++++++- .../diagnostics/__tests__/telemetry.test.ts | 178 +++++++ packages/jest/src/diagnostics/index.ts | 12 +- packages/jest/src/diagnostics/report.ts | 274 ++++++++++- packages/jest/src/diagnostics/telemetry.ts | 106 +++++ packages/jest/src/execute-run.ts | 26 +- packages/jest/src/harness-session.ts | 44 +- 9 files changed, 1119 insertions(+), 16 deletions(-) create mode 100644 packages/jest/src/diagnostics/__tests__/telemetry.test.ts create mode 100644 packages/jest/src/diagnostics/telemetry.ts diff --git a/packages/jest/src/__tests__/execute-run.test.ts b/packages/jest/src/__tests__/execute-run.test.ts index 3c234f1d..a1aff0b0 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,22 @@ describe('executeRun', () => { }); }); + it('emits test-file lifecycle phases around every file', 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([ + ['test-file.start', { file }], + ['test-file.end', { file, 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..061f7df1 100644 --- a/packages/jest/src/diagnostics/__tests__/report.test.ts +++ b/packages/jest/src/diagnostics/__tests__/report.test.ts @@ -1,9 +1,19 @@ 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, + createDiagnosticsAppender, + printSummary, + summarizeRunKpis, + writeSummaryFile, + writeTraceFile, +} from '../report.js'; const makeSpanEntry = ( overrides: Partial = {}, @@ -16,6 +26,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 +93,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 +184,377 @@ 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(); + 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); + + 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); + await expect(fs.stat(appender.filePath)).rejects.toThrow(); + + vi.advanceTimersByTime(2000); + + 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], + ]); + + appender.dispose(); + }); + + it('flushes as soon as enough entries are buffered', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'batch', + maxBufferedEntries: 3, + }); + + diagnostics.mark('1'); + diagnostics.mark('2'); + await expect(fs.stat(appender.filePath)).rejects.toThrow(); + diagnostics.mark('3'); + + expect(await readLines(appender.filePath)).toHaveLength(3); + appender.dispose(); + }); + + 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); + appender.flush(); + + expect(await readLines(appender.filePath)).toHaveLength(1); + appender.dispose(); + }); + + it('flushes on dispose and stops observing afterwards', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'dispose', + }); + + diagnostics.mark('before'); + appender.dispose(); + diagnostics.mark('after'); + appender.flush(); + + expect((await readLines(appender.filePath)).map((e) => e.label)).toEqual([ + 'before', + ]); + }); + + it('flushes on process exit', async () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'exit', + }); + + diagnostics.mark('last-words'); + process.emit('exit', 0); + + expect(await readLines(appender.filePath)).toHaveLength(1); + appender.dispose(); + }); + + it.each(['SIGTERM', 'SIGINT'] as const)( + 'flushes on %s and leaves other handlers in charge of termination', + async (signal) => { + const kill = vi.spyOn(process, 'kill').mockImplementation(() => true); + const otherHandler = vi.fn(); + process.on(signal, otherHandler); + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: `signal-${signal}`, + }); + + diagnostics.mark('before-kill'); + process.emit(signal); + + expect(await readLines(appender.filePath)).toHaveLength(1); + expect(kill).not.toHaveBeenCalled(); + + appender.dispose(); + process.off(signal, otherHandler); + }, + ); + + it('re-raises the signal when it was the only handler', async () => { + const kill = vi.spyOn(process, 'kill').mockImplementation(() => true); + const baseline = process.listenerCount('SIGTERM'); + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot, + id: 'only-handler', + }); + // Only ours is registered if nothing else was (the common test setup). + const others = process.listeners('SIGTERM').slice(0, baseline); + others.forEach((listener) => process.off('SIGTERM', listener)); + + diagnostics.mark('x'); + process.emit('SIGTERM'); + + expect(kill).toHaveBeenCalledWith(process.pid, 'SIGTERM'); + expect(process.listenerCount('SIGTERM')).toBe(0); + + others.forEach((listener) => process.on('SIGTERM', listener)); + appender.dispose(); + }); + + it('removes every process listener on dispose', () => { + const before = { + exit: process.listenerCount('exit'), + sigterm: process.listenerCount('SIGTERM'), + sigint: process.listenerCount('SIGINT'), + }; + const appender = createDiagnosticsAppender( + createDiagnostics({ enabled: true }), + { projectRoot, id: 'listeners' }, + ); + appender.dispose(); + + expect({ + exit: process.listenerCount('exit'), + sigterm: process.listenerCount('SIGTERM'), + sigint: process.listenerCount('SIGINT'), + }).toEqual(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(); + appender.dispose(); + + expect(setIntervalSpy).not.toHaveBeenCalled(); + expect(process.listenerCount('exit')).toBe(before); + await expect(fs.stat(path.join(projectRoot, '.harness'))).rejects.toThrow(); + }); + + it('never throws when the directory cannot be written', () => { + const diagnostics = createDiagnostics({ enabled: true }); + const appender = createDiagnosticsAppender(diagnostics, { + projectRoot: '/dev/null/nope', + id: 'unwritable', + }); + + diagnostics.mark('a'); + expect(() => appender.flush()).not.toThrow(); + appender.dispose(); + }); }); 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..42fd421d --- /dev/null +++ b/packages/jest/src/diagnostics/__tests__/telemetry.test.ts @@ -0,0 +1,178 @@ +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 { 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('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..a44dc009 100644 --- a/packages/jest/src/diagnostics/index.ts +++ b/packages/jest/src/diagnostics/index.ts @@ -1,2 +1,12 @@ export { observeMetroEvents, observeBridgeEvents } from './derivers.js'; -export { writeTraceFile, printSummary } from './report.js'; +export { + writeTraceFile, + 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..6c017a43 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 } 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,246 @@ 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 buffered so far. */ + flush(): void; + /** Flushes, then stops the timer and removes every process listener. */ + dispose(): void; +}; + +const APPENDED_SIGNALS = ['SIGINT', 'SIGTERM'] as const; + +/** + * 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. + * + * Writes are batched (every `flushIntervalMs` or `maxBufferedEntries`) and + * synchronous, so they also work from `exit` and signal handlers. A signal is + * re-raised after flushing when nothing else is listening for it, so + * persistence never changes how the process terminates. + */ +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: () => undefined }; + } + + const maxBufferedEntries = options.maxBufferedEntries ?? 100; + let buffer: string[] = []; + let directoryReady = false; + + const flush = () => { + if (buffer.length === 0) { + return; + } + + const lines = buffer; + buffer = []; + try { + if (!directoryReady) { + fsSync.mkdirSync(path.dirname(filePath), { recursive: true }); + directoryReady = true; + } + fsSync.appendFileSync(filePath, `${lines.join('\n')}\n`, '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) { + flush(); + } + }); + + const timer = setInterval(flush, options.flushIntervalMs ?? 2000); + timer.unref(); + + const signalHandlers = new Map void>(); + for (const signal of APPENDED_SIGNALS) { + const handler = () => { + flush(); + if (process.listenerCount(signal) === 1) { + // Ours is the only handler: restore the default behaviour (terminate). + process.off(signal, handler); + process.kill(process.pid, signal); + } + }; + signalHandlers.set(signal, handler); + process.on(signal, handler); + } + process.on('exit', flush); + + const dispose = () => { + unsubscribe(); + clearInterval(timer); + flush(); + process.off('exit', flush); + for (const [signal, handler] of signalHandlers) { + process.off(signal, handler); + } + signalHandlers.clear(); + }; + + return { filePath, flush, 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); + } +}; + const formatDuration = (ms: number): string => { if (ms >= 1000) { return `${(ms / 1000).toFixed(1)}s`; @@ -82,6 +338,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 +381,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..4422f08f --- /dev/null +++ b/packages/jest/src/diagnostics/telemetry.ts @@ -0,0 +1,106 @@ +import { randomUUID } from 'node:crypto'; +import { + 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 { createDiagnosticsAppender } from './report.js'; + +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; + /** Resolves once lifecycle driven collection started so far has finished. */ + settled(): Promise; + /** Stops probes and the incremental log. 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; + + 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; + }, + settled: run.settled, + dispose: () => { + disposed ??= (async () => { + try { + abortController.abort(); + await run.dispose(); + } finally { + appender.dispose(); + } + })(); + return disposed; + }, + }; +}; diff --git a/packages/jest/src/execute-run.ts b/packages/jest/src/execute-run.ts index 04a14e8f..32112334 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'); @@ -227,6 +233,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 +347,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) { @@ -365,6 +381,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 528e7dcc..567502a7 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; @@ -494,6 +505,15 @@ 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'); + sessionLogger.debug( 'creating session for runner=%s platform=%s', platform.name, @@ -539,7 +559,10 @@ export const createHarnessSession = async ( }, }), { lockKey: resourceLockKey } - ); + ).catch(async (error) => { + await telemetry.dispose(); + throw error; + }); if (didWaitForResourceLock) logRunnerStarting(platform); sessionLogger.debug('resource lock acquired for runner=%s key=%s', platform.name, resourceLockKey); @@ -638,6 +661,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); @@ -679,6 +703,8 @@ export const createHarnessSession = async ( } initialized.platform = instance; sessionLogger.debug('platform runner initialized'); + telemetry.attachPlatform(instance); + telemetry.phase('platform.ready'); return instance; }); }, @@ -808,6 +834,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(); @@ -840,6 +867,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); } @@ -900,7 +934,7 @@ export const createHarnessSession = async ( }; const dispose = (reason: 'normal' | 'abort' | 'error' = 'normal') => { - disposePromise ??= disposeOnce(reason); + disposePromise ??= disposeOnce(reason).finally(() => telemetry.dispose()); return disposePromise; }; @@ -966,6 +1000,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 @@ -1118,6 +1153,8 @@ export const createHarnessSession = async ( config: runtimeConfig, context, diagnostics, + sessionId: telemetry.sessionId, + lifecycle: telemetry.lifecycle, onTestRunnerEvent: (listener) => { testRunnerEventListeners.add(listener); return () => { @@ -1157,6 +1194,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); From 95894e84894befc32aa32528cf8e0b8222e23027 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:57:28 +0200 Subject: [PATCH 06/10] docs: document run diagnostics and the diagnostics config object --- .../docs/getting-started/configuration.mdx | 50 +++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/website/src/docs/getting-started/configuration.mdx b/website/src/docs/getting-started/configuration.mdx index 2a0d6f16..62c5364a 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. | @@ -281,6 +282,55 @@ 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, when the app becomes ready, and at the end of the run. For iOS simulators it records `platform.ios.simulator.guest_process_count`, 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 on `SIGINT`/`SIGTERM`), 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`. | + +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. From 172ae0dcd44a546effbc039d3e7aceb593b5e9a7 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 08:57:45 +0200 Subject: [PATCH 07/10] chore: add version plan for run telemetry --- .nx/version-plans/version-plan-1792133861187.md | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 .nx/version-plans/version-plan-1792133861187.md 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. From 3ee3f6cff4f721f2953a74a5f0be8c931879f41a Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 09:15:20 +0200 Subject: [PATCH 08/10] fix(tools): bound telemetry teardown and stop idle or late probe work TelemetryCollector.collect now receives an abort signal that fires when the probe stops or the context aborts, and the iOS guest process listing passes it to its spawn, so teardown never waits on a measurement nobody will read. run.dispose() no longer waits for work whose context was already aborted, and bounds the wait otherwise. Queued probe jobs are skipped once a probe stops or aborts, so no collect() runs after collector.dispose() and no AbortError snapshot marks are written. The process snapshot is now taken at platform.ready, the first app.ready and dispose only, instead of after every app relaunch. Samplers pause on the new run.end phase and resume on run.start or dispose, so a watch-mode session no longer accumulates idle samples while a single run still samples from session start to teardown. Diagnostics.subscribe gains a replay option for sinks attached after entries were recorded. guest_process_count now counts only launchd rows with a PID (running processes), not loaded jobs. --- .../src/__tests__/instance.test.ts | 11 +-- .../platform-ios/src/__tests__/simctl.test.ts | 10 ++- packages/platform-ios/src/instance.ts | 4 +- packages/platform-ios/src/xcrun/simctl.ts | 16 ++-- .../tools/src/__tests__/diagnostics.test.ts | 24 ++++++ packages/tools/src/diagnostics.ts | 20 ++++- .../__tests__/host-resources.test.ts | 42 ++++++++++ .../src/telemetry/__tests__/index.test.ts | 42 +++++++++- .../__tests__/platform-collector.test.ts | 52 +++++++++++- .../__tests__/process-snapshot.test.ts | 62 +++++++++++++- .../tools/src/telemetry/host-resources.ts | 7 +- packages/tools/src/telemetry/index.ts | 22 ++++- packages/tools/src/telemetry/node-runtime.ts | 6 +- .../tools/src/telemetry/platform-collector.ts | 14 +++- packages/tools/src/telemetry/probe-utils.ts | 82 +++++++++++++++---- .../tools/src/telemetry/process-snapshot.ts | 29 +++++-- packages/tools/src/telemetry/types.ts | 11 ++- 17 files changed, 397 insertions(+), 57 deletions(-) diff --git a/packages/platform-ios/src/__tests__/instance.test.ts b/packages/platform-ios/src/__tests__/instance.test.ts index 1b0724fe..4056d6c2 100644 --- a/packages/platform-ios/src/__tests__/instance.test.ts +++ b/packages/platform-ios/src/__tests__/instance.test.ts @@ -285,16 +285,17 @@ describe('iOS platform instance dependency validation', () => { ); const collector = instance.createTelemetryCollector?.(); - await expect(collector?.collect('platform.ready')).resolves.toEqual({ + 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')).resolves.toEqual({ + await expect(collector?.collect('dispose', signal)).resolves.toEqual({ 'ios.simulator.guest_process_count': 312, }); - await expect(collector?.collect('app.ready')).resolves.toEqual({}); - await expect(collector?.collect('test-file.start')).resolves.toEqual({}); + 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'); + expect(getGuestProcessCount).toHaveBeenCalledWith('sim-udid', signal); }); it('records the last bootstatus stage on the waitForBoot span', async () => { diff --git a/packages/platform-ios/src/__tests__/simctl.test.ts b/packages/platform-ios/src/__tests__/simctl.test.ts index d6057935..23357c4e 100644 --- a/packages/platform-ios/src/__tests__/simctl.test.ts +++ b/packages/platform-ios/src/__tests__/simctl.test.ts @@ -116,16 +116,18 @@ describe('simctl startup', () => { ); }); - it('counts guest launchd services without the header line', async () => { + 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', + 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')).resolves.toBe(2); + await expect(getGuestProcessCount('sim-udid', signal)).resolves.toBe(2); expect(spawnSpy).toHaveBeenCalledWith( 'xcrun', ['simctl', 'spawn', 'sim-udid', 'launchctl', 'list'], - { timeout: 30_000 }, + { timeout: 30_000, signal }, ); }); }); diff --git a/packages/platform-ios/src/instance.ts b/packages/platform-ios/src/instance.ts index 63e38cd5..5aefeea3 100644 --- a/packages/platform-ios/src/instance.ts +++ b/packages/platform-ios/src/instance.ts @@ -240,7 +240,7 @@ export const getAppleSimulatorPlatformInstance = async ( }); }, createTelemetryCollector: () => ({ - collect: async (phase): Promise> => { + 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') { @@ -249,7 +249,7 @@ export const getAppleSimulatorPlatformInstance = async ( return { 'ios.simulator.guest_process_count': - await simctl.getGuestProcessCount(udid), + await simctl.getGuestProcessCount(udid, signal), }; }, }), diff --git a/packages/platform-ios/src/xcrun/simctl.ts b/packages/platform-ios/src/xcrun/simctl.ts index 1d3e95f9..a602b689 100644 --- a/packages/platform-ios/src/xcrun/simctl.ts +++ b/packages/platform-ios/src/xcrun/simctl.ts @@ -391,17 +391,21 @@ export const waitForBoot = async ( const GUEST_PROCESS_LIST_TIMEOUT_MS = 30_000; /** - * Counts the services the simulator's own `launchd` is managing. A guest that - * is overloaded or still migrating shows up here long before anything fails. + * 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): Promise => { +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 }, + { timeout: GUEST_PROCESS_LIST_TIMEOUT_MS, signal }, ); - // The first line is the column header (PID Status Label). - return Math.max(0, stdout.split('\n').filter((line) => line.trim()).length - 1); + return stdout.split('\n').filter((line) => /^\d+\s/.test(line)).length; }; export const diagnose = async ( diff --git a/packages/tools/src/__tests__/diagnostics.test.ts b/packages/tools/src/__tests__/diagnostics.test.ts index cc9f357f..2d7c5220 100644 --- a/packages/tools/src/__tests__/diagnostics.test.ts +++ b/packages/tools/src/__tests__/diagnostics.test.ts @@ -153,6 +153,30 @@ describe('createDiagnostics (enabled)', () => { 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[] = []; diff --git a/packages/tools/src/diagnostics.ts b/packages/tools/src/diagnostics.ts index 0e868edd..ea66e7bd 100644 --- a/packages/tools/src/diagnostics.ts +++ b/packages/tools/src/diagnostics.ts @@ -39,9 +39,15 @@ export type 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. Returns a function that unsubscribes. + * 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): () => void; + subscribe( + listener: DiagnosticEntryListener, + options?: { replay?: boolean } + ): () => void; flush(): DiagnosticEntry[]; }; @@ -228,7 +234,15 @@ const createEnabledDiagnostics = ( ); }; - const subscribe = (listener: DiagnosticEntryListener): (() => void) => { + 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); diff --git a/packages/tools/src/telemetry/__tests__/host-resources.test.ts b/packages/tools/src/telemetry/__tests__/host-resources.test.ts index 9f470900..58e896cd 100644 --- a/packages/tools/src/telemetry/__tests__/host-resources.test.ts +++ b/packages/tools/src/telemetry/__tests__/host-resources.test.ts @@ -205,6 +205,48 @@ describe('hostResourcesProbe', () => { 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); diff --git a/packages/tools/src/telemetry/__tests__/index.test.ts b/packages/tools/src/telemetry/__tests__/index.test.ts index c3274a2a..85c022ea 100644 --- a/packages/tools/src/telemetry/__tests__/index.test.ts +++ b/packages/tools/src/telemetry/__tests__/index.test.ts @@ -9,6 +9,7 @@ vi.mock('../../spawn.js', () => ({ spawn: vi.fn() })); describe('startTelemetryProbes', () => { afterEach(() => { + vi.useRealTimers(); vi.restoreAllMocks(); }); @@ -81,6 +82,7 @@ describe('startTelemetryProbes', () => { }); it('exposes in-flight tracked work through settled()', async () => { + vi.useFakeTimers(); let finished = false; const probe: TelemetryProbe = { name: 'slow', @@ -100,11 +102,49 @@ describe('startTelemetryProbes', () => { const run = startTelemetryProbes([probe], ctx); expect(finished).toBe(false); - await run.settled(); + 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(); diff --git a/packages/tools/src/telemetry/__tests__/platform-collector.test.ts b/packages/tools/src/telemetry/__tests__/platform-collector.test.ts index 6e78a101..ec03e0a2 100644 --- a/packages/tools/src/telemetry/__tests__/platform-collector.test.ts +++ b/packages/tools/src/telemetry/__tests__/platform-collector.test.ts @@ -17,7 +17,10 @@ describe('platform collector probe', () => { ctx.lifecycle.emit({ type: 'phase', phase: 'platform.ready' }); await settle(ctx); - expect(collector.collect).toHaveBeenCalledWith('platform.ready'); + 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', @@ -81,4 +84,51 @@ describe('platform collector probe', () => { 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 index 86548f20..a0d90fb6 100644 --- a/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts +++ b/packages/tools/src/telemetry/__tests__/process-snapshot.test.ts @@ -64,6 +64,7 @@ describe('processSnapshotProbe', () => { }); afterEach(() => { + vi.useRealTimers(); vi.restoreAllMocks(); }); @@ -122,13 +123,14 @@ describe('processSnapshotProbe', () => { }); 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)); + await new Promise((resolve) => setTimeout(resolve, 5_000)); active -= 1; return { stdout: TOP_FIXTURE }; }) as never); @@ -137,14 +139,68 @@ describe('processSnapshotProbe', () => { ctx.lifecycle.emit({ type: 'phase', phase: 'app.ready' }); ctx.lifecycle.emit({ type: 'phase', phase: 'dispose' }); - await settle(ctx); - await new Promise((resolve) => setTimeout(resolve, 30)); + 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')); diff --git a/packages/tools/src/telemetry/host-resources.ts b/packages/tools/src/telemetry/host-resources.ts index 6648e5fd..b9c86457 100644 --- a/packages/tools/src/telemetry/host-resources.ts +++ b/packages/tools/src/telemetry/host-resources.ts @@ -220,7 +220,12 @@ export const hostResourcesProbe: TelemetryProbe = { const { diagnostics } = ctx; let previousCpu: CpuTimes | null = null; - return startSampler(ctx, async (signal) => { + 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(); diff --git a/packages/tools/src/telemetry/index.ts b/packages/tools/src/telemetry/index.ts index 776b49c7..36ad9ba4 100644 --- a/packages/tools/src/telemetry/index.ts +++ b/packages/tools/src/telemetry/index.ts @@ -58,10 +58,18 @@ export const createDefaultProbes = ( 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. */ + /** + * 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; }; @@ -118,7 +126,17 @@ export const startTelemetryProbes = ( telemetryLogger.debug('probe %s failed to stop: %s', name, error); } } - await settled(); + if (!ctx.signal.aborted) { + let timer: NodeJS.Timeout | undefined; + const timeout = new Promise((resolve) => { + timer = setTimeout(resolve, DISPOSE_SETTLE_TIMEOUT_MS); + }); + try { + await Promise.race([settled(), timeout]); + } finally { + clearTimeout(timer); + } + } })(); return disposed; }; diff --git a/packages/tools/src/telemetry/node-runtime.ts b/packages/tools/src/telemetry/node-runtime.ts index e74fc9b4..ecca534a 100644 --- a/packages/tools/src/telemetry/node-runtime.ts +++ b/packages/tools/src/telemetry/node-runtime.ts @@ -24,7 +24,11 @@ export const nodeRuntimeProbe: TelemetryProbe = { const histogram = monitorEventLoopDelay({ resolution: RESOLUTION_MS }); histogram.enable(); - const stopSampling = startSampler(ctx, () => { + const stopSampling = startSampler(ctx, (_signal, { afterPause }) => { + if (afterPause) { + histogram.reset(); + } + const memory = process.memoryUsage(); diagnostics.gauge( 'node.rss_mb', diff --git a/packages/tools/src/telemetry/platform-collector.ts b/packages/tools/src/telemetry/platform-collector.ts index eebe5e02..e859e939 100644 --- a/packages/tools/src/telemetry/platform-collector.ts +++ b/packages/tools/src/telemetry/platform-collector.ts @@ -32,18 +32,21 @@ export const createPlatformCollectorProbe = ({ name: 'platform-collector', start: (ctx) => { const { diagnostics } = ctx; - const enqueue = createSerialQueue(); + 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 }) => - enqueue(async () => { + queue.run(async () => { collector ??= getCollector(); if (!collector) { return; } - const values = await collector.collect(phase); - if (ctx.signal.aborted) { + const values = await collector.collect(phase, controller.signal); + if (controller.signal.aborted) { return; } @@ -64,6 +67,9 @@ export const createPlatformCollectorProbe = ({ 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 index f365b1f9..891000a4 100644 --- a/packages/tools/src/telemetry/probe-utils.ts +++ b/packages/tools/src/telemetry/probe-utils.ts @@ -1,35 +1,46 @@ 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, - sample: (signal: AbortSignal) => void | Promise + ctx: Pick< + ProbeContext, + 'signal' | 'track' | 'sampleIntervalMs' | 'lifecycle' + >, + sample: (signal: AbortSignal, info: SampleInfo) => void | Promise ): (() => void) => { const controller = new AbortController(); let running = false; - - const stop = () => { - clearInterval(timer); - controller.abort(); - ctx.signal.removeEventListener('abort', stop); - }; + let paused = false; + let afterPause = false; const tick = () => { - if (running || controller.signal.aborted) { + if (running || paused || controller.signal.aborted) { return; } running = true; + const info = { afterPause }; + afterPause = false; const work = (async () => { try { - await sample(controller.signal); + await sample(controller.signal, info); } catch { // A failed sample is dropped; the next tick tries again. } finally { @@ -39,9 +50,30 @@ export const startSampler = ( 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); timer.unref(); ctx.signal.addEventListener('abort', stop, { once: true }); + ctx.lifecycle.addListener(onPhase); tick(); return stop; @@ -76,19 +108,33 @@ export const onLifecyclePhases = ( 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. + * 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 = (): (( - job: () => Promise -) => Promise) => { +export const createSerialQueue = (): SerialQueue => { let tail: Promise = Promise.resolve(); + let closed = false; - return (job) => { - const result = tail.then(job, job); - tail = result.catch(() => undefined); - return result.catch(() => undefined); + 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 index 14d9c971..f3c7be84 100644 --- a/packages/tools/src/telemetry/process-snapshot.ts +++ b/packages/tools/src/telemetry/process-snapshot.ts @@ -75,13 +75,26 @@ export const processSnapshotProbe: TelemetryProbe = { } const { diagnostics, signal } = ctx; - const enqueue = createSerialQueue(); + 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; - return onLifecyclePhases( + const stop = onLifecyclePhases( ctx, ['platform.ready', 'app.ready', 'dispose'], - ({ phase }) => - enqueue(async () => { + ({ phase }) => { + if (phase === 'app.ready') { + if (appReadySeen) { + return; + } + appReadySeen = true; + } + + return queue.run(async () => { + if (signal.aborted) { + return; + } try { const { stdout } = await spawn( 'top', @@ -115,7 +128,13 @@ export const processSnapshotProbe: TelemetryProbe = { error: String(error).slice(0, 200), }); } - }) + }); + } ); + + return () => { + stop(); + queue.close(); + }; }, }; diff --git a/packages/tools/src/telemetry/types.ts b/packages/tools/src/telemetry/types.ts index 053da8b9..04d88fee 100644 --- a/packages/tools/src/telemetry/types.ts +++ b/packages/tools/src/telemetry/types.ts @@ -8,6 +8,8 @@ import type { EventEmitter } from '../events.js'; */ export type LifecyclePhase = | 'session.created' + | 'run.start' + | 'run.end' | 'metro.ready' | 'platform.ready' | 'app.ready' @@ -47,6 +49,13 @@ export type TelemetryProbe = { * become gauges named `platform.`; strings become attrs of a mark. */ export type TelemetryCollector = { - collect(phase: LifecyclePhase): Promise>; + /** + * `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; }; From 58b1d5ab72d9dea487637fb2864fb3dc17139ec0 Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 09:17:36 +0200 Subject: [PATCH 09/10] fix(jest): make incremental diagnostics non-blocking and complete The appender now writes asynchronously, one chunk at a time, so recording an entry never blocks on disk; only the exit handler writes synchronously (and also writes chunks still pending). SIGINT/SIGTERM handlers are removed: the session owns those signals and leaves through process.exit, and a re-raise that depends on listener order can fight other handlers. The appender replays entries recorded before it attached, so session.config.load is in the log. Entries recorded after a run's report was written (the dispose-phase process snapshot and guest process count, dispose.total) are appended to that run's trace when the session is disposed. executeRun emits run.start and run.end so samplers pause between runs in watch mode. Telemetry is also stopped when setup fails before the main try block. --- .../jest/src/__tests__/execute-run.test.ts | 4 +- .../src/diagnostics/__tests__/report.test.ts | 200 ++++++++++++------ .../diagnostics/__tests__/telemetry.test.ts | 54 +++++ packages/jest/src/diagnostics/index.ts | 1 + packages/jest/src/diagnostics/report.ts | 149 +++++++++---- packages/jest/src/diagnostics/telemetry.ts | 33 ++- packages/jest/src/execute-run.ts | 11 + packages/jest/src/harness-session.ts | 21 +- .../docs/getting-started/configuration.mdx | 6 +- 9 files changed, 352 insertions(+), 127 deletions(-) diff --git a/packages/jest/src/__tests__/execute-run.test.ts b/packages/jest/src/__tests__/execute-run.test.ts index a1aff0b0..c34886d8 100644 --- a/packages/jest/src/__tests__/execute-run.test.ts +++ b/packages/jest/src/__tests__/execute-run.test.ts @@ -275,7 +275,7 @@ describe('executeRun', () => { }); }); - it('emits test-file lifecycle phases around every file', async () => { + it('emits run and test-file lifecycle phases', async () => { const session = makeSession(); const phases: Array<[string, unknown]> = []; session.lifecycle.addListener((event) => @@ -286,8 +286,10 @@ describe('executeRun', () => { 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' }], ]); }); diff --git a/packages/jest/src/diagnostics/__tests__/report.test.ts b/packages/jest/src/diagnostics/__tests__/report.test.ts index 061f7df1..92358770 100644 --- a/packages/jest/src/diagnostics/__tests__/report.test.ts +++ b/packages/jest/src/diagnostics/__tests__/report.test.ts @@ -1,3 +1,4 @@ +import fsSync from 'node:fs'; import fs from 'node:fs/promises'; import os from 'node:os'; import path from 'node:path'; @@ -8,6 +9,7 @@ import { } from '@react-native-harness/tools'; import { appendStepSummary, + appendToTraceFile, createDiagnosticsAppender, printSummary, summarizeRunKpis, @@ -360,7 +362,7 @@ describe('createDiagnosticsAppender', () => { let projectRoot: string; beforeEach(async () => { - vi.useFakeTimers(); + vi.useFakeTimers({ toFake: ['setInterval', 'clearInterval'] }); projectRoot = await fs.mkdtemp(path.join(os.tmpdir(), 'harness-appender-test-')); }); @@ -376,6 +378,12 @@ describe('createDiagnosticsAppender', () => { .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, { @@ -388,21 +396,21 @@ describe('createDiagnosticsAppender', () => { diagnostics.mark('a'); diagnostics.child('host').gauge('load1', 2.5); - await expect(fs.stat(appender.filePath)).rejects.toThrow(); + 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], ]); - - appender.dispose(); }); - it('flushes as soon as enough entries are buffered', async () => { + 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', @@ -411,11 +419,47 @@ describe('createDiagnosticsAppender', () => { diagnostics.mark('1'); diagnostics.mark('2'); - await expect(fs.stat(appender.filePath)).rejects.toThrow(); diagnostics.mark('3'); + expect(appendFileSync).not.toHaveBeenCalled(); + await appender.dispose(); expect(await readLines(appender.filePath)).toHaveLength(3); - appender.dispose(); + 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 () => { @@ -427,13 +471,12 @@ describe('createDiagnosticsAppender', () => { diagnostics.mark('a'); expect(diagnostics.flush()).toHaveLength(1); - appender.flush(); + await appender.dispose(); expect(await readLines(appender.filePath)).toHaveLength(1); - appender.dispose(); }); - it('flushes on dispose and stops observing afterwards', async () => { + it('stops observing after dispose', async () => { const diagnostics = createDiagnostics({ enabled: true }); const appender = createDiagnosticsAppender(diagnostics, { projectRoot, @@ -441,7 +484,7 @@ describe('createDiagnosticsAppender', () => { }); diagnostics.mark('before'); - appender.dispose(); + await appender.dispose(); diagnostics.mark('after'); appender.flush(); @@ -450,82 +493,54 @@ describe('createDiagnosticsAppender', () => { ]); }); - it('flushes on process exit', async () => { + 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('last-words'); + diagnostics.mark('queued-1'); + diagnostics.mark('queued-2'); // handed to the async writer, not yet awaited + diagnostics.mark('buffered'); process.emit('exit', 0); - expect(await readLines(appender.filePath)).toHaveLength(1); - appender.dispose(); - }); - - it.each(['SIGTERM', 'SIGINT'] as const)( - 'flushes on %s and leaves other handlers in charge of termination', - async (signal) => { - const kill = vi.spyOn(process, 'kill').mockImplementation(() => true); - const otherHandler = vi.fn(); - process.on(signal, otherHandler); - const diagnostics = createDiagnostics({ enabled: true }); - const appender = createDiagnosticsAppender(diagnostics, { - projectRoot, - id: `signal-${signal}`, - }); - - diagnostics.mark('before-kill'); - process.emit(signal); - - expect(await readLines(appender.filePath)).toHaveLength(1); - expect(kill).not.toHaveBeenCalled(); - - appender.dispose(); - process.off(signal, otherHandler); - }, - ); - - it('re-raises the signal when it was the only handler', async () => { - const kill = vi.spyOn(process, 'kill').mockImplementation(() => true); - const baseline = process.listenerCount('SIGTERM'); - const diagnostics = createDiagnostics({ enabled: true }); - const appender = createDiagnosticsAppender(diagnostics, { - projectRoot, - id: 'only-handler', - }); - // Only ours is registered if nothing else was (the common test setup). - const others = process.listeners('SIGTERM').slice(0, baseline); - others.forEach((listener) => process.off('SIGTERM', listener)); - - diagnostics.mark('x'); - process.emit('SIGTERM'); - - expect(kill).toHaveBeenCalledWith(process.pid, 'SIGTERM'); - expect(process.listenerCount('SIGTERM')).toBe(0); - - others.forEach((listener) => process.on('SIGTERM', listener)); - appender.dispose(); + 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('removes every process listener on dispose', () => { + it('does not install signal handlers', async () => { const before = { - exit: process.listenerCount('exit'), sigterm: process.listenerCount('SIGTERM'), sigint: process.listenerCount('SIGINT'), }; const appender = createDiagnosticsAppender( createDiagnostics({ enabled: true }), - { projectRoot, id: 'listeners' }, + { projectRoot, id: 'signals' }, ); - appender.dispose(); expect({ - exit: process.listenerCount('exit'), 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 () => { @@ -539,14 +554,14 @@ describe('createDiagnosticsAppender', () => { }); diagnostics.mark('a'); appender.flush(); - appender.dispose(); + await appender.dispose(); expect(setIntervalSpy).not.toHaveBeenCalled(); expect(process.listenerCount('exit')).toBe(before); - await expect(fs.stat(path.join(projectRoot, '.harness'))).rejects.toThrow(); + expect(await exists(path.join(projectRoot, '.harness'))).toBe(false); }); - it('never throws when the directory cannot be written', () => { + it('never throws when the directory cannot be written', async () => { const diagnostics = createDiagnostics({ enabled: true }); const appender = createDiagnosticsAppender(diagnostics, { projectRoot: '/dev/null/nope', @@ -555,6 +570,53 @@ describe('createDiagnosticsAppender', () => { diagnostics.mark('a'); expect(() => appender.flush()).not.toThrow(); - appender.dispose(); + 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 index 42fd421d..cb63b25b 100644 --- a/packages/jest/src/diagnostics/__tests__/telemetry.test.ts +++ b/packages/jest/src/diagnostics/__tests__/telemetry.test.ts @@ -4,6 +4,7 @@ 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 = { @@ -164,6 +165,59 @@ describe('startSessionTelemetry', () => { } }); + 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 }), diff --git a/packages/jest/src/diagnostics/index.ts b/packages/jest/src/diagnostics/index.ts index a44dc009..5ce02fff 100644 --- a/packages/jest/src/diagnostics/index.ts +++ b/packages/jest/src/diagnostics/index.ts @@ -1,6 +1,7 @@ export { observeMetroEvents, observeBridgeEvents } from './derivers.js'; export { writeTraceFile, + appendToTraceFile, printSummary, createDiagnosticsAppender, summarizeRunKpis, diff --git a/packages/jest/src/diagnostics/report.ts b/packages/jest/src/diagnostics/report.ts index 6c017a43..29e1140e 100644 --- a/packages/jest/src/diagnostics/report.ts +++ b/packages/jest/src/diagnostics/report.ts @@ -77,24 +77,28 @@ const getDiagnosticsDir = (projectRoot: string): string => export type DiagnosticsAppender = { readonly filePath: string; - /** Synchronously writes everything buffered so far. */ + /** Synchronously writes everything not yet on disk. For `exit` handlers. */ flush(): void; - /** Flushes, then stops the timer and removes every process listener. */ - dispose(): void; + /** Waits for in-flight writes, then writes the rest and detaches. */ + dispose(): Promise; }; -const APPENDED_SIGNALS = ['SIGINT', 'SIGTERM'] as const; - /** * 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. * - * Writes are batched (every `flushIntervalMs` or `maxBufferedEntries`) and - * synchronous, so they also work from `exit` and signal handlers. A signal is - * re-raised after flushing when nothing else is listening for it, so - * persistence never changes how the process terminates. + * 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, @@ -111,68 +115,88 @@ export const createDiagnosticsAppender = ( ); if (!diagnostics.enabled) { - return { filePath, flush: () => undefined, dispose: () => undefined }; + 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 flush = () => { + const render = (lines: string[]) => `${lines.join('\n')}\n`; + + const flushAsync = () => { if (buffer.length === 0) { return; } const lines = buffer; buffer = []; - try { - if (!directoryReady) { - fsSync.mkdirSync(path.dirname(filePath), { recursive: true }); - directoryReady = true; + 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); } - fsSync.appendFileSync(filePath, `${lines.join('\n')}\n`, 'utf-8'); + }); + }; + + 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) { - flush(); - } - }); + const unsubscribe = diagnostics.subscribe( + (entry) => { + buffer.push(JSON.stringify(entry)); + if (buffer.length >= maxBufferedEntries) { + flushAsync(); + } + }, + { replay: true } + ); - const timer = setInterval(flush, options.flushIntervalMs ?? 2000); + const timer = setInterval(flushAsync, options.flushIntervalMs ?? 2000); timer.unref(); + process.on('exit', flushSync); - const signalHandlers = new Map void>(); - for (const signal of APPENDED_SIGNALS) { - const handler = () => { - flush(); - if (process.listenerCount(signal) === 1) { - // Ours is the only handler: restore the default behaviour (terminate). - process.off(signal, handler); - process.kill(process.pid, signal); - } - }; - signalHandlers.set(signal, handler); - process.on(signal, handler); - } - process.on('exit', flush); - - const dispose = () => { + const dispose = async () => { unsubscribe(); clearInterval(timer); - flush(); - process.off('exit', flush); - for (const [signal, handler] of signalHandlers) { - process.off(signal, handler); - } - signalHandlers.clear(); + process.off('exit', flushSync); + flushAsync(); + await writeChain; }; - return { filePath, flush, dispose }; + return { filePath, flush: flushSync, dispose }; }; export type RunKpis = { @@ -312,6 +336,39 @@ export const appendStepSummary = async ( } }; +/** + * 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`; diff --git a/packages/jest/src/diagnostics/telemetry.ts b/packages/jest/src/diagnostics/telemetry.ts index 4422f08f..fe9c590e 100644 --- a/packages/jest/src/diagnostics/telemetry.ts +++ b/packages/jest/src/diagnostics/telemetry.ts @@ -1,5 +1,6 @@ import { randomUUID } from 'node:crypto'; import { + logger, createDefaultProbes, createLifecycleEmitter, DEFAULT_SAMPLE_INTERVAL_MS, @@ -13,7 +14,9 @@ import { type Config as HarnessConfig, } from '@react-native-harness/config'; import type { HarnessPlatformRunner } from '@react-native-harness/platforms'; -import { createDiagnosticsAppender } from './report.js'; +import { appendToTraceFile, createDiagnosticsAppender } from './report.js'; + +const telemetryLogger = logger.child('diagnostics'); export type SessionTelemetry = { /** Identifies the session; names the incremental `.jsonl` log. */ @@ -24,9 +27,15 @@ export type SessionTelemetry = { 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. Safe to call more than once. */ + /** + * 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; }; @@ -51,6 +60,7 @@ export const startSessionTelemetry = ({ const options = resolveDiagnosticsOptions(config); let platform: HarnessPlatformRunner | undefined; + let lastRunId: string | undefined; const appender = createDiagnosticsAppender(diagnostics, { projectRoot, @@ -90,14 +100,31 @@ export const startSessionTelemetry = ({ 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 { - appender.dispose(); + await appender.dispose(); } })(); return disposed; diff --git a/packages/jest/src/execute-run.ts b/packages/jest/src/execute-run.ts index 32112334..dddf3cf4 100644 --- a/packages/jest/src/execute-run.ts +++ b/packages/jest/src/execute-run.ts @@ -183,6 +183,11 @@ export const executeRun = async ( }; updateRunState(); + session.lifecycle.emit({ + type: 'phase', + phase: 'run.start', + attrs: { runId }, + }); await session.callHook('run:started', { runId, @@ -374,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(); diff --git a/packages/jest/src/harness-session.ts b/packages/jest/src/harness-session.ts index 567502a7..82c9e2b9 100644 --- a/packages/jest/src/harness-session.ts +++ b/packages/jest/src/harness-session.ts @@ -513,6 +513,13 @@ export const createHarnessSession = async ( 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', @@ -535,13 +542,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, { @@ -559,10 +568,7 @@ export const createHarnessSession = async ( }, }), { lockKey: resourceLockKey } - ).catch(async (error) => { - await telemetry.dispose(); - throw error; - }); + )); if (didWaitForResourceLock) logRunnerStarting(platform); sessionLogger.debug('resource lock acquired for runner=%s key=%s', platform.name, resourceLockKey); @@ -1178,6 +1184,9 @@ export const createHarnessSession = async ( }, setRunState: (state) => { currentRun = state; + if (state) { + telemetry.trackRun(state.runId); + } }, dispose: async (reason = 'normal') => { try { diff --git a/website/src/docs/getting-started/configuration.mdx b/website/src/docs/getting-started/configuration.mdx index 62c5364a..13149aeb 100644 --- a/website/src/docs/getting-started/configuration.mdx +++ b/website/src/docs/getting-started/configuration.mdx @@ -317,7 +317,7 @@ Besides timings for session setup, Metro bundling, app startup and each test fil | `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, when the app becomes ready, and at the end of the run. For iOS simulators it records `platform.ios.simulator.guest_process_count`, 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. +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 @@ -325,10 +325,12 @@ 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 on `SIGINT`/`SIGTERM`), so a job that is cancelled or times out still leaves its data behind. | +| `.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 From ceff5becec8737ac57c134d81848f2a74219433a Mon Sep 17 00:00:00 2001 From: Szymon Chmal Date: Fri, 16 Oct 2026 09:26:08 +0200 Subject: [PATCH 10/10] fix(tools): type telemetry timers for DOM-lib consumers The runtime package typechecks the tools sources with the DOM lib, where setInterval and setTimeout return numbers, so calling unref() on the result and annotating it as NodeJS.Timeout failed CI. Timers now go through a guarded unrefTimer helper and ReturnType-based annotations that hold under both libs. --- packages/jest/src/diagnostics/report.ts | 4 ++-- packages/tools/src/index.ts | 1 + packages/tools/src/telemetry/index.ts | 2 +- packages/tools/src/telemetry/probe-utils.ts | 3 ++- packages/tools/src/unref-timer.ts | 11 +++++++++++ 5 files changed, 17 insertions(+), 4 deletions(-) create mode 100644 packages/tools/src/unref-timer.ts diff --git a/packages/jest/src/diagnostics/report.ts b/packages/jest/src/diagnostics/report.ts index 29e1140e..3455ec98 100644 --- a/packages/jest/src/diagnostics/report.ts +++ b/packages/jest/src/diagnostics/report.ts @@ -2,7 +2,7 @@ import fsSync from 'node:fs'; import fs from 'node:fs/promises'; import path from 'node:path'; import type { DiagnosticEntry, Diagnostics } from '@react-native-harness/tools'; -import { getHarnessRootPath, logger } from '@react-native-harness/tools'; +import { getHarnessRootPath, logger, unrefTimer } from '@react-native-harness/tools'; const reportLogger = logger.child('diagnostics'); @@ -185,7 +185,7 @@ export const createDiagnosticsAppender = ( ); const timer = setInterval(flushAsync, options.flushIntervalMs ?? 2000); - timer.unref(); + unrefTimer(timer); process.on('exit', flushSync); const dispose = async () => { diff --git a/packages/tools/src/index.ts b/packages/tools/src/index.ts index 6de4aeeb..7aaf52ac 100644 --- a/packages/tools/src/index.ts +++ b/packages/tools/src/index.ts @@ -19,5 +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/index.ts b/packages/tools/src/telemetry/index.ts index 36ad9ba4..6565bcb1 100644 --- a/packages/tools/src/telemetry/index.ts +++ b/packages/tools/src/telemetry/index.ts @@ -127,7 +127,7 @@ export const startTelemetryProbes = ( } } if (!ctx.signal.aborted) { - let timer: NodeJS.Timeout | undefined; + let timer: ReturnType | undefined; const timeout = new Promise((resolve) => { timer = setTimeout(resolve, DISPOSE_SETTLE_TIMEOUT_MS); }); diff --git a/packages/tools/src/telemetry/probe-utils.ts b/packages/tools/src/telemetry/probe-utils.ts index 891000a4..8c035e90 100644 --- a/packages/tools/src/telemetry/probe-utils.ts +++ b/packages/tools/src/telemetry/probe-utils.ts @@ -1,3 +1,4 @@ +import { unrefTimer } from '../unref-timer.js'; import type { LifecycleEvent, LifecyclePhase, ProbeContext } from './types.js'; export type SampleInfo = { @@ -71,7 +72,7 @@ export const startSampler = ( }; const timer = setInterval(tick, ctx.sampleIntervalMs); - timer.unref(); + unrefTimer(timer); ctx.signal.addEventListener('abort', stop, { once: true }); ctx.lifecycle.addListener(onPhase); tick(); 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(); + } +};