diff --git a/runner/package.json b/runner/package.json index 609ce36..d377d63 100644 --- a/runner/package.json +++ b/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", diff --git a/runner/src/index.ts b/runner/src/index.ts index 226a68b..412e124 100644 --- a/runner/src/index.ts +++ b/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 => { + const __timing = createTimings() + + __timing.time('runTest', 'start') testsLeft.add(test.path); // return new Promise((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'); }; diff --git a/runner/src/log.ts b/runner/src/log.ts new file mode 100644 index 0000000..ff24ed0 --- /dev/null +++ b/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 + +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} +} diff --git a/runner/src/worker.ts b/runner/src/worker.ts index 3836011..9c9b93b 100644 --- a/runner/src/worker.ts +++ b/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;