feat(core): add phase-level Duration breakdown

Author: fi3ework

.gitignore

@@ -1,6 +1,7 @@
 .DS_Store
 *.log*
 *.cpuprofile
+*.dump
 node_modules/
 
 .cache/

e2e/globalSetup/index.test.ts

@@ -23,7 +23,7 @@ describe('globalSetup', async () => {
     });
 
     await expectExecSuccess();
-    const logs = cli.stdout.split('\n').filter((log) => log.includes('['));
+    const logs = cli.stdout.split('\n').filter((log) => log.startsWith('['));
 
     expect(logs).toMatchInlineSnapshot(`
       [

e2e/reporter/githubActions.test.ts

@@ -55,7 +55,7 @@ it.skipIf(!process.env.CI)('github-actions', async () => {
   expect(stepSummary).toContain('| **Test Files** | ❌ 1 failed |');
   expect(stepSummary).toContain('| **Tests** | ❌ 2 failed |');
   expect(stepSummary).toMatch(
-    /\| \*\*Duration\*\* \| \d+ms \(build \d+ms, tests \d+ms\) \|/,
+    /\| \*\*Duration\*\* \| \d+ms \(build \d+ms; worker aggregate \[setup \d+ms, load \d+ms, collect \d+ms, tests \d+ms\]\) \|/,
   );
   expect(stepSummary).toContain('## Failures');
   expect(stepSummary).toContain(
@@ -174,7 +174,7 @@ it.skipIf(!process.env.CI)('github-actions summary on pass', async () => {
     '| **Tests** | ✅ 13 passed \\| 1 skipped (14) |',
   );
   expect(stepSummary).toMatch(
-    /\| \*\*Duration\*\* \| \d+ms \(build \d+ms, tests \d+ms\) \|/,
+    /\| \*\*Duration\*\* \| \d+ms \(build \d+ms; worker aggregate \[setup \d+ms, load \d+ms, collect \d+ms, tests \d+ms\]\) \|/,
   );
   expect(stepSummary).not.toContain('## Failures');
 

packages/core/src/core/mergeReports.ts

@@ -10,7 +10,13 @@ import type {
   TestResult,
 } from '../types';
 import type { CoverageMap } from '../types/coverage';
-import { color, logger, prettyTime } from '../utils';
+import {
+  color,
+  formatDurationParts,
+  logger,
+  mergePhaseTimings,
+  prettyTime,
+} from '../utils';
 import type { Rstest } from './rstest';
 
 const DEFAULT_BLOB_DIR = '.rstest-reports';
@@ -86,14 +92,16 @@ function mergeDurations(durations: Duration[]): Duration {
   let totalTime = 0;
   let buildTime = 0;
   let testTime = 0;
+  let phaseTimings: Duration['phaseTimings'];
 
   for (const d of durations) {
     totalTime += d.totalTime;
     buildTime += d.buildTime;
     testTime += d.testTime;
+    phaseTimings = mergePhaseTimings(phaseTimings, d.phaseTimings);
   }
 
-  return { totalTime, buildTime, testTime };
+  return { totalTime, buildTime, testTime, phaseTimings };
 }
 
 function mergeBlobCoverage(blob: BlobData, coverageMap: CoverageMap): boolean {
@@ -191,7 +199,7 @@ export async function mergeReports(
   for (const { label, duration } of shardDurations) {
     logger.log(
       color.gray(
-        `  ${label}: ${prettyTime(duration.totalTime)} (build ${prettyTime(duration.buildTime)}, tests ${prettyTime(duration.testTime)})`,
+        `  ${label}: ${prettyTime(duration.totalTime)} (${formatDurationParts(duration)})`,
       ),
     );
   }

packages/core/src/core/runTests.ts

@@ -1,13 +1,20 @@
 import { constants as osConstants } from 'node:os';
 import { cleanCoverageReports, createCoverageProvider } from '../coverage';
 import { createPool } from '../pool';
-import type { EntryInfo, ProjectEntries, SourceMapInput } from '../types';
+import type {
+  Duration,
+  EntryInfo,
+  PhaseTimings,
+  ProjectEntries,
+  SourceMapInput,
+} from '../types';
 import type { CoverageMap } from '../types/coverage';
 import {
   clearScreen,
   color,
   getTestEntries,
   logger,
+  mergePhaseTimings,
   resolveShardedEntries,
 } from '../utils';
 import {
@@ -110,11 +117,7 @@ const notifyReportersOnTestRunEnd = async ({
 }: {
   context: Rstest;
   coverage?: CoverageMap;
-  duration: {
-    totalTime: number;
-    buildTime: number;
-    testTime: number;
-  };
+  duration: Duration;
   getSourcemap: (sourcePath: string) => Promise<SourceMapInput | null>;
   unhandledErrors?: Error[];
   filterRerunTestPaths?: string[];
@@ -460,6 +463,8 @@ export async function runTests(context: Rstest): Promise<void> {
       ? coverageProvider.createCoverageMap()
       : undefined;
 
+    let phaseTimings: PhaseTimings | undefined;
+
     const returns = await Promise.all(
       projects.map(async (p) => {
         const {
@@ -548,6 +553,9 @@ export async function runTests(context: Rstest): Promise<void> {
           project: p,
           updateSnapshot: context.snapshotManager.options.updateSnapshot,
           onCoverageResult: (coverage) => mergedCoverageMap?.merge(coverage),
+          onPhaseTimings: (timings) => {
+            phaseTimings = mergePhaseTimings(phaseTimings, timings);
+          },
         });
 
         return {
@@ -599,7 +607,7 @@ export async function runTests(context: Rstest): Promise<void> {
       };
 
       // When unifying reporter output, combine browser and node durations
-      const duration =
+      const base =
         shouldUnifyReporter && browserResult
           ? {
               totalTime:
@@ -612,6 +620,7 @@ export async function runTests(context: Rstest): Promise<void> {
               buildTime,
               testTime,
             };
+      const duration: Duration = { ...base, phaseTimings };
 
       const results = returns.flatMap((r) => r.results);
       const testResults = returns.flatMap((r) => r.testResults);

packages/core/src/pool/index.ts

@@ -7,6 +7,7 @@ import type {
   CoverageMapData,
   EntryInfo,
   FormattedError,
+  PhaseTimings,
   ProjectContext,
   RstestContext,
   RuntimeConfig,
@@ -267,6 +268,8 @@ export const createPool = async ({
     project: ProjectContext;
     /** When provided, coverage data is passed to this callback immediately for caller-owned merging. */
     onCoverageResult?: (coverage: CoverageMapData) => void;
+    /** Per-file phase timings forwarded for caller-owned aggregation. */
+    onPhaseTimings?: (timings: PhaseTimings) => void;
   }) => Promise<{
     results: TestFileResult[];
     testResults: TestResult[];
@@ -449,6 +452,7 @@ export const createPool = async ({
       project,
       updateSnapshot,
       onCoverageResult,
+      onPhaseTimings,
     }) => {
       const projectName = project.name;
       const runtimeConfig = getRuntimeConfig(project);
@@ -488,6 +492,10 @@ export const createPool = async ({
             onCoverageResult?.(result.coverage);
             delete result.coverage;
           }
+          if (result.phaseTimings) {
+            onPhaseTimings?.(result.phaseTimings);
+            delete result.phaseTimings;
+          }
           context.stateManager.onTestFileResult(result);
           reporters.map((reporter) => reporter.onTestFileResult?.(result));
           return result;

packages/core/src/reporter/githubActions.ts

@@ -10,6 +10,7 @@ import type {
   TestResult,
 } from '../types';
 import {
+  formatDurationParts,
   getTaskNameWithPrefix,
   logger,
   prettyTime,
@@ -316,7 +317,7 @@ async function renderStepSummary({
     `| **Tests** | ${escapeMarkdownTableCell(getPlainSummaryStatusString(testResults))} |`,
   );
   lines.push(
-    `| **Duration** | ${prettyTime(duration.totalTime)} (build ${prettyTime(duration.buildTime)}, tests ${prettyTime(duration.testTime)}) |`,
+    `| **Duration** | ${prettyTime(duration.totalTime)} (${formatDurationParts(duration)}) |`,
   );
   if (flakyTests.length > 0) {
     lines.push(

packages/core/src/reporter/summary.ts

@@ -24,6 +24,7 @@ import type {
 import {
   bgColor,
   color,
+  formatDurationParts,
   formatTestPath,
   getTaskNameWithPrefix,
   logger,
@@ -181,7 +182,7 @@ export const printSummaryLog = ({
   logger.log(`${TestSummaryLabel} ${getSummaryStatusString(testResults)}`);
 
   logger.log(
-    `${DurationLabel} ${prettyTime(duration.totalTime)} ${color.gray(`(build ${prettyTime(duration.buildTime)}, tests ${prettyTime(duration.testTime)})`)}`,
+    `${DurationLabel} ${prettyTime(duration.totalTime)} ${color.gray(`(${formatDurationParts(duration)})`)}`,
   );
   logger.log('');
 };

packages/core/src/runtime/util.ts

@@ -28,6 +28,14 @@ export const getRealTimers = (): typeof REAL_TIMERS => {
   return REAL_TIMERS;
 };
 
+/**
+ * Stable reference to `Date.now`, captured before `@sinonjs/fake-timers`
+ * can hijack the global. Phase boundaries straddling `tests` rely on this.
+ */
+const realNow = Date.now.bind(Date);
+
+export const getRealNow = (): number => realNow();
+
 export const formatTestError = async (
   err: any,
   test?: Test,

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

@@ -0,0 +1,41 @@
+import type { PhaseTimings } from '../../types/reporter';
+import { emptyPhaseTimings } from '../../utils/phaseTimings';
+import { getRealNow } from '../util';
+
+type PhaseName = keyof PhaseTimings;
+
+/**
+ * Accumulates non-overlapping per-phase totals (ms) for a single test file.
+ *
+ * `transition(name)` ends the active phase and starts the next. A phase
+ * may be re-entered (e.g. `prepare` resumes after `envSetup`); each entry
+ * adds to the matching `PhaseTimings` field.
+ */
+export class PhaseTracker {
+  private currentPhase: PhaseName | null = null;
+  private currentStart = 0;
+  private hasData = false;
+  private readonly totals: PhaseTimings = emptyPhaseTimings();
+
+  transition(phase: PhaseName): void {
+    const now = getRealNow();
+    if (this.currentPhase) {
+      this.totals[this.currentPhase] += now - this.currentStart;
+      this.hasData = true;
+    }
+    this.currentPhase = phase;
+    this.currentStart = now;
+  }
+
+  end(): void {
+    if (this.currentPhase) {
+      this.totals[this.currentPhase] += getRealNow() - this.currentStart;
+      this.hasData = true;
+      this.currentPhase = null;
+    }
+  }
+
+  getTotals(): PhaseTimings | undefined {
+    return this.hasData ? this.totals : undefined;
+  }
+}