timings

runner/package.json

@@ -1,6 +1,6 @@
 {
   "name": "fastest-jest-runner",
-  "version": "29.0.0",
+  "version": "29.0.2",
   "repository": {
     "type": "git",
     "url": "https://github.com/goloveychuk/fastest-jest-runner.git",

runner/src/index.ts

@@ -33,6 +33,7 @@ import type { SnapshotBuilderModule, SnapshotConfig } from './snapshots/types';
 import { replaceRootDirInPath } from 'jest-config';
 import { createScriptTransformer } from '@jest/transform';
 import { Config } from '@jest/types';
+import {  createTimings } from './log';
 
 function setCleanupBeforeExit(clean: () => void) {
   let called = false;
@@ -301,10 +302,11 @@ class TestRunner extends EmittingTestRunner {
     });
 
     child.stdout!.on('data', (data) => {
-      console.log('stdout', data.toString('utf-8'));
+      console.log(data.toString('utf-8'));
     });
     child.stderr!.on('data', (data) => {
-      console.log('stderr', data.toString('utf-8'));
+      const chunk = data.toString('utf-8')
+      console.log(chunk)
     });
 
     child.send(workerConfig);
@@ -339,6 +341,9 @@ class TestRunner extends EmittingTestRunner {
     const initOrGetSnapshot = withCache(initSnapshot);
 
     const runTest = async (test: Test): Promise<TestResult> => {
+      const __timing = createTimings()
+
+      __timing.time('runTest', 'start')
       testsLeft.add(test.path);
       // return new Promise<TestResult>((resolve, reject) => {
       const snapshotName = await getSnapshotName(test);
@@ -349,27 +354,32 @@ class TestRunner extends EmittingTestRunner {
       testsById.set(resultFifo.id, test);
 
       console.log(`sent msg ${test.path}`);
-
+
+      __timing.time('writeToFifo', 'start')
       await snapshotObj.writer.write({
         type: 'test',
         testPath: test.path,
         resultFifo,
       });
-
+      __timing.time('writeToFifo', 'end')
       // child.stdin!.uncork()
       // child.send([id, test.path]);
 
+      __timing.time('readTestResult', 'start')
       const resp = JSON.parse(
         await fs.promises.readFile(resultFifo.path, 'utf8'),
       ) as WorkerResponse.Response;
+      __timing.time('readTestResult', 'end')
       await fs.promises.unlink(resultFifo.path);
       testsLeft.delete(test.path);
       // process.kill(resp.pid, 'SIGKILL'); // killing zombies, better to wait for SIGCHLD
       //
+      __timing.time('runTest', 'end')
+
       if (resp.testResult.type === 'error') {
         throw resp.testResult.data;
       }
-      return resp.testResult.data;
+      return __timing.enrich(resp.testResult.data);
       // if (oneResolved) {
       //   setTimeout(() => {
       //     reject(new Error('timeout'));
@@ -433,6 +443,7 @@ class TestRunner extends EmittingTestRunner {
       console.log('after proc loop await');
       // if (testsLeft.size) {
       console.log('Tests left:', Array.from(testsLeft).join('\n'));
+
       // }
       // child.kill('SIGTERM');
     };

runner/src/log.ts

@@ -0,0 +1,54 @@
+import { TestResult } from "@jest/test-result";
+
+export const phaseOrder = [
+  'runTest',
+  'writeToFifo',
+  'fork',
+//   'handleTestRes',
+//   'writeResult',
+  'innerRunTest',
+  'readTestResult',
+] as const;
+
+type Phases = typeof phaseOrder[number];
+
+// const _allTimings: any[] = []
+// const PREFIX = '____¬timings¬'
+// const SUFFIX = '¬end¬\n'
+
+// export const getAllTimings = () => _allTimings
+
+// export function handleStderr(chunk: string) {
+//     const start = chunk.indexOf(PREFIX);
+//     if (start === -1) {
+//         return chunk
+//     }
+
+//     const end = chunk.indexOf(SUFFIX);
+//     if (end ===-1) {
+//         console.error('should not happen, size is small so should be atomic')
+//         return chunk
+//     }
+//     let left = chunk.slice(0, start) + chunk.slice(end+SUFFIX.length)
+//     _allTimings.push(JSON.parse(chunk.slice(PREFIX.length, end)))
+//     return left
+// }
+
+export type Timing = ReturnType<typeof createTimings>
+
+export const createTimings = () => {
+    const allTimings: any[] = []
+    const time = (phase: Phases, type: 'start' | 'end') => {
+        allTimings.push({phase, type, time: Date.now()})
+    }
+    const enrich = (res: TestResult) => {
+        res.perfStats = {
+            ...(res.perfStats ?? {}), 
+            //@ts-ignore
+            timings: [...(res.perfStats.timings ?? []), ...allTimings]
+        }
+        return res
+    }
+
+    return {time, enrich}
+}

runner/src/worker.ts

@@ -13,6 +13,7 @@ import type { Fifo } from './fifo-maker';
 import RuntimeMod from 'jest-runtime';
 import HasteMap from 'jest-haste-map';
 import { buildSnapshot } from './snapshots/build';
+import { createTimings, Timing } from './log';
 
 
 // console.log(process.argv[2]);
@@ -27,7 +28,7 @@ const runGc = async () => {
   await sleep(300); //waiting for gc??
 };
 
-function handleChild(testEnv: TestEnv, payload: WorkerInput.RunTest) {
+function handleChild(__timing: Timing, testEnv: TestEnv, payload: WorkerInput.RunTest) {
   let handled = false;
 
   const handle = (data: WorkerResponse.Response['testResult']) => {
@@ -36,15 +37,17 @@ function handleChild(testEnv: TestEnv, payload: WorkerInput.RunTest) {
       return;
     }
     handled = true;
-
+    // __timing.time('handleTestRes', 'start');
     const resp: WorkerResponse.Response = {
       pid: process.pid,
       testResult: data,
     };
     console.log('writing to', payload.resultFifo.path);
+    // __timing.time('writeResult', 'start');
     fs.writeFileSync(payload.resultFifo.path, JSON.stringify(resp));
+    // __timing.time('writeResult', 'end');
     addon.sendThisProcOk();
-    // });
+    // __timing.time('handleTestRes', 'end');
   };
 
   process.on('unhandledRejection', (reason, _promise) => {
@@ -70,11 +73,18 @@ function handleChild(testEnv: TestEnv, payload: WorkerInput.RunTest) {
     handle(makeErrorResp('exited before result: ' + code));
   });
 
+  __timing.time('innerRunTest', 'start');
   testEnv
     .runTest(payload.testPath)
     .then(
-      (data) => handle({ type: 'result', data }),
-      (err) => handle(makeErrorResp(err)),
+      (data) => {
+        __timing.time('innerRunTest', 'end');
+        return handle({ type: 'result', data: __timing.enrich(data) });
+      },
+      (err) => {
+        // __timing.time('innerRunTest', 'end');
+        return handle(makeErrorResp(err));
+      },
     )
     .finally(() => {
       console.log('exiting');
@@ -125,14 +135,16 @@ function loop(
         }
       }
       case 'test': {
-        console.log('got test job', payload.testPath);
-        const childPid = addon.fork(payload.resultFifo.id);
+        const __timing = createTimings()
 
+        __timing.time('fork', 'start');
+        const childPid = addon.fork(payload.resultFifo.id);
         // const res = 0 ;
         const isChild = childPid === 0;
 
         if (isChild) {
-          handleChild(testEnv, payload);
+          __timing.time('fork', 'end');
+          handleChild(__timing, testEnv, payload);
           return 'child';
         } else {
           continue;