diff --git a/packages/core/src/process/3-DryRunExecutor.ts b/packages/core/src/process/3-DryRunExecutor.ts index 41e46c296c..d22c56bfa1 100644 --- a/packages/core/src/process/3-DryRunExecutor.ts +++ b/packages/core/src/process/3-DryRunExecutor.ts @@ -58,6 +58,11 @@ interface Timing { * So the time it took to start the test runner and to report the result. */ overhead: number; + + /** + * The total time spent (net + overhead) in a human readable format + */ + humanReadableTimeElapsed: string; } function isFailedTest(testResult: TestResult): testResult is FailedTestResult { @@ -87,11 +92,8 @@ export class DryRunExecutor { .provideValue(coreTokens.testRunnerConcurrencyTokens, this.concurrencyTokenProvider.testRunnerToken$) .provideFactory(coreTokens.testRunnerPool, createTestRunnerPool); const testRunnerPool = testRunnerInjector.resolve(coreTokens.testRunnerPool); - this.log.info('Starting initial test run. This may take a while.'); const testRunner = await testRunnerPool.worker$.pipe(first()).toPromise(); - const { dryRunResult, grossTimeMS } = await this.timeDryRun(testRunner); - this.validateResultCompleted(dryRunResult); - const timing = this.calculateTiming(grossTimeMS, dryRunResult.tests); + const { dryRunResult, timing } = await this.timeDryRun(testRunner); this.logInitialTestRunSucceeded(dryRunResult.tests, timing); if (!dryRunResult.tests.length) { throw new ConfigError('No tests were executed. Stryker will exit prematurely. Please check your configuration.'); @@ -121,18 +123,23 @@ export class DryRunExecutor { } throw new Error('Something went wrong in the initial test run'); } - private async timeDryRun(testRunner: TestRunner): Promise<{ dryRunResult: DryRunResult; grossTimeMS: number }> { + + private async timeDryRun(testRunner: TestRunner): Promise<{ dryRunResult: CompleteDryRunResult; timing: Timing }> { this.timer.mark(INITIAL_TEST_RUN_MARKER); + this.log.info('Starting initial test run. This may take a while.'); const dryRunResult = await testRunner.dryRun({ timeout: INITIAL_RUN_TIMEOUT, coverageAnalysis: this.options.coverageAnalysis }); const grossTimeMS = this.timer.elapsedMs(INITIAL_TEST_RUN_MARKER); - return { dryRunResult, grossTimeMS }; + const humanReadableTimeElapsed = this.timer.humanReadableElapsed(INITIAL_TEST_RUN_MARKER); + this.validateResultCompleted(dryRunResult); + const timing = this.calculateTiming(grossTimeMS, humanReadableTimeElapsed, dryRunResult.tests); + return { dryRunResult, timing }; } private logInitialTestRunSucceeded(tests: TestResult[], timing: Timing) { this.log.info( 'Initial test run succeeded. Ran %s tests in %s (net %s ms, overhead %s ms).', tests.length, - this.timer.humanReadableElapsed(), + timing.humanReadableTimeElapsed, timing.net, timing.overhead ); @@ -145,12 +152,13 @@ export class DryRunExecutor { * The overhead time is used to calculate exact timeout values during mutation testing. * See timeoutMS setting in README for more information on this calculation */ - private calculateTiming(grossTimeMS: number, tests: readonly TestResult[]): Timing { + private calculateTiming(grossTimeMS: number, humanReadableTimeElapsed: string, tests: readonly TestResult[]): Timing { const netTimeMS = tests.reduce((total, test) => total + test.timeSpentMs, 0); const overheadTimeMS = grossTimeMS - netTimeMS; return { net: netTimeMS, overhead: overheadTimeMS < 0 ? 0 : overheadTimeMS, + humanReadableTimeElapsed, }; } diff --git a/packages/core/src/utils/Timer.ts b/packages/core/src/utils/Timer.ts index 84539a0bb0..c8be84c8e1 100644 --- a/packages/core/src/utils/Timer.ts +++ b/packages/core/src/utils/Timer.ts @@ -15,13 +15,13 @@ export default class Timer { this.start = this.now(); } - public humanReadableElapsed() { - const elapsedSeconds = this.elapsedSeconds(); + public humanReadableElapsed(sinceMarker?: string) { + const elapsedSeconds = this.elapsedSeconds(sinceMarker); return Timer.humanReadableElapsedMinutes(elapsedSeconds) + Timer.humanReadableElapsedSeconds(elapsedSeconds); } - public elapsedSeconds() { - const elapsedMs = this.elapsedMs(); + public elapsedSeconds(sinceMarker?: string) { + const elapsedMs = this.elapsedMs(sinceMarker); return Math.floor(elapsedMs / 1000); } diff --git a/packages/core/test/unit/process/3-DryRunExecutor.spec.ts b/packages/core/test/unit/process/3-DryRunExecutor.spec.ts index cf76368f29..a3a5a8ed7b 100644 --- a/packages/core/test/unit/process/3-DryRunExecutor.spec.ts +++ b/packages/core/test/unit/process/3-DryRunExecutor.spec.ts @@ -92,15 +92,19 @@ describe(DryRunExecutor.name, () => { it('should have logged the amount of tests ran', async () => { runResult.tests.push(factory.successTestResult({ timeSpentMs: 10 })); runResult.tests.push(factory.successTestResult({ timeSpentMs: 10 })); - timerMock.humanReadableElapsed.returns('2 seconds'); - timerMock.elapsedMs.returns(50); + timerMock.humanReadableElapsed.returns('30 seconds'); + timerMock.humanReadableElapsed.withArgs('Initial test run').returns('2 seconds'); + timerMock.elapsedMs.returns(30000); + timerMock.elapsedMs.withArgs('Initial test run').returns(2000); + await sut.execute(); + expect(testInjector.logger.info).to.have.been.calledWith( 'Initial test run succeeded. Ran %s tests in %s (net %s ms, overhead %s ms).', 2, '2 seconds', 20, - 30 + 1980 ); }); diff --git a/packages/core/test/unit/utils/Timer.spec.ts b/packages/core/test/unit/utils/Timer.spec.ts index a80b92944b..19e4c302ca 100644 --- a/packages/core/test/unit/utils/Timer.spec.ts +++ b/packages/core/test/unit/utils/Timer.spec.ts @@ -3,7 +3,7 @@ import * as sinon from 'sinon'; import Timer from '../../../src/utils/Timer'; -describe('Timer', () => { +describe(Timer.name, () => { let clock: sinon.SinonFakeTimers; let sut: Timer; @@ -14,19 +14,27 @@ describe('Timer', () => { afterEach(() => clock.restore()); - const arrangeActAssert = (elapsedMs: number, expectedTimeLabel: string) => { - describe(`after ${expectedTimeLabel}`, () => { - beforeEach(() => clock.tick(elapsedMs)); - - it(`should show "${expectedTimeLabel}" when humanReadableElapsed()`, () => expect(sut.humanReadableElapsed()).to.be.eq(expectedTimeLabel)); + describe(Timer.prototype.humanReadableElapsed.name, () => { + const arrangeActAssert = (elapsedMs: number, expectedTimeLabel: string) => { + it(`should show "${expectedTimeLabel}" after ${elapsedMs} ms`, () => { + clock.tick(elapsedMs); + expect(sut.humanReadableElapsed()).to.be.eq(expectedTimeLabel); + }); + }; + + arrangeActAssert(59999, '59 seconds'); + arrangeActAssert(119999, '1 minute 59 seconds'); + arrangeActAssert(120000, '2 minutes 0 seconds'); + arrangeActAssert(121999, '2 minutes 1 second'); + arrangeActAssert(61000, '1 minute 1 second'); + + it('should use the since marker when provided', () => { + clock.tick(1000); + sut.mark('foo'); + clock.tick(1000); + expect(sut.humanReadableElapsed('foo')).eq('1 second'); }); - }; - - arrangeActAssert(59999, '59 seconds'); - arrangeActAssert(119999, '1 minute 59 seconds'); - arrangeActAssert(120000, '2 minutes 0 seconds'); - arrangeActAssert(121999, '2 minutes 1 second'); - arrangeActAssert(61000, '1 minute 1 second'); + }); describe('mark and elapsedMS', () => { it('should result in expected elapsedMS', () => {