feat(warn slow): warn users for slow runs (#3490)

Warn users for slow runs because a relatively big chunk of their mutants are _static mutants_.

For example:

```
02:34:04 (4545) INFO DryRunExecutor Initial test run succeeded. Ran 693 tests in 4 seconds (net 3420 ms, overhead 591 ms).
02:34:04 (4545) WARN MutantTestPlanner Detected 255 static mutants (8% of total) that are estimated to take 85% of the time running the tests!
  You might want to enable "ignoreStatic" to ignore these static mutants for your next run. 
  For more information about static mutants visit: https://stryker-mutator.io/docs/mutation-testing-elements/static-mutants.
  (disable "warnings.slow" to ignore this warning)
```

packages/api/schema/stryker-core.json

@@ -226,6 +226,11 @@
           "description": "decide whether or not to log warnings when a configuration options are unserializable. For example, using a `/regex/` or `function` in your configuration options.",
           "type": "boolean",
           "default": true
+        },
+        "slow": {
+          "description": "decide whether or not to log warnings when Stryker detects a slow part of mutation that can be sped up by changing some configuration. For example using `--ignoreStatic`.",
+          "type": "boolean",
+          "default": true
         }
       }
     }

packages/api/src/core/mutant-test-plan.ts

@@ -47,4 +47,10 @@ export interface MutantRunPlan {
    * The run options that will be used to test this mutant
    */
   runOptions: MutantRunOptions;
+
+  /**
+   * Estimated net time to run this mutant when it would survive in ms (which should be the worst case).
+   * This is used as input to calculate the runOptions.timeout
+   */
+  netTime: number;
 }

packages/core/src/mutants/mutant-test-planner.ts

@@ -17,6 +17,8 @@ import { I } from '@stryker-mutator/util';
 import { coreTokens } from '../di/index.js';
 import { StrictReporter } from '../reporters/strict-reporter.js';
 import { Sandbox } from '../sandbox/index.js';
+import { objectUtils } from '../utils/object-utils.js';
+import { optionsPath } from '../utils/index.js';
 
 /**
  * The factor by which hit count from dry run is multiplied to calculate the hit limit for a mutant.
@@ -50,16 +52,17 @@ export class MutantTestPlanner {
     private readonly sandbox: I<Sandbox>,
     private readonly timeOverheadMS: number,
     private readonly options: StrykerOptions,
-    logger: Logger
+    private readonly logger: Logger
   ) {
-    this.testsByMutantId = findTestsByMutant(this.dryRunResult.mutantCoverage?.perTest, dryRunResult.tests, logger);
+    this.testsByMutantId = this.findTestsByMutant(this.dryRunResult.mutantCoverage?.perTest, dryRunResult.tests);
     this.hitsByMutantId = findHitsByMutantId(this.dryRunResult.mutantCoverage);
     this.timeSpentAllTests = calculateTotalTime(this.dryRunResult.tests);
   }
 
   public makePlan(mutants: readonly Mutant[]): readonly MutantTestPlan[] {
     const mutantPlans = mutants.map((mutant) => this.planMutant(mutant));
     this.reporter.onMutationTestingPlanReady({ mutantPlans });
+    this.warnAboutSlow(mutantPlans);
     return mutantPlans;
   }
 
@@ -133,6 +136,7 @@ export class MutantTestPlanner {
 
     return {
       plan: PlanKind.Run,
+      netTime,
       mutant: {
         ...mutant,
         coveredBy,
@@ -157,31 +161,63 @@ export class MutantTestPlanner {
       },
     };
   }
-}
-function findTestsByMutant(coveragePerTest: CoveragePerTestId | undefined, allTests: TestResult[], logger: Logger) {
-  const testsByMutantId = new Map<string, Set<TestResult>>();
-  const testsById = allTests.reduce((acc, test) => acc.set(test.id, test), new Map<string, TestResult>());
-  coveragePerTest &&
-    Object.entries(coveragePerTest).forEach(([testId, mutantCoverage]) => {
-      const foundTest = testsById.get(testId);
-      if (!foundTest) {
-        logger.warn(
-          `Found test with id "${testId}" in coverage data, but not in the test results of the dry run. Not taking coverage data for this test into account.`
-        );
-        return;
-      }
-      Object.entries(mutantCoverage).forEach(([mutantId, count]) => {
-        if (count > 0) {
-          let tests = testsByMutantId.get(mutantId);
-          if (!tests) {
-            tests = new Set();
-            testsByMutantId.set(mutantId, tests);
-          }
-          tests.add(foundTest);
+  private findTestsByMutant(coveragePerTest: CoveragePerTestId | undefined, allTests: TestResult[]) {
+    const testsByMutantId = new Map<string, Set<TestResult>>();
+    const testsById = allTests.reduce((acc, test) => acc.set(test.id, test), new Map<string, TestResult>());
+    coveragePerTest &&
+      Object.entries(coveragePerTest).forEach(([testId, mutantCoverage]) => {
+        const foundTest = testsById.get(testId);
+        if (!foundTest) {
+          this.logger.warn(
+            `Found test with id "${testId}" in coverage data, but not in the test results of the dry run. Not taking coverage data for this test into account.`
+          );
+          return;
         }
+        Object.entries(mutantCoverage).forEach(([mutantId, count]) => {
+          if (count > 0) {
+            let tests = testsByMutantId.get(mutantId);
+            if (!tests) {
+              tests = new Set();
+              testsByMutantId.set(mutantId, tests);
+            }
+            tests.add(foundTest);
+          }
+        });
       });
-    });
-  return testsByMutantId;
+    return testsByMutantId;
+  }
+
+  private warnAboutSlow(mutantPlans: readonly MutantTestPlan[]) {
+    if (!this.options.ignoreStatic && objectUtils.isWarningEnabled('slow', this.options.warnings)) {
+      // Only warn when the estimated time to run all static mutants exceeds 40%
+      // ... and when the average performance impact of a static mutant is estimated to be twice that of a non-static mutant
+      const ABSOLUTE_CUT_OFF_PERUNAGE = 0.4;
+      const RELATIVE_CUT_OFF_FACTOR = 2;
+      const runPlans = mutantPlans.filter(isRunPlan);
+      const staticRunPlans = runPlans.filter(({ mutant }) => mutant.static);
+      const estimatedTimeForStaticMutants = staticRunPlans.reduce((acc, { netTime }) => acc + netTime, 0);
+      const estimatedTimeForRunTimeMutants = runPlans.filter(({ mutant }) => !mutant.static).reduce((acc, { netTime }) => acc + netTime, 0);
+      const estimatedTotalTime = estimatedTimeForRunTimeMutants + estimatedTimeForStaticMutants;
+      const relativeTimeForStaticMutants = estimatedTimeForStaticMutants / estimatedTotalTime;
+      const relativeNumberOfStaticMutants = staticRunPlans.length / runPlans.length;
+      if (
+        relativeNumberOfStaticMutants * RELATIVE_CUT_OFF_FACTOR < relativeTimeForStaticMutants &&
+        relativeTimeForStaticMutants >= ABSOLUTE_CUT_OFF_PERUNAGE
+      ) {
+        const percentage = (perunage: number) => Math.round(perunage * 100);
+        this.logger.warn(
+          `Detected ${staticRunPlans.length} static mutants (${percentage(
+            staticRunPlans.length / runPlans.length
+          )}% of total) that are estimated to take ${percentage(
+            relativeTimeForStaticMutants
+          )}% of the time running the tests!\n  You might want to enable "ignoreStatic" to ignore these static mutants for your next run. \n  For more information about static mutants visit: https://stryker-mutator.io/docs/mutation-testing-elements/static-mutants.\n  (disable "${optionsPath(
+            'warnings',
+            'slow'
+          )}" to ignore this warning)`
+        );
+      }
+    }
+  }
 }
 
 function calculateTotalTime(testResults: Iterable<TestResult>): number {
@@ -218,3 +254,10 @@ function findHitsByMutantId(coverageData: MutantCoverage | undefined): Map<strin
   }
   return hitsByMutant;
 }
+
+export function isEarlyResult(mutantPlan: MutantTestPlan): mutantPlan is MutantEarlyResultPlan {
+  return mutantPlan.plan === PlanKind.EarlyResult;
+}
+export function isRunPlan(mutantPlan: MutantTestPlan): mutantPlan is MutantRunPlan {
+  return mutantPlan.plan === PlanKind.Run;
+}

packages/core/src/process/4-mutation-test-executor.ts

@@ -1,16 +1,7 @@
 import { from, partition, merge, Observable, lastValueFrom, EMPTY, concat, bufferTime, mergeMap } from 'rxjs';
 import { toArray, map, shareReplay, tap } from 'rxjs/operators';
 import { tokens, commonTokens } from '@stryker-mutator/api/plugin';
-import {
-  MutantResult,
-  MutantStatus,
-  Mutant,
-  StrykerOptions,
-  PlanKind,
-  MutantTestPlan,
-  MutantEarlyResultPlan,
-  MutantRunPlan,
-} from '@stryker-mutator/api/core';
+import { MutantResult, MutantStatus, Mutant, StrykerOptions, PlanKind, MutantTestPlan, MutantRunPlan } from '@stryker-mutator/api/core';
 import { TestRunner } from '@stryker-mutator/api/test-runner';
 import { Logger } from '@stryker-mutator/api/logging';
 import { I } from '@stryker-mutator/util';
@@ -21,7 +12,7 @@ import { StrictReporter } from '../reporters/strict-reporter.js';
 import { MutationTestReportHelper } from '../reporters/mutation-test-report-helper.js';
 import { Timer } from '../utils/timer.js';
 import { ConcurrencyTokenProvider, Pool } from '../concurrent/index.js';
-import { MutantTestPlanner } from '../mutants/index.js';
+import { isEarlyResult, MutantTestPlanner } from '../mutants/index.js';
 import { CheckerFacade } from '../checker/index.js';
 
 import { DryRunContext } from './3-dry-run-executor.js';
@@ -192,7 +183,3 @@ function reloadEnvironmentLast(a: MutantRunPlan, b: MutantRunPlan): number {
   }
   return 0;
 }
-
-function isEarlyResult(mutantPlan: MutantTestPlan): mutantPlan is MutantEarlyResultPlan {
-  return mutantPlan.plan === PlanKind.EarlyResult;
-}

packages/core/src/reporters/progress-keeper.ts

@@ -1,13 +1,11 @@
 import { MutantResult, MutantStatus, MutantRunPlan, MutantTestPlan, PlanKind } from '@stryker-mutator/api/core';
 import { DryRunCompletedEvent, MutationTestingPlanReadyEvent, Reporter, RunTiming } from '@stryker-mutator/api/report';
-import { TestResult } from '@stryker-mutator/api/src/test-runner';
 
 import { Timer } from '../utils/timer.js';
 
 export abstract class ProgressKeeper implements Reporter {
   private timer!: Timer;
   private timing!: RunTiming;
-  private testsById!: Map<string, TestResult>;
   private ticksByMutantId!: Map<string, number>;
   protected progress = {
     survived: 0,
@@ -18,9 +16,8 @@ export abstract class ProgressKeeper implements Reporter {
     ticks: 0,
   };
 
-  public onDryRunCompleted({ result, timing }: DryRunCompletedEvent): void {
+  public onDryRunCompleted({ timing }: DryRunCompletedEvent): void {
     this.timing = timing;
-    this.testsById = new Map(result.tests.map((test) => [test.id, test]));
   }
 
   /**
@@ -30,16 +27,11 @@ export abstract class ProgressKeeper implements Reporter {
   public onMutationTestingPlanReady({ mutantPlans }: MutationTestingPlanReadyEvent): void {
     this.timer = new Timer();
     this.ticksByMutantId = new Map(
-      mutantPlans.filter(isRunPlan).map(({ mutant, runOptions }) => {
-        let ticks = 0;
+      mutantPlans.filter(isRunPlan).map(({ netTime, mutant, runOptions }) => {
+        let ticks = netTime;
         if (runOptions.reloadEnvironment) {
           ticks += this.timing.overhead;
         }
-        if (runOptions.testFilter) {
-          ticks += runOptions.testFilter.reduce((acc, testId) => (this.testsById.get(testId)?.timeSpentMs ?? 0) + acc, 0);
-        } else {
-          ticks += this.timing.net;
-        }
         return [mutant.id, ticks];
       })
     );