feat(core): correct initial test run timing (#2496)

Correctly report the initial test run timing. For example:

> `INFO DryRunExecutor Initial test run succeeded. Ran 502 tests in 2 seconds (net 2295 ms, overhead 572 ms)`

Co-authored-by: root <root@SimonL03.corp.infosupport.com>
Co-authored-by: Nico Jansen <jansennico@gmail.com>

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,
     };
   }
 

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);
   }
 

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
         );
       });
 

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', () => {