feat(jest-core): Add perfStats to surface test setup overhead (#14622)

Author: mattkubej

CHANGELOG.md

@@ -5,6 +5,7 @@
 - `[jest-config]` [**BREAKING**] Add `mts` and `cts` to default `moduleFileExtensions` config ([#14369](https://github.com/facebook/jest/pull/14369))
 - `[jest-config]` [**BREAKING**] Update `testMatch` and `testRegex` default option for supporting `mjs`, `cjs`, `mts`, and `cts` ([#14584](https://github.com/jestjs/jest/pull/14584))
 - `[@jest/core]` [**BREAKING**] Group together open handles with the same stack trace ([#13417](https://github.com/jestjs/jest/pull/13417), & [#14543](https://github.com/jestjs/jest/pull/14543))
+- `[@jest/core]` Add `perfStats` to surface test setup overhead ([#14622](https://github.com/jestjs/jest/pull/14622))
 - `[@jest/core, @jest/test-sequencer]` [**BREAKING**] Exposes `globalConfig` & `contexts` to `TestSequencer` ([#14535](https://github.com/jestjs/jest/pull/14535), & [#14543](https://github.com/jestjs/jest/pull/14543))
 - `[jest-environment-jsdom]` [**BREAKING**] Upgrade JSDOM to v22 ([#13825](https://github.com/jestjs/jest/pull/13825))
 - `[@jest/fake-timers]` [**BREAKING**] Upgrade `@sinonjs/fake-timers` to v11 ([#14544](https://github.com/jestjs/jest/pull/14544))

docs/Configuration.md

@@ -2080,13 +2080,22 @@ This option allows the use of a custom results processor. This processor must be
         "column": number,
         "line": number
       },
-      "duration": number | null
+      "duration": number | null,
+      "startAt": epoch | null
     },
     ...
     ],
     "perfStats": {
-      "start": epoch,
-      "end": epoch
+      "end": epoch,
+      "loadTestEnvironmentEnd": epoch,
+      "loadTestEnvironmentStart": epoch,
+      "runtime": number,
+      "setupAfterEnvEnd": epoch,
+      "setupAfterEnvStart": epoch,
+      "setupFilesEnd": epoch,
+      "setupFilesStart": epoch,
+      "slow": boolean,
+      "start": epoch
     },
     "testFilePath": absolute path to test file,
     "coverage": {}

packages/jest-circus/src/legacy-code-todo-rewrite/jestAdapter.ts

@@ -74,6 +74,7 @@ const jestAdapter = async (
     }
   });
 
+  const setupAfterEnvStart = Date.now();
   for (const path of config.setupFilesAfterEnv) {
     const esm = runtime.unstable_shouldLoadAsEsm(path);
 
@@ -83,6 +84,7 @@ const jestAdapter = async (
       runtime.requireModule(path);
     }
   }
+  const setupAfterEnvEnd = Date.now();
   const esm = runtime.unstable_shouldLoadAsEsm(testPath);
 
   if (esm) {
@@ -91,9 +93,15 @@ const jestAdapter = async (
     runtime.requireModule(testPath);
   }
 
+  const setupAfterEnvPerfStats = {
+    setupAfterEnvEnd,
+    setupAfterEnvStart,
+  };
+
   const results = await runAndTransformResultsToJestFormat({
     config,
     globalConfig,
+    setupAfterEnvPerfStats,
     testPath,
   });
 

packages/jest-circus/src/legacy-code-todo-rewrite/jestAdapterInit.ts

@@ -141,11 +141,13 @@ export const initialize = async ({
 export const runAndTransformResultsToJestFormat = async ({
   config,
   globalConfig,
+  setupAfterEnvPerfStats,
   testPath,
 }: {
   config: Config.ProjectConfig;
   globalConfig: Config.GlobalConfig;
   testPath: string;
+  setupAfterEnvPerfStats: Config.SetupAfterEnvPerfStats;
 }): Promise<TestResult> => {
   const runResult: Circus.RunResult = await run();
 
@@ -189,6 +191,7 @@ export const runAndTransformResultsToJestFormat = async ({
         location: testResult.location,
         numPassingAsserts: testResult.numPassingAsserts,
         retryReasons: testResult.retryReasons,
+        startAt: testResult.startedAt,
         status,
         title: testResult.testPath[testResult.testPath.length - 1],
       };
@@ -215,15 +218,21 @@ export const runAndTransformResultsToJestFormat = async ({
 
   await dispatch({name: 'teardown'});
 
+  const emptyTestResult = createEmptyTestResult();
+
   return {
-    ...createEmptyTestResult(),
+    ...emptyTestResult,
     console: undefined,
     displayName: config.displayName,
     failureMessage,
     numFailingTests,
     numPassingTests,
     numPendingTests,
     numTodoTests,
+    perfStats: {
+      ...emptyTestResult.perfStats,
+      ...setupAfterEnvPerfStats,
+    },
     testExecError,
     testFilePath: testPath,
     testResults: assertionResults,

packages/jest-circus/src/utils.ts

@@ -382,6 +382,7 @@ export const makeSingleTestResult = (
     location,
     numPassingAsserts: test.numPassingAsserts,
     retryReasons: test.retryReasons.map(_getError).map(getErrorStack),
+    startedAt: test.startedAt,
     status,
     testPath: Array.from(testPath),
   };

packages/jest-runner/src/runTest.ts

@@ -87,6 +87,7 @@ async function runTestInternal(
   const docblockPragmas = docblock.parse(docblock.extract(testSource));
   const customEnvironment = docblockPragmas['jest-environment'];
 
+  const loadTestEnvironmentStart = Date.now();
   let testEnvironment = projectConfig.testEnvironment;
 
   if (customEnvironment) {
@@ -169,6 +170,7 @@ async function runTestInternal(
       testPath: path,
     },
   );
+  const loadTestEnvironmentEnd = Date.now();
 
   if (typeof environment.getVmContext !== 'function') {
     console.error(
@@ -213,6 +215,7 @@ async function runTestInternal(
 
   const start = Date.now();
 
+  const setupFilesStart = Date.now();
   for (const path of projectConfig.setupFiles) {
     const esm = runtime.unstable_shouldLoadAsEsm(path);
 
@@ -225,6 +228,7 @@ async function runTestInternal(
       }
     }
   }
+  const setupFilesEnd = Date.now();
 
   const sourcemapOptions: sourcemapSupport.Options = {
     environment: 'node',
@@ -329,8 +333,13 @@ async function runTestInternal(
     const end = Date.now();
     const testRuntime = end - start;
     result.perfStats = {
+      ...result.perfStats,
       end,
+      loadTestEnvironmentEnd,
+      loadTestEnvironmentStart,
       runtime: testRuntime,
+      setupFilesEnd,
+      setupFilesStart,
       slow: testRuntime / 1000 > projectConfig.slowTestThreshold,
       start,
     };

packages/jest-test-result/src/helpers.ts

@@ -57,7 +57,13 @@ export const buildFailureTestResult = (
   openHandles: [],
   perfStats: {
     end: 0,
+    loadTestEnvironmentEnd: 0,
+    loadTestEnvironmentStart: 0,
     runtime: 0,
+    setupAfterEnvEnd: 0,
+    setupAfterEnvStart: 0,
+    setupFilesEnd: 0,
+    setupFilesStart: 0,
     slow: false,
     start: 0,
   },
@@ -155,7 +161,13 @@ export const createEmptyTestResult = (): TestResult => ({
   openHandles: [],
   perfStats: {
     end: 0,
+    loadTestEnvironmentEnd: 0,
+    loadTestEnvironmentStart: 0,
     runtime: 0,
+    setupAfterEnvEnd: 0,
+    setupAfterEnvStart: 0,
+    setupFilesEnd: 0,
+    setupFilesStart: 0,
     slow: false,
     start: 0,
   },

packages/jest-test-result/src/types.ts

@@ -106,7 +106,13 @@ export type TestResult = {
   openHandles: Array<Error>;
   perfStats: {
     end: number;
+    loadTestEnvironmentEnd: number;
+    loadTestEnvironmentStart: number;
     runtime: number;
+    setupAfterEnvEnd: number;
+    setupAfterEnvStart: number;
+    setupFilesEnd: number;
+    setupFilesStart: number;
     slow: boolean;
     start: number;
   };

packages/jest-types/src/Circus.ts

@@ -209,6 +209,7 @@ export type TestResult = {
    */
   failing?: boolean;
   invocations: number;
+  startedAt?: number | null;
   status: TestStatus;
   location?: {column: number; line: number} | null;
   numPassingAsserts: number;

packages/jest-types/src/Config.ts

@@ -494,6 +494,11 @@ export type ProjectConfig = {
   workerIdleMemoryLimit?: number;
 };
 
+export type SetupAfterEnvPerfStats = {
+  setupAfterEnvStart: number;
+  setupAfterEnvEnd: number;
+};
+
 export type Argv = Arguments<
   Partial<{
     all: boolean;

packages/jest-types/src/TestResult.ts

@@ -23,6 +23,7 @@ type Callsite = {
 export type AssertionResult = {
   ancestorTitles: Array<string>;
   duration?: number | null;
+  startAt?: number | null;
   /**
    * Whether [`test.failing()`](https://jestjs.io/docs/api#testfailingname-fn-timeout)
    * was used.