Skip to content

Commit 835f41b

Browse files
committed
feat(core): expand --trace dump with per-case spans, heap counter, and metadata
Why: phase summary already conveys macro-level timings, but Perfetto UI is underused at the file level — every test file shows up as 8 phase blocks with no visibility into which case or hook dominates `tests`. Add detail that surfaces in Perfetto without touching `runner.ts`. - Emit per-case and per-suite `ph: 'X'` slices (cats `case` / `suite`) via the runner's existing `RunnerHooks` lifecycle callbacks; `runner.ts` is untouched. `TestCaseInfo.startTime` provides the case start time, suite start is captured at hook firing. - Sample `process.memoryUsage()` as `ph: 'C'` counter events at every phase boundary so heap pressure shows up as Perfetto tracks (heapUsedMB / heapTotalMB / rssMB). - Add `process_sort_index` and `thread_name` metadata per pid so the UI lists test files in execution order under a "worker" label. - Delete previous-session trace JSON on each finalize so watch mode doesn't accumulate multi-MB files under `.rstest/`. Refactor: collapse `types/trace.ts`, `utils/traceController.ts`, and `utils/traceServer.ts` into a single `utils/trace.ts`. The split was incidental, the call sites all consume the same surface, and a single file makes the public-vs-internal boundary obvious. When `--trace` is off, the new methods early-return on a single `if (!this.trace)` check; the no-trace path stays allocation-free aside from the existing `PhaseTimings` totals object used by phase summary.
1 parent 78a6cbb commit 835f41b

10 files changed

Lines changed: 395 additions & 269 deletions

File tree

packages/core/src/pool/index.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,6 @@ import type {
1818
TestInfo,
1919
TestResult,
2020
TestSuiteInfo,
21-
TraceEvent,
2221
UserConsoleLog,
2322
} from '../types';
2423
import {
@@ -27,6 +26,7 @@ import {
2726
isDeno,
2827
needFlagExperimentalDetectModule,
2928
} from '../utils';
29+
import type { TraceEvent } from '../utils/trace';
3030
import { isMemorySufficient } from '../utils/memory';
3131
import { Pool } from './pool';
3232

packages/core/src/runtime/worker/phaseTracker.ts

Lines changed: 100 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,10 @@
11
import type { PhaseTimings } from '../../types/reporter';
2-
import type { TraceEvent } from '../../types/trace';
2+
import type {
3+
TestCaseInfo,
4+
TestResult,
5+
TestSuiteInfo,
6+
} from '../../types/testSuite';
7+
import type { TraceEvent } from '../../utils/trace';
38
import { emptyPhaseTimings } from '../../utils/phaseTimings';
49
import { getRealNow } from '../util';
510

@@ -16,28 +21,48 @@ export type PhaseTrackerOptions = {
1621
type TraceState = {
1722
events: TraceEvent[];
1823
meta: NonNullable<PhaseTrackerOptions['trace']>;
24+
/** Start timestamps (ms, wall-clock) keyed by testId. */
25+
suiteStarts: Map<string, number>;
26+
caseStarts: Map<string, number>;
1927
};
2028

29+
type SliceCat = 'phase' | 'suite' | 'case';
30+
2131
/**
2232
* Accumulates non-overlapping per-phase totals (ms) for a single test file.
2333
*
2434
* `transition(name)` ends the active phase and starts the next. A phase
2535
* may be re-entered (e.g. `prepare` resumes after `envSetup`); each entry
2636
* adds to the matching `PhaseTimings` field.
2737
*
28-
* When `trace` is enabled, each completed span is also recorded as a
29-
* Perfetto-compatible `ph: 'X'` event with `pid = process.pid`. The host
30-
* later writes these into a single trace JSON file.
38+
* When `trace` is enabled, the tracker also emits Perfetto-compatible events:
39+
* - per-phase `ph: 'X'` spans (`cat: 'phase'`)
40+
* - per-suite / per-case `ph: 'X'` spans (`cat: 'suite' | 'case'`), recorded
41+
* via the runner's existing lifecycle hooks (zero intrusion into runner.ts)
42+
* - heap-usage counter samples (`ph: 'C'`, `cat: 'memory'`) at each phase
43+
* boundary, so memory pressure shows up as a track in Perfetto UI
44+
*
45+
* All events use `pid = process.pid`. The host later merges these into a
46+
* single trace JSON file.
3147
*/
3248
export class PhaseTracker {
3349
private currentPhase: PhaseName | null = null;
3450
private currentStart = 0;
3551
private hasData = false;
3652
private readonly totals: PhaseTimings = emptyPhaseTimings();
3753
private readonly trace: TraceState | null;
54+
/** Workers are single-threaded; pid doubles as tid for Perfetto tracks. */
55+
private readonly pid = process.pid;
3856

3957
constructor(options: PhaseTrackerOptions = {}) {
40-
this.trace = options.trace ? { events: [], meta: options.trace } : null;
58+
this.trace = options.trace
59+
? {
60+
events: [],
61+
meta: options.trace,
62+
suiteStarts: new Map(),
63+
caseStarts: new Map(),
64+
}
65+
: null;
4166
}
4267

4368
transition(phase: PhaseName): void {
@@ -46,8 +71,9 @@ export class PhaseTracker {
4671
const dur = now - this.currentStart;
4772
this.totals[this.currentPhase] += dur;
4873
this.hasData = true;
49-
this.recordTraceSpan(this.currentPhase, this.currentStart, dur);
74+
this.pushSlice(this.currentPhase, 'phase', this.currentStart, dur);
5075
}
76+
this.sampleHeap(now);
5177
this.currentPhase = phase;
5278
this.currentStart = now;
5379
}
@@ -58,11 +84,49 @@ export class PhaseTracker {
5884
const dur = now - this.currentStart;
5985
this.totals[this.currentPhase] += dur;
6086
this.hasData = true;
61-
this.recordTraceSpan(this.currentPhase, this.currentStart, dur);
87+
this.pushSlice(this.currentPhase, 'phase', this.currentStart, dur);
88+
this.sampleHeap(now);
6289
this.currentPhase = null;
6390
}
6491
}
6592

93+
recordSuiteStart(info: TestSuiteInfo): void {
94+
if (!this.trace) return;
95+
this.trace.suiteStarts.set(info.testId, getRealNow());
96+
}
97+
98+
recordSuiteResult(result: TestResult): void {
99+
if (!this.trace) return;
100+
const start = this.trace.suiteStarts.get(result.testId);
101+
this.trace.suiteStarts.delete(result.testId);
102+
if (start === undefined || typeof result.duration !== 'number') return;
103+
this.pushSlice(result.name || '<suite>', 'suite', start, result.duration, {
104+
testId: result.testId,
105+
status: result.status,
106+
});
107+
}
108+
109+
recordCaseStart(info: TestCaseInfo): void {
110+
if (!this.trace) return;
111+
// Prefer the runner's authoritative start time when present so the slice
112+
// aligns exactly with the case's reported duration.
113+
const start =
114+
typeof info.startTime === 'number' ? info.startTime : getRealNow();
115+
this.trace.caseStarts.set(info.testId, start);
116+
}
117+
118+
recordCaseResult(result: TestResult): void {
119+
if (!this.trace) return;
120+
const start = this.trace.caseStarts.get(result.testId);
121+
this.trace.caseStarts.delete(result.testId);
122+
if (start === undefined || typeof result.duration !== 'number') return;
123+
this.pushSlice(result.name, 'case', start, result.duration, {
124+
testId: result.testId,
125+
status: result.status,
126+
retryCount: result.retryCount,
127+
});
128+
}
129+
66130
getTotals(): PhaseTimings | undefined {
67131
return this.hasData ? this.totals : undefined;
68132
}
@@ -73,24 +137,47 @@ export class PhaseTracker {
73137
: undefined;
74138
}
75139

76-
private recordTraceSpan(
77-
phase: PhaseName,
140+
private pushSlice(
141+
name: string,
142+
cat: SliceCat,
78143
startMs: number,
79144
durMs: number,
145+
extraArgs?: Record<string, string | number | boolean | undefined>,
80146
): void {
81147
if (!this.trace) return;
82148
this.trace.events.push({
83-
name: phase,
84-
cat: 'phase',
149+
name,
150+
cat,
85151
ph: 'X',
86152
ts: startMs * 1000,
87153
dur: durMs * 1000,
88-
pid: process.pid,
89-
tid: process.pid,
154+
pid: this.pid,
155+
tid: this.pid,
90156
args: {
91157
testPath: this.trace.meta.testPath,
92158
project: this.trace.meta.project,
159+
...extraArgs,
160+
},
161+
});
162+
}
163+
164+
private sampleHeap(nowMs: number): void {
165+
if (!this.trace) return;
166+
const mem = process.memoryUsage();
167+
this.trace.events.push({
168+
name: 'heap',
169+
cat: 'memory',
170+
ph: 'C',
171+
ts: nowMs * 1000,
172+
pid: this.pid,
173+
tid: this.pid,
174+
args: {
175+
heapUsedMB: round2(mem.heapUsed / 1024 / 1024),
176+
heapTotalMB: round2(mem.heapTotal / 1024 / 1024),
177+
rssMB: round2(mem.rss / 1024 / 1024),
93178
},
94179
});
95180
}
96181
}
182+
183+
const round2 = (n: number): number => Math.round(n * 100) / 100;

packages/core/src/runtime/worker/runInPool.ts

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -555,9 +555,11 @@ export const runInPool = async (
555555
await rpc.onTestFileReady(test);
556556
},
557557
onTestSuiteStart: async (test) => {
558+
tracker.recordSuiteStart(test);
558559
await rpc.onTestSuiteStart(test);
559560
},
560561
onTestSuiteResult: async (result) => {
562+
tracker.recordSuiteResult(result);
561563
silentConsoleController.flushBufferedLogsForTask({
562564
taskId: result.testId,
563565
status: result.status,
@@ -568,9 +570,11 @@ export const runInPool = async (
568570
await rpc.onTestSuiteResult(result);
569571
},
570572
onTestCaseStart: async (test) => {
573+
tracker.recordCaseStart(test);
571574
await rpc.onTestCaseStart(test);
572575
},
573576
onTestCaseResult: async (result) => {
577+
tracker.recordCaseResult(result);
574578
silentConsoleController.flushBufferedLogsForTask({
575579
taskId: result.testId,
576580
status: result.status,

packages/core/src/types/index.ts

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,5 @@ export type * from './mock';
99
export type * from './reporter';
1010
export type * from './runner';
1111
export type * from './testSuite';
12-
export type * from './trace';
1312
export type * from './utils';
1413
export type * from './worker';

packages/core/src/types/testSuite.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -175,7 +175,7 @@ export type TestFileResult = TestResult & {
175175
*
176176
* @internal
177177
*/
178-
traceEvents?: import('./trace').TraceEvent[];
178+
traceEvents?: import('../utils/trace').TraceEvent[];
179179
};
180180

181181
export interface UserConsoleLog {

packages/core/src/types/trace.ts

Lines changed: 0 additions & 14 deletions
This file was deleted.

packages/core/src/utils/index.ts

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,5 +7,3 @@ export * from './process';
77
export * from './shard';
88
export * from './testFiles';
99
export * from './trace';
10-
export * from './traceController';
11-
export * from './traceServer';

0 commit comments

Comments
 (0)