diff --git a/docs/config/experimental.md b/docs/config/experimental.md index a3a188cef..82d244ef3 100644 --- a/docs/config/experimental.md +++ b/docs/config/experimental.md @@ -413,3 +413,86 @@ const tags = getTags() test('my test', { tags }, () => {}) ``` ::: + +## experimental.diagnostics 5.0.0 {#experimental-diagnostics} + +- **Type:** + +```ts +interface DiagnosticsOptions { + /** + * Hint when `isolate: true` spends a significant amount of time spawning + * a fresh worker (and re-creating the environment) for every test file, + * estimating how much `isolate: false` could save. + * @default true + */ + isolate?: boolean + /** + * Hint when re-creating a DOM environment for every test file dominates + * the run and a `vm` pool would set it up once per worker. + * @default true + */ + environment?: boolean + /** + * Hint when test files repeatedly evaluate the same module graph + * (typical for barrel-file imports) and `isolate: false` would + * evaluate it once per worker. + * @default true + */ + import?: boolean + /** + * Hint when transforming modules dominates the run and + * `fsModuleCache` would persist the results across runs. + * @default true + */ + transform?: boolean +} +``` + +- **Default:** `true` + +Print performance hints after the run when the collected timings show that a configuration change would make the run significantly faster: + +``` +Environment jsdom was created 40 times · 23.80s total, 79% of tracked time + create it once per worker with pool: 'vmThreads' (keeps per-file isolation) or isolate: false (shares it across files) + learn more: https://vitest.dev/guide/improving-performance#test-environments +``` + +Hints never suggest changing an option that was set explicitly: if the config defines `pool`, other pools are not suggested, and an explicitly configured `isolate` is never suggested to be disabled. Hints are also printed in CI. Set the option to `false` to disable all hints, or disable them individually. + +To measure the impact of a configuration change instead of estimating it, run [`vitest doctor`](/guide/cli#vitest-doctor). + +### experimental.diagnostics.isolate {#experimental-diagnostics-isolate} + +- **Type:** `boolean` +- **Default:** `true` + +Hint when `isolate: true` spends a significant amount of time spawning a fresh worker (and re-creating the environment) for every test file, estimating how much `isolate: false` could save. Reused workers also keep evaluated modules alive, so files stop re-evaluating the module graph they share. Per-module evaluation times are only collected when [`experimental.importDurations`](#experimental-importdurations) is enabled; without it the estimate counts the worker startups alone and is reported as a lower bound ("at least"). + +### experimental.diagnostics.environment {#experimental-diagnostics-environment} + +- **Type:** `boolean` +- **Default:** `true` + +Hint when re-creating a DOM environment for every test file dominates the run and a `vm` pool would set it up once per worker. + +### experimental.diagnostics.import {#experimental-diagnostics-import} + +- **Type:** `boolean` +- **Default:** `true` + +Hint when test files repeatedly evaluate the same module graph and `isolate: false` would evaluate it once per worker. This is typical for barrel-file imports: every test file imports a few symbols through an index file and evaluates the whole graph behind it. The duplication is measured from how often each module was served to the workers, so suites whose test files import mostly disjoint modules stay quiet: reusing workers would not reduce their import work. + +``` +Import 837 modules were evaluated 16740 times · 15.69s total, 64% of tracked time + ~850ms faster with isolate: false — shared modules are evaluated once per worker instead of once per file + learn more: https://vitest.dev/guide/improving-performance#test-isolation +``` + +### experimental.diagnostics.transform {#experimental-diagnostics-transform} + +- **Type:** `boolean` +- **Default:** `true` + +Hint when transforming modules dominates the run. Without a persistent cache every `vitest run` transforms the whole module graph from scratch; [`fsModuleCache`](/config/fsmodulecache) stores the results on disk so repeated runs skip them. The hint estimates the time the next run would save. On CI the hint includes a note that the cache directory must be persisted between runs for the cache to take effect. diff --git a/docs/guide/cli-generated.md b/docs/guide/cli-generated.md index bd55f1f35..e06f45f79 100644 --- a/docs/guide/cli-generated.md +++ b/docs/guide/cli-generated.md @@ -992,3 +992,31 @@ Custom provider for detecting changed files. (default: `git`) - **Config:** [experimental.preParse](/config/experimental#experimental-preparse) Parse test specifications before running them. This will apply `.only` flag and test name pattern across all files without running them. (default: `false`) + +### experimental.diagnostics.isolate + +- **CLI:** `--experimental.diagnostics.isolate` +- **Config:** [experimental.diagnostics.isolate](/config/experimental#experimental-diagnostics-isolate) + +Print a hint estimating how much time `isolate: false` would save when `isolate: true` spends a significant amount of time spawning a worker per test file. (default: `true`) + +### experimental.diagnostics.environment + +- **CLI:** `--experimental.diagnostics.environment` +- **Config:** [experimental.diagnostics.environment](/config/experimental#experimental-diagnostics-environment) + +Print a hint when re-creating a DOM environment for every test file dominates the run and a `vm` pool would set it up once per worker. (default: `true`) + +### experimental.diagnostics.import + +- **CLI:** `--experimental.diagnostics.import` +- **Config:** [experimental.diagnostics.import](/config/experimental#experimental-diagnostics-import) + +Print a hint when test files repeatedly evaluate the same module graph (typical for barrel-file imports) and `isolate: false` would evaluate it once per worker. (default: `true`) + +### experimental.diagnostics.transform + +- **CLI:** `--experimental.diagnostics.transform` +- **Config:** [experimental.diagnostics.transform](/config/experimental#experimental-diagnostics-transform) + +Print a hint when transforming modules dominates the run and `fsModuleCache` would persist the results across runs. (default: `true`) diff --git a/docs/guide/cli.md b/docs/guide/cli.md index dcef0f023..afff5f82a 100644 --- a/docs/guide/cli.md +++ b/docs/guide/cli.md @@ -123,6 +123,50 @@ tests/test2.test.ts Since Vitest 4.1, you may pass `--static-parse` to [parse test files](/api/advanced/vitest#parsespecifications) instead of running them to collect tests. Vitest parses test files with limited concurrency, defaulting to `os.availableParallelism()`. You can change it via the `--static-parse-concurrency` option. +### `vitest doctor` + +`vitest doctor` measures how much faster the test suite would run under alternative configurations by running it under each of them. The candidates are picked based on the current config: + +```bash +vitest doctor +``` + +``` +Results (min of 3 runs each) + + baseline (pool: forks · isolate: true) 4.08s + pool: 'threads' 3.64s (-11%) + pool: 'vmThreads' 1.33s (-67%) + isolate: false 1.28s (-69%) + +Recommendation: pool: 'vmThreads' (-67%) + + // vitest.config.ts + import { defineConfig } from 'vitest/config' + + export default defineConfig({ + test: { + pool: 'vmThreads', // measured -67% on this suite + }, + }) +``` + +The `isolate: false` candidate is additionally validated by running the suite twice with a shuffled file order: if any test depends on isolation, the candidate is reported as failed instead of recommended. When several candidates are close to the fastest, doctor prefers the one that keeps per-file isolation. + +Doctor also probes lower [`maxWorkers`](/config/maxworkers) values on top of the winning configuration: every worker funnels its transform requests through the single main-thread Vite server, so past a certain count more workers make the run slower, not faster. Starting from half the current worker count, doctor keeps halving while the suite gets at least 5% faster, and includes the winning value in the recommendation. + +Suites running a DOM environment are measured under both vm pools, `vmThreads` and `vmForks`: they amortize the environment creation cost by keeping one environment per worker while every file still gets a fresh VM context. `vmForks` uses child processes instead of worker threads: each child gets its own heap and garbage collector, so either pool can come out faster depending on the suite, and `vmForks` is the vm option for suites that cannot run in worker threads. + +Projects running `jsdom` are also measured under `environment: 'happy-dom'` when the package is installed. The swap is applied per project; projects on other environments keep them. happy-dom implements the DOM differently than jsdom, so tests that depend on layout or navigation should be verified before adopting the swap. When the [fs module cache](/config/fsmodulecache) is off, doctor measures `fsModuleCache: true` after an untimed priming run that populates the cache, so the reported time is what repeated runs pay. + +Every measurement runs the full suite, including browser projects: `isolate: false` also affects browser mode. Candidates that cannot affect browser projects (`pool`, `environment`, the fs module cache) are picked based on the node-side projects only. + +Failing candidates are reported with an excerpt of their errors. If the suite fails under the current configuration, doctor aborts and shows the errors: it needs a passing baseline to compare against. + +Short suites are measured multiple times and the best time is reported, so the comparison reflects a warm steady state. Doctor runs the full suite several times, so it takes a multiple of a normal run's time. See [Improving Performance](/guide/improving-performance) for the trade-offs behind every candidate. + +Doctor measures and reports the baseline even when there are no candidates to compare. Configurations on a `vm` pool are additionally compared against `pool: 'threads'` with `isolate: false`, which also reuses workers but shares module state between files; a configuration already on one vm pool is still measured under the other. + ## Shell Autocompletions Vitest provides shell autocompletions for commands, options, and option values powered by [`@bomb.sh/tab`](https://github.com/bombshell-dev/tab). diff --git a/docs/guide/improving-performance.md b/docs/guide/improving-performance.md index 58244a92a..4cf231854 100644 --- a/docs/guide/improving-performance.md +++ b/docs/guide/improving-performance.md @@ -1,5 +1,28 @@ # Improving Performance +## Profile First + +The `Duration` line of the summary breaks the run down into phases, as percentages of all tracked time: + +``` +Duration 3.76s (environment 79%, import 13%, transform 6%, tests 1%, setup 1%) +``` + +The percentages are relative to the sum of all tracked phases, not to the wall-clock time: phases run in parallel workers, so their sum is usually larger than the run itself. In a multi-project setup the percentages aggregate over all [projects](/guide/projects), so a phase that dominates one project can be diluted by the others; the performance hints below analyze each project separately. + +The phases map to configuration options: + +- `environment` - creating the test environment (for example `jsdom`, `happy-dom`) for test files. See [Test Environments](#test-environments). +- `transform` - waiting for Vite to resolve and transform imported modules. See [Caching Between Reruns](#caching-between-reruns). +- `import` - evaluating test files and their modules, excluding the transform wait tracked above. When files import mostly the same modules (typical for barrel-file imports), isolation re-evaluates that shared graph for every file. See [Test Isolation](#test-isolation). +- `setup` - running [`setupFiles`](/config/setupfiles). +- `worker` - preparing the test runner in each worker. Isolation pays this cost for every test file. See [Test Isolation](#test-isolation). +- `tests` - running the tests themselves. A run dominated by this phase has little to gain from configuration changes. + +When the collected timings show that a configuration change would make the run significantly faster, Vitest also prints a hint after the summary, see [`experimental.diagnostics`](/config/experimental#experimental-diagnostics). Hints never suggest changing an option that was set explicitly. + +[`vitest doctor`](/guide/cli#vitest-doctor) measures the alternative configurations instead of estimating them: it runs the suite under each candidate and reports the comparison, including whether the tests pass with `isolate: false`. + ## Test Isolation By default Vitest runs every test file in an isolated environment based on the [pool](/config/pool): @@ -73,6 +96,31 @@ export default defineConfig({ ``` ::: +## Test Environments + +DOM environments are expensive to create: `jsdom` costs roughly 200-500ms per import and `happy-dom` roughly 90-200ms, plus the time to construct the window. With an isolating pool (the default), that cost is paid for every test file, because every file gets a fresh worker. On DOM-heavy suites this is often the largest cost of the run; it appears as the `environment` share of the `Duration` breakdown. + +Three configurations reduce this cost: + +| configuration | environment created | isolation | trade-off | +|---|---|---|---| +| `pool: 'forks'`/`'threads'` + `isolate: true` (default) | once per file | fresh process/thread and environment per file | safest, slowest | +| `pool: 'vmThreads'` | once per worker | fresh VM context and `window` per file | test code runs in a VM realm: cross-realm `instanceof` edge cases with externalized packages, and memory is not reclaimed as reliably (see [`vmMemoryLimit`](/config/vmmemorylimit)) | +| `isolate: false` | once per worker | none - files in the same worker share the environment and module state | tests must not depend on a clean `window` or module state; run `vitest doctor` to check | + +```ts [vitest.config.js] +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + environment: 'jsdom', + pool: 'vmThreads', // environment per worker, fresh window per file + }, +}) +``` + +Prefer `isolate: false` with `threads` if the tests tolerate shared state: it is the fastest option and keeps memory behavior simple. Use `vmThreads` when every file needs a fresh `window` and the per-file environment cost dominates the run. `happy-dom` is cheaper to create than `jsdom` in every setup. + ## Limiting Directory Search You can limit the working directory when Vitest searches for files using [`test.dir`](/config/dir) option. This should make the search faster if you have unrelated folders and files in the root directory. @@ -85,10 +133,10 @@ This improvement is most noticeable when rerunning a small number of tests that ```shell # the first run -Duration 8.75s (transform 4.02s, setup 629ms, import 5.52s, tests 2.52s, environment 0ms, prepare 3ms) +Duration 8.75s (import 43%, transform 32%, tests 20%, setup 5%) # the second run -Duration 5.90s (transform 842ms, setup 543ms, import 2.35s, tests 2.94s, environment 0ms, prepare 3ms) +Duration 5.90s (tests 44%, import 35%, transform 13%, setup 8%) ``` ## Node Compile Cache diff --git a/packages/browser/src/client/tester/state.ts b/packages/browser/src/client/tester/state.ts index 55e6e77f5..d54d1627e 100644 --- a/packages/browser/src/client/tester/state.ts +++ b/packages/browser/src/client/tester/state.ts @@ -42,6 +42,7 @@ const state: WorkerGlobalState = { durations: { environment: 0, prepare: performance.now(), + fetch: 0, }, providedContext: {}, } diff --git a/packages/vitest/src/node/cli/cac.ts b/packages/vitest/src/node/cli/cac.ts index f5d9d58bf..5ef682197 100644 --- a/packages/vitest/src/node/cli/cac.ts +++ b/packages/vitest/src/node/cli/cac.ts @@ -186,6 +186,10 @@ export function createCLI(options: CliParseOptions = {}): CAC { .command('init ', undefined, options) .action(init) + cli + .command('doctor [...filters]', undefined, options) + .action(doctorCommand) + addCliOptions( cli .command('list [...filters]', undefined, options) @@ -321,6 +325,23 @@ async function start(cliFilters: string[], options: CliOptions): Promise { } } +async function doctorCommand(cliFilters: string[], options: CliOptions): Promise { + try { + const { doctor } = await import('./doctor') + await doctor(cliFilters.map(normalize), normalizeCliOptions(cliFilters, options)) + process.exit() + } + catch (e) { + const { errorBanner } = await import('../reporters/renderers/utils') + console.error(`\n${errorBanner('Doctor Error')}`) + console.error(e) + console.error('\n\n') + + process.exitCode ??= 1 + process.exit() + } +} + async function init(project: string) { if (project !== 'browser') { console.error(new Error('Only the "browser" project is supported. Use "vitest init browser" to create a new project.')) diff --git a/packages/vitest/src/node/cli/cli-config.ts b/packages/vitest/src/node/cli/cli-config.ts index 8f5a4e1d5..5adf434e5 100644 --- a/packages/vitest/src/node/cli/cli-config.ts +++ b/packages/vitest/src/node/cli/cli-config.ts @@ -950,6 +950,24 @@ export const cliOptionsConfig: VitestCLIOptions = { preParse: { description: 'Parse test specifications before running them. This will apply `.only` flag and test name pattern across all files without running them. (default: `false`)', }, + diagnostics: { + description: 'Print performance hints after the run when a configuration change would make it significantly faster. Hints never suggest changing options that were set explicitly. (default: `true`)', + argument: '', + subcommands: { + isolate: { + description: 'Print a hint estimating how much time `isolate: false` would save when `isolate: true` spends a significant amount of time spawning a worker per test file. (default: `true`)', + }, + environment: { + description: 'Print a hint when re-creating a DOM environment for every test file dominates the run and a `vm` pool would set it up once per worker. (default: `true`)', + }, + import: { + description: 'Print a hint when test files repeatedly evaluate the same module graph (typical for barrel-file imports) and `isolate: false` would evaluate it once per worker. (default: `true`)', + }, + transform: { + description: 'Print a hint when transforming modules dominates the run and `fsModuleCache` would persist the results across runs. (default: `true`)', + }, + }, + }, }, }, // disable CLI options diff --git a/packages/vitest/src/node/cli/doctor.ts b/packages/vitest/src/node/cli/doctor.ts new file mode 100644 index 000000000..575f4de11 --- /dev/null +++ b/packages/vitest/src/node/cli/doctor.ts @@ -0,0 +1,635 @@ +import type { CliOptions } from './cli-api' +import { spawn } from 'node:child_process' +import { mkdtempSync, rmSync, writeFileSync } from 'node:fs' +import { availableParallelism, tmpdir } from 'node:os' +import { join } from 'node:path' +import { performance } from 'node:perf_hooks' +import { pathToFileURL } from 'node:url' +import { toArray } from '@vitest/utils/helpers' +import { resolve } from 'pathe' +import c from 'tinyrainbow' +import { distDir } from '../../paths' + +export interface DoctorProjectSummary { + name: string + pool: string + environment: string + isolate: boolean + browser: boolean + fsModuleCache: boolean +} + +export interface DoctorCandidateOptions { + /** `happy-dom` is resolvable, so the environment candidate can actually run. */ + happyDomAvailable?: boolean +} + +export interface DoctorCandidate { + id: string + /** Human readable config change, e.g. `pool: 'threads'`. */ + title: string + /** Config overrides applied to the measured run. */ + overrides: CliOptions + /** + * Swap `test.environment` of every project currently using `from` to `to`. + * Applied per project by the runner script, so projects running other + * environments keep them. + */ + envSwap?: { from: string; to: string } + /** Config entries to show in the recommended snippet, one per line. */ + configLines: string[] + /** Keeps every test file in its own fresh environment. */ + preservesIsolation: boolean + /** Run extra shuffled passes to check that tests survive shared state. */ + validateIsolation?: boolean + /** + * Untimed runs before the measured ones. Used for candidates whose benefit + * only shows once a persistent cache is populated. + */ + primeRuns?: number +} + +const DOM_ENVIRONMENTS = new Set(['jsdom', 'happy-dom']) + +/** + * Builds the list of configurations worth measuring for this config. The + * candidates are pruned by what the config already uses - there is no point + * in measuring `threads` when the config already runs in `threads`. + */ +export function resolveDoctorCandidates( + projects: DoctorProjectSummary[], + options: DoctorCandidateOptions = {}, +): DoctorCandidate[] { + const candidates: DoctorCandidate[] = [] + // `pool`, `environment` and the fs module cache don't reach the browser + // runtime, so those candidates are driven by the node-side projects only; + // isolation applies to browser projects as well + const testProjects = projects.filter(project => !project.browser) + + const pools = new Set(testProjects.map(project => project.pool)) + const usesVmPool = pools.has('vmThreads') || pools.has('vmForks') + const runsDom = testProjects.some(project => + DOM_ENVIRONMENTS.has(project.environment), + ) + const isolates = projects.some( + project => project.isolate + && (project.browser || (project.pool !== 'vmThreads' && project.pool !== 'vmForks')), + ) + + if (pools.has('forks')) { + candidates.push({ + id: 'threads', + title: `pool: 'threads'`, + overrides: { pool: 'threads' }, + configLines: [`pool: 'threads'`], + preservesIsolation: true, + }) + } + if (runsDom && !pools.has('vmThreads')) { + candidates.push({ + id: 'vmThreads', + title: `pool: 'vmThreads'`, + overrides: { pool: 'vmThreads' }, + configLines: [`pool: 'vmThreads'`], + preservesIsolation: true, + }) + } + // vmForks trades vmThreads' worker threads for child processes: each child + // gets its own heap and GC, which can beat vmThreads on GC-heavy suites, and + // it is the vm option for suites that cannot run in worker threads + if (runsDom && !pools.has('vmForks')) { + candidates.push({ + id: 'vmForks', + title: `pool: 'vmForks'`, + overrides: { pool: 'vmForks' }, + configLines: [`pool: 'vmForks'`], + preservesIsolation: true, + }) + } + // jsdom -> happy-dom is the only swap with a speed upside; it is applied per + // project, so projects running other environments keep them + if (options.happyDomAvailable && testProjects.some(project => project.environment === 'jsdom')) { + candidates.push({ + id: 'happy-dom', + title: `environment: 'happy-dom'`, + overrides: {}, + envSwap: { from: 'jsdom', to: 'happy-dom' }, + configLines: [`environment: 'happy-dom'`], + preservesIsolation: true, + }) + } + if (isolates) { + candidates.push({ + id: 'no-isolate', + title: 'isolate: false', + overrides: { isolate: false }, + configLines: ['isolate: false'], + preservesIsolation: false, + validateIsolation: true, + }) + } + if (usesVmPool) { + // the honest competitor of a vm pool: reused workers with shared state + candidates.push({ + id: 'threads-no-isolate', + title: `pool: 'threads' + isolate: false`, + overrides: { pool: 'threads', isolate: false }, + configLines: [`pool: 'threads'`, 'isolate: false'], + preservesIsolation: false, + validateIsolation: true, + }) + } + if (testProjects.length > 0 && testProjects.every(project => !project.fsModuleCache)) { + // an untimed priming run populates the cache first: the candidate measures + // what repeated runs pay, which is what doctor compares everywhere else + candidates.push({ + id: 'fs-cache', + title: 'fsModuleCache: true', + overrides: { fsModuleCache: true }, + configLines: ['fsModuleCache: true'], + preservesIsolation: true, + primeRuns: 1, + }) + } + + return candidates +} + +interface MeasuredRun { + wall: number + ok: boolean + stderr: string +} + +interface MeasuredCandidate { + candidate: DoctorCandidate + wall: number + ok: boolean + stderr: string + isolationVerdict?: 'passed' | 'failed' +} + +function log(...args: string[]): void { + console.log(...args) +} + +export async function doctor(cliFilters: string[], options: CliOptions): Promise { + const { prepareVitest } = await import('./cli-api') + + log() + log(c.inverse(c.bold(c.blue(' DOCTOR '))), 'resolving the current configuration...') + + const ctx = await prepareVitest( + { ...options, watch: false, run: true }, + undefined, + undefined, + cliFilters, + ) + const projects: DoctorProjectSummary[] = ctx.projects.map(project => ({ + name: project.name, + pool: project.config.pool, + environment: project.config.environment, + isolate: project.config.isolate, + browser: project.config.browser.enabled, + fsModuleCache: project.config.fsModuleCache === true, + })) + const fileCount = (await ctx.getRelevantTestSpecifications(cliFilters)).length + const configuredMaxWorkers = ctx.config.maxWorkers + const effectiveMaxWorkers = typeof configuredMaxWorkers === 'number' && configuredMaxWorkers > 0 + ? configuredMaxWorkers + : Math.max(1, availableParallelism() - 1) + await ctx.close() + + // the environments import 'happy-dom' relative to the vitest package (it is + // a peer dependency), so resolving from here mirrors what a run would do + let happyDomAvailable = false + try { + import.meta.resolve('happy-dom') + happyDomAvailable = true + } + catch {} + + const candidates = resolveDoctorCandidates(projects, { happyDomAvailable }) + + const baselineTitle = `baseline (${describeProjects(projects)})` + + // every measured run goes through one generated runner script: candidates + // may need per-project overrides (the happy-dom swap), which the CLI cannot + // express, and routing the baseline through the same entry keeps the + // process cost identical across measurements + const runnerDir = mkdtempSync(join(tmpdir(), 'vitest-doctor-')) + const runnerPath = join(runnerDir, 'runner.mjs') + writeFileSync(runnerPath, createRunnerScript()) + process.once('exit', () => rmSync(runnerDir, { recursive: true, force: true })) + + const childProjects = toArray(options.project).map(String) + const childOptions: CliOptions = { + watch: false, + ...(options.root ? { root: String(options.root) } : {}), + ...(options.config ? { config: String(options.config) } : {}), + ...(childProjects.length ? { project: childProjects } : {}), + } + + // make sure an interrupted doctor doesn't leave a test suite running + let activeChild: ReturnType | undefined + const killActiveChild = (): never => { + activeChild?.kill('SIGKILL') + process.exit(130) + } + process.once('SIGINT', killActiveChild) + process.once('SIGTERM', killActiveChild) + + interface RunOverrides { + overrides?: CliOptions + envSwap?: DoctorCandidate['envSwap'] + } + + const runVitest = (run: RunOverrides, timeoutMs?: number): Promise => { + return new Promise((resolve) => { + const start = performance.now() + const payload = JSON.stringify({ + filters: cliFilters, + options: { ...childOptions, ...run.overrides }, + envSwap: run.envSwap, + }) + const child = spawn( + process.execPath, + [runnerPath, payload], + { + env: { ...process.env, NO_COLOR: '1' }, + stdio: ['ignore', 'ignore', 'pipe'], + }, + ) + activeChild = child + let timedOut = false + const timer = timeoutMs + ? setTimeout(() => { + timedOut = true + child.kill('SIGKILL') + }, timeoutMs) + : undefined + let stderr = '' + child.stderr!.on('data', (chunk) => { + stderr = (stderr + String(chunk)).slice(-4_000) + }) + child.on('close', (code) => { + if (timer) { + clearTimeout(timer) + } + activeChild = undefined + if (timedOut) { + stderr += `\n(the run was killed after exceeding ${Math.round((timeoutMs || 0) / 1000)}s - several times the baseline duration)` + } + resolve({ wall: performance.now() - start, ok: code === 0 && !timedOut, stderr }) + }) + }) + } + + log() + if (candidates.length === 0) { + log('The configuration already uses the fastest setup Vitest knows how to compare - measuring it for reference.') + } + else { + log('Measuring alternative configurations by running the test suite under each of them.') + log(c.dim('Close other heavy programs - the comparison is only as good as the machine is quiet.')) + } + log() + + // The first baseline run also warms up caches for every following run, so + // candidates are compared in a warm steady state. + process.stdout.write(c.dim(` measuring ${baselineTitle}...`)) + const firstRun = await runVitest({}) + if (!firstRun.ok) { + process.stdout.write('\n') + log(c.red('The test suite fails with the current configuration. Fix the failures first - doctor needs a green suite to compare configurations.')) + if (firstRun.stderr.trim()) { + log(c.dim(firstRun.stderr.trim())) + } + process.exitCode = 1 + return + } + + // scale repetitions to the suite duration: short suites are noisy and can + // afford more runs, long suites cannot + const reps = firstRun.wall < 10_000 ? 3 : firstRun.wall < 60_000 ? 2 : 1 + // the first run is cold and mostly warms up caches: always take at least one + // more baseline run so the reported baseline is a warm one, like the + // candidates that run after it + const baselineRuns = Math.max(reps, 2) + const baselineWalls = [firstRun.wall] + for (let i = 1; i < baselineRuns; i++) { + const run = await runVitest({}) + if (!run.ok) { + process.stdout.write('\n') + log(c.red(`The test suite passed once but failed on repetition ${i + 1} with the same configuration - doctor needs a stable green suite to compare configurations.`)) + if (run.stderr.trim()) { + log(c.dim(run.stderr.trim())) + } + process.exitCode = 1 + return + } + baselineWalls.push(run.wall) + } + const baselineWall = Math.min(...baselineWalls) + process.stdout.write(` ${formatSeconds(baselineWall)}\n`) + + // a candidate that takes several times the baseline is a regression, not a + // recommendation - don't let it stall doctor indefinitely + const candidateTimeout = Math.max(60_000, baselineWall * 4) + + const measured: MeasuredCandidate[] = [] + for (const candidate of candidates) { + process.stdout.write(c.dim(` measuring ${candidate.title}...`)) + let wall = Number.POSITIVE_INFINITY + let ok = true + let stderr = '' + const candidateRun: RunOverrides = { overrides: candidate.overrides, envSwap: candidate.envSwap } + for (let i = 0; i < (candidate.primeRuns ?? 0) && ok; i++) { + const run = await runVitest(candidateRun, candidateTimeout) + ok = run.ok + stderr = run.stderr + } + for (let i = 0; i < reps && ok; i++) { + const run = await runVitest(candidateRun, candidateTimeout) + wall = Math.min(wall, run.wall) + ok = run.ok + stderr = run.stderr + } + + let isolationVerdict: MeasuredCandidate['isolationVerdict'] + if (ok && candidate.validateIsolation) { + // tests can pass under shared state by accident of ordering: shuffle the + // file order twice to catch the common cross-file couplings; the explicit + // distinct seeds guarantee two different orders even when the user pinned + // `sequence.seed` in their config + isolationVerdict = 'passed' + for (let i = 0; i < 2; i++) { + const run = await runVitest( + { + overrides: { + ...candidate.overrides, + sequence: { shuffle: { files: true }, seed: 271828 + i }, + }, + envSwap: candidate.envSwap, + }, + candidateTimeout, + ) + if (!run.ok) { + isolationVerdict = 'failed' + stderr = run.stderr + break + } + } + } + + measured.push({ candidate, wall, ok, stderr, isolationVerdict }) + process.stdout.write(ok ? ` ${formatSeconds(wall)}\n` : ` ${c.red('failed')}\n`) + } + + const viable = measured.filter(result => + result.ok + && result.isolationVerdict !== 'failed' + && result.wall < baselineWall * 0.9, + ) + + // among candidates close to the fastest, prefer the one that keeps per-file + // isolation - equal speed with stronger guarantees wins + const fastest = viable.length > 0 + ? viable.reduce((a, b) => (b.wall < a.wall ? b : a)) + : undefined + const preferred = fastest + ? viable + .filter(result => result.wall <= fastest.wall * 1.05) + .sort((a, b) => Number(b.candidate.preservesIsolation) - Number(a.candidate.preservesIsolation))[0] + : undefined + + // Past a certain worker count the single main-thread Vite server becomes the + // bottleneck, so FEWER workers can be faster. Greedily descend by halving on + // top of the winning configuration, keeping a step only when it is a real + // (>= 5%) improvement. + const workerStack: RunOverrides = preferred + ? { overrides: preferred.candidate.overrides, envSwap: preferred.candidate.envSwap } + : {} + const workerSuffix = preferred ? ` (with ${preferred.candidate.title})` : '' + interface WorkerProbe { workers: number; wall: number } + const workerProbes: WorkerProbe[] = [] + let bestWorkers: WorkerProbe | undefined + { + let currentBest = preferred ? preferred.wall : baselineWall + let probe = Math.floor(effectiveMaxWorkers / 2) + while (probe >= 2 && probe < fileCount) { + process.stdout.write(c.dim(` measuring maxWorkers: ${probe}${workerSuffix}...`)) + let wall = Number.POSITIVE_INFINITY + let ok = true + for (let i = 0; i < reps && ok; i++) { + const run = await runVitest( + { overrides: { ...workerStack.overrides, maxWorkers: probe }, envSwap: workerStack.envSwap }, + candidateTimeout, + ) + wall = Math.min(wall, run.wall) + ok = run.ok + } + process.stdout.write(ok ? ` ${formatSeconds(wall)}\n` : ` ${c.red('failed')}\n`) + if (!ok) { + break + } + workerProbes.push({ workers: probe, wall }) + if (wall >= currentBest * 0.95) { + break + } + currentBest = wall + bestWorkers = { workers: probe, wall } + probe = Math.floor(probe / 2) + } + } + + log() + log(c.bold('Results') + c.dim(` (min of ${reps} run${reps === 1 ? '' : 's'} each)`)) + log() + const rowTitles = [ + ...measured.map(m => m.candidate.title), + ...workerProbes.map(p => `maxWorkers: ${p.workers}${workerSuffix}`), + ] + const width = Math.max(baselineTitle.length, ...rowTitles.map(title => title.length)) + 2 + log(` ${baselineTitle.padEnd(width)}${formatSeconds(baselineWall)}`) + for (const result of measured) { + const title = result.candidate.title.padEnd(width) + if (!result.ok) { + log(` ${title}${c.red('failed')}`) + } + else if (result.isolationVerdict === 'failed') { + log(` ${title}${formatSeconds(result.wall)} ${c.red('(fails with a shuffled file order - tests depend on isolation)')}`) + } + else { + log(` ${title}${formatSeconds(result.wall)} ${formatDelta(result.wall, baselineWall)}`) + } + } + for (const probeResult of workerProbes) { + const title = `maxWorkers: ${probeResult.workers}${workerSuffix}`.padEnd(width) + log(` ${title}${formatSeconds(probeResult.wall)} ${formatDelta(probeResult.wall, baselineWall)}`) + } + + // failing candidates are as informative as fast ones: show what broke, + // so "vmThreads is not an option for this suite" comes with the reason + for (const result of measured) { + if (!result.ok) { + logFailureExcerpt(`${result.candidate.title} failed with:`, result.stderr) + } + else if (result.isolationVerdict === 'failed') { + logFailureExcerpt(`${result.candidate.title} failed with a shuffled file order:`, result.stderr) + } + } + + log() + if (!preferred && !bestWorkers) { + if (candidates.length === 0) { + log(`${c.bold('Recommendation:')} keep the current configuration (${describeProjects(projects)}) - it measured ${c.yellow(formatSeconds(baselineWall))} and Vitest has no faster candidate to suggest for it.`) + } + else { + log(`${c.bold('Recommendation:')} keep the current configuration (${describeProjects(projects)}) - no measured candidate was more than 10% faster.`) + } + return + } + + const finalWall = bestWorkers ? bestWorkers.wall : preferred!.wall + const recommendationTitle = [ + preferred?.candidate.title, + bestWorkers ? `maxWorkers: ${bestWorkers.workers}` : undefined, + ].filter(Boolean).join(' + ') + const configLines = [ + ...(preferred ? preferred.candidate.configLines : []), + ...(bestWorkers ? [`maxWorkers: ${bestWorkers.workers}`] : []), + ] + + log(`${c.bold('Recommendation:')} ${c.yellow(recommendationTitle)} ${formatDelta(finalWall, baselineWall)}`) + log() + log(c.dim(' // vitest.config.ts')) + log(c.dim(` import { defineConfig } from 'vitest/config'`)) + log() + log(c.dim(' export default defineConfig({')) + log(c.dim(' test: {')) + for (const [index, line] of configLines.entries()) { + const comment = index === configLines.length - 1 + ? c.dim(` // measured ${Math.round(((finalWall - baselineWall) / baselineWall) * 100)}% on this suite`) + : '' + log(` ${line},${comment}`) + } + log(c.dim(' },')) + log(c.dim(' })')) + log() + if (preferred) { + for (const note of candidateNotes(preferred)) { + log(c.dim(` ${note}`)) + } + } + if (bestWorkers) { + log(c.dim(` Fewer workers can be faster because every worker funnels transforms through the`)) + log(c.dim(` single main-thread Vite server; a lower count also reduces memory pressure.`)) + } + if (projects.length > 1) { + const note = preferred?.candidate.envSwap + ? `Doctor swapped the environment of every project running ${preferred.candidate.envSwap.from}; other projects were left unchanged.` + : 'Doctor overrides options for all projects at once; apply the change per project if they need different settings.' + log(c.dim(` ${note}`)) + } + log(c.dim(' Trade-offs of every option: https://vitest.dev/guide/improving-performance')) +} + +/** + * The measured runs execute this script instead of the CLI binary: it accepts + * the overrides as JSON and can apply per-project changes (the environment + * swap) that CLI flags cannot express. `createVitest` attaches the projects, + * so the swap mutates each resolved project config before the run starts. + */ +function createRunnerScript(): string { + const nodeEntry = pathToFileURL(resolve(distDir, 'node.js')).href + return `import { createVitest } from ${JSON.stringify(nodeEntry)} + +const { filters, options, envSwap } = JSON.parse(process.argv[2]) +const ctx = await createVitest(options) +if (envSwap) { + for (const project of ctx.projects) { + if (!project.config.browser.enabled && project.config.environment === envSwap.from) { + project.config.environment = envSwap.to + } + } +} +try { + await ctx.start(filters) +} +catch (error) { + console.error(error?.stack || String(error)) + process.exitCode = 1 +} +await ctx.close() +process.exit(process.exitCode || 0) +` +} + +const FAILURE_EXCERPT_LINES = 15 + +function logFailureExcerpt(title: string, stderr: string): void { + log() + log(` ${c.red(title)}`) + if (!stderr.trim()) { + log(c.dim(' (the run produced no error output - rerun with the same options to inspect it)')) + return + } + const lines = stderr.trim().split('\n') + const excerpt = lines.slice(-FAILURE_EXCERPT_LINES) + if (lines.length > excerpt.length) { + log(c.dim(` … (last ${excerpt.length} lines)`)) + } + for (const line of excerpt) { + log(c.dim(` ${line}`)) + } +} + +function candidateNotes(result: MeasuredCandidate): string[] { + switch (result.candidate.id) { + case 'vmThreads': + case 'vmForks': + return [ + `vm pools keep per-file isolation but run test code in a VM context: cross-realm`, + `instanceof edge cases and higher memory usage are possible (see vmMemoryLimit).`, + ] + case 'no-isolate': + case 'threads-no-isolate': + return [ + `The suite passed twice with a shuffled file order under shared state, so it is`, + `likely - but not guaranteed - that no test depends on isolation.`, + ] + case 'happy-dom': + return [ + `The swap was applied only to projects running jsdom; other projects kept their`, + `environment. happy-dom implements the DOM differently than jsdom: the suite`, + `passed under it, but double-check tests that depend on layout, navigation or`, + `other DOM edge cases.`, + ] + case 'fs-cache': + return [ + `The fs module cache persists transformed modules on disk: repeated runs skip`, + `the transforms, the first run after a file change still pays them.`, + ] + default: + return [] + } +} + +function describeProjects(projects: DoctorProjectSummary[]): string { + const pools = [...new Set(projects.map(project => project.browser ? 'browser' : project.pool))].join(', ') + const isolate = projects.some(project => project.isolate) + return `pool: ${pools} · isolate: ${isolate}` +} + +function formatSeconds(time: number): string { + return `${(time / 1000).toFixed(2)}s` +} + +function formatDelta(wall: number, baseline: number): string { + const delta = Math.round(((wall - baseline) / baseline) * 100) + if (delta === 0) { + return c.dim('(±0%)') + } + return delta < 0 ? c.green(`(${delta}%)`) : c.yellow(`(+${delta}%)`) +} diff --git a/packages/vitest/src/node/config/resolveConfig.ts b/packages/vitest/src/node/config/resolveConfig.ts index 18a050ebe..d9908f323 100644 --- a/packages/vitest/src/node/config/resolveConfig.ts +++ b/packages/vitest/src/node/config/resolveConfig.ts @@ -170,6 +170,24 @@ function resolveInlineWorkerOption(value: string | number): number { } } +/** + * Records which options the user provided explicitly. Must be computed from + * the raw user config sources BEFORE `configDefaults` is merged in - the + * merged object cannot distinguish a default from a user-provided value. + */ +export function captureProvidedOptions( + ...sources: (UserConfig | undefined)[] +): ResolvedConfig['providedOptions'] { + return { + pool: sources.some(source => source?.pool != null), + isolate: sources.some(source => source?.isolate != null), + environment: sources.some(source => source?.environment != null || source?.dom), + fsModuleCache: sources.some(source => + source?.fsModuleCache != null + || (source?.experimental as { fsModuleCache?: boolean } | undefined)?.fsModuleCache != null), + } +} + // warn only once, check one PER PROCESS, not per instance, // that's why it's on a module-level let warnedTypeCheck = false @@ -205,8 +223,18 @@ export function resolveTestConfig( options.environment = 'happy-dom' } + // provenance must be captured from the raw options BEFORE `configDefaults` + // is merged in - the merged object cannot distinguish a default from a + // user-provided value; `viteConfig.test` is not resolved yet at this point, + // the call sites assign the resolved config to it after this function returns + const providedOptions = captureProvidedOptions( + options, + viteConfig.test as UserConfig | undefined, + ) + const resolved = deepMerge({}, configDefaults, options) as ResolvedConfig resolved.root = viteConfig.root + resolved.providedOptions = providedOptions // These options are resolved once for the whole run using the root config. // Coverage is shared by reference: each project's setup/test/config files are @@ -997,6 +1025,17 @@ export function resolveTestConfig( resolved.experimental.importDurations.thresholds.warn ??= 100 resolved.experimental.importDurations.thresholds.danger ??= 500 + const diagnostics = (resolved.experimental.diagnostics as boolean | { isolate?: boolean; environment?: boolean; import?: boolean; transform?: boolean } | undefined) + ?? true + resolved.experimental.diagnostics = typeof diagnostics === 'boolean' + ? { isolate: diagnostics, environment: diagnostics, import: diagnostics, transform: diagnostics } + : { + isolate: diagnostics.isolate ?? true, + environment: diagnostics.environment ?? true, + import: diagnostics.import ?? true, + transform: diagnostics.transform ?? true, + } + if (typeof resolved.experimental.vcsProvider === 'string' && resolved.experimental.vcsProvider !== 'git') { resolved.experimental.vcsProvider = resolvePath(resolved.experimental.vcsProvider, resolved.root) } diff --git a/packages/vitest/src/node/core.ts b/packages/vitest/src/node/core.ts index 88762dafc..66073e4d5 100644 --- a/packages/vitest/src/node/core.ts +++ b/packages/vitest/src/node/core.ts @@ -255,7 +255,6 @@ export class Vitest { this._resolver, resolved, this._fsCache, - this.state, this._traces, this._tmpDir, ) @@ -677,9 +676,8 @@ export class Vitest { throw new Error('Cannot merge reports when `--reporter=blob` is used. Remove blob reporter from the config first.') } - const { files, errors, coverages, executionTimes, transformTimes } = await readBlobs(this.version, directory || this.config.mergeReports, this.projects) - this.state.blobs = { files, errors, coverages, executionTimes, transformTimes } - this.state.transformTime = transformTimes.reduce((a, b) => a + b, 0) + const { files, errors, coverages, executionTimes } = await readBlobs(this.version, directory || this.config.mergeReports, this.projects) + this.state.blobs = { files, errors, coverages, executionTimes } await this.report('onInit', this) diff --git a/packages/vitest/src/node/environments/fetchModule.ts b/packages/vitest/src/node/environments/fetchModule.ts index ee4ad00f3..6a3462ea1 100644 --- a/packages/vitest/src/node/environments/fetchModule.ts +++ b/packages/vitest/src/node/environments/fetchModule.ts @@ -24,18 +24,6 @@ const saveCachePromises = new Map< >() const readFilePromises = new Map>() -/** - * Tracks the wall time during which at least one transform is running. - * Durations of individual fetches cannot be summed instead: concurrent - * fetches (parallel workers, the vm pool graph prewarm) all wait on the same - * deduplicated in-flight transforms, so per-caller wall times overcount the - * actual work by orders of magnitude. - */ -export interface TransformClock { - transformStarted: () => void - transformFinished: () => void -} - class ModuleFetcher { private tmpDirectories = new Set() private fsCacheEnabled: boolean @@ -48,7 +36,6 @@ class ModuleFetcher { private resolver: VitestResolver, private config: ResolvedConfig, private fsCache: FileSystemModuleCache, - private clock: TransformClock, private tmpProjectDir: string, ) { this.fsCacheEnabled = config.fsModuleCache === true @@ -338,27 +325,21 @@ class ModuleFetcher { moduleGraphModule: EnvironmentModuleNode, options?: FetchFunctionOptions, ): Promise { - this.clock.transformStarted() - try { - const moduleRunnerModule = await fetchModule( - environment, - url, - importer, - { - ...options, - inlineSourceMap: false, - }, - ).catch(handleRollupError) - - const result: VitestFetchResult = processResultSource(environment, moduleRunnerModule) - if ('code' in result) { - result.moduleType = await this.cachedModuleType(result.file, result.code, moduleGraphModule.transformResult) - } - return result - } - finally { - this.clock.transformFinished() + const moduleRunnerModule = await fetchModule( + environment, + url, + importer, + { + ...options, + inlineSourceMap: false, + }, + ).catch(handleRollupError) + + const result: VitestFetchResult = processResultSource(environment, moduleRunnerModule) + if ('code' in result) { + result.moduleType = await this.cachedModuleType(result.file, result.code, moduleGraphModule.transformResult) } + return result } private sourceLoader(file: string | null): (() => Promise) | undefined { @@ -449,11 +430,10 @@ export function createFetchModuleFunction( resolver: VitestResolver, config: ResolvedConfig, fsCache: FileSystemModuleCache, - clock: TransformClock, traces: Traces, tmpProjectDir: string, ): VitestFetchFunction { - const fetcher = new ModuleFetcher(resolver, config, fsCache, clock, tmpProjectDir) + const fetcher = new ModuleFetcher(resolver, config, fsCache, tmpProjectDir) return async (url, importer, environment, cacheFs, options, otelCarrier) => { await traces.waitInit() const context = otelCarrier diff --git a/packages/vitest/src/node/pools/poolRunner.ts b/packages/vitest/src/node/pools/poolRunner.ts index 7f16cac6e..90b938cbe 100644 --- a/packages/vitest/src/node/pools/poolRunner.ts +++ b/packages/vitest/src/node/pools/poolRunner.ts @@ -184,6 +184,7 @@ export class PoolRunner { this._operationLock = createDefer() let startSpan: Span | undefined + const startedAt = performance.now() try { this._state = RunnerState.STARTING @@ -233,6 +234,12 @@ export class PoolRunner { await startPromise this._state = RunnerState.STARTED + + // record how long it took to spawn this worker, load its bundle and set up the + // environment, so the reporter can surface the cost of `isolate: true` + const { state } = this.project.vitest + state.startupTime += performance.now() - startedAt + state.workersSpawned += 1 } catch (error: any) { this._state = RunnerState.START_FAILURE diff --git a/packages/vitest/src/node/project.ts b/packages/vitest/src/node/project.ts index 4f29dfc6a..d0799003c 100644 --- a/packages/vitest/src/node/project.ts +++ b/packages/vitest/src/node/project.ts @@ -101,7 +101,6 @@ export class TestProject { this._resolver, this.config, this.vitest._fsCache, - this.vitest.state, this.vitest._traces, this.tmpDir, ) diff --git a/packages/vitest/src/node/reporters/base.ts b/packages/vitest/src/node/reporters/base.ts index 69fd00b35..9215e0bf1 100644 --- a/packages/vitest/src/node/reporters/base.ts +++ b/packages/vitest/src/node/reporters/base.ts @@ -6,15 +6,18 @@ import type { TestSpecification } from '../test-specification' import type { Reporter, TestRunEndReason } from '../types/reporter' import type { TestCase, TestCollection, TestModule, TestModuleState, TestResult, TestSuite, TestSuiteState } from './reported-tasks' import { readFileSync } from 'node:fs' +import { availableParallelism } from 'node:os' import { performance } from 'node:perf_hooks' import { toArray } from '@vitest/utils/helpers' import { parseStacktrace } from '@vitest/utils/source-map' import { relative } from 'pathe' import c from 'tinyrainbow' import { groupBy } from '../../utils/base' -import { isTTY } from '../../utils/env' +import { isCI, isTTY } from '../../utils/env' import { getSuites, getTestName, getTests, hasFailed, hasFailedSnapshot } from '../../utils/tasks' import { generateCodeFrame, printStack } from '../printError' +import { estimateModuleEvaluationSaving, getEnvironmentDiagnostics, getImportDiagnostics, getTransformDiagnostics, isSavingWorthHinting } from './diagnostics' +import { computeDurationBreakdown, formatDurationBreakdown } from './durationBreakdown' import { BENCH_TABLE_HEAD, computeBenchColumnWidths, padBenchRow, renderBenchmarkRow } from './renderers/benchmark-table' import { F_CHECK, F_DOWN_RIGHT, F_POINTER } from './renderers/figures' import { @@ -638,20 +641,15 @@ export abstract class BaseReporter implements Reporter { // Execution time is either sum of all runs of `--merge-reports` or the current run's time const executionTime = blobs?.executionTimes ? sum(blobs.executionTimes, time => time) : this.end - this.start - const environmentTime = sum(files, file => file.environmentLoad) - const transformTime = this.ctx.state.transformTime - const typecheck = sum(this.ctx.projects, project => project.typechecker?.getResult().time) - - const timers = [ - `transform ${formatTime(transformTime)}`, - `setup ${formatTime(setupTime)}`, - `import ${formatTime(collectTime)}`, - `tests ${formatTime(testsTime)}`, - `environment ${formatTime(environmentTime)}`, - typecheck && `typecheck ${formatTime(typecheck)}`, - ].filter(Boolean).join(', ') + const breakdown = computeDurationBreakdown({ + files, + typecheckTime: sum(this.ctx.projects, project => project.typechecker?.getResult().time), + }) - this.log(padSummaryTitle('Duration'), formatTime(executionTime) + c.dim(` (${timers})`)) + // percentages are relative to the sum of all tracked phases: phases run + // in parallel workers, so their sum is not comparable to the wall time + const timers = breakdown.total > 0 ? formatDurationBreakdown(breakdown) : '' + this.log(padSummaryTitle('Duration'), formatTime(executionTime) + (timers ? c.dim(` (${timers})`) : '')) if (blobs?.executionTimes) { this.log(padSummaryTitle('Per blob') + blobs.executionTimes.map(time => ` ${formatTime(time)}`).join('')) @@ -660,9 +658,336 @@ export abstract class BaseReporter implements Reporter { this.reportImportDurations() + // at most one hint per family: the environment hint is the most specific, + // the import hint explains the same `isolate` remedy through module data, + // and the transform hint (a cache, helping the *next* run) only speaks up + // when neither applies + const hinted = this.reportEnvironmentDiagnostic(files) + || this.reportImportDiagnostic(files) + || this.reportTransformDiagnostic(files) + if (!hinted) { + this.reportIsolateDiagnostic(files) + } + this.log() } + private getEffectiveMaxWorkers(): number { + const configured = this.ctx.config.maxWorkers + return typeof configured === 'number' && configured > 0 + ? configured + : Math.max(1, availableParallelism() - 1) + } + + /** + * Surfaces the cost of re-creating a DOM environment for every test file: + * with an isolating pool, `jsdom`/`happy-dom` are imported and set up once + * per file. When that repeated setup dominates the run, hint that a `vm` + * pool sets the environment up once per worker while keeping per-file + * isolation, and that `isolate: false` shares it across files. + */ + private reportEnvironmentDiagnostic(files: File[]): boolean { + // merged blob reports replay durations of past runs: no environments were + // created by this process + if (this.ctx.config.watch || this.ctx.state.blobs || !this.ctx.config.experimental.diagnostics.environment) { + return false + } + + const executionTime = this.end - this.start + const maxWorkers = this.getEffectiveMaxWorkers() + const inputs = this.ctx.projects.map((project) => { + const projectFiles = files.filter(file => (file.projectName || '') === project.name) + let environmentTime = 0 + let environmentCount = 0 + let trackedTime = 0 + for (const file of projectFiles) { + if (file.environmentLoad) { + environmentTime += file.environmentLoad + environmentCount++ + } + trackedTime += trackedFileTime(file) + } + return { + name: project.name, + environment: project.config.environment, + pool: project.config.pool, + isolate: project.config.isolate, + browser: project.config.browser.enabled, + poolProvided: project.config.providedOptions.pool, + isolateProvided: project.config.providedOptions.isolate, + environmentTime, + environmentCount, + trackedTime, + parallelism: Math.max(1, Math.min(environmentCount, maxWorkers)), + executionTime, + } + }) + + const diagnostics = getEnvironmentDiagnostics(inputs) + if (!diagnostics.length) { + return false + } + + for (const diagnostic of diagnostics) { + const project = this.ctx.projects.find(p => p.name === diagnostic.name) + this.log() + this.log( + padSummaryTitle('Environment'), + formatProjectName(project) + + c.yellow(`${diagnostic.environment} was created ${diagnostic.environmentCount} times`) + + c.dim(` · ${formatTime(diagnostic.environmentTime)} total, ${Math.round(diagnostic.share * 100)}% of tracked time`), + ) + const alternative = diagnostic.suggestIsolate + ? c.dim(' (keeps per-file isolation) or ') + c.yellow('isolate: false') + c.dim(' (shares it across files)') + : c.dim(' (keeps per-file isolation)') + this.log( + padSummaryTitle(''), + c.dim('create it once per worker with ') + + c.yellow(`pool: 'vmThreads'`) + + alternative, + ) + this.log( + padSummaryTitle(''), + c.dim('learn more: https://vitest.dev/guide/improving-performance#test-environments'), + ) + } + + return true + } + + /** + * Surfaces repeated evaluation of the same module graph: with `isolate: true` + * every test file re-imports its whole graph, so suites where files share + * most of their modules (typically through barrel files) pay the graph cost + * once per file. The duplication is measured from server-side fetch counts, + * so suites with disjoint per-file graphs stay quiet. + */ + private reportImportDiagnostic(files: File[]): boolean { + if (this.ctx.config.watch || this.ctx.state.blobs || !this.ctx.config.experimental.diagnostics.import) { + return false + } + + const executionTime = this.end - this.start + const maxWorkers = this.getEffectiveMaxWorkers() + const inputs = this.ctx.projects.map((project) => { + const projectFiles = files.filter(file => (file.projectName || '') === project.name) + let importTime = 0 + let trackedTime = 0 + for (const file of projectFiles) { + // the transform wait is subtracted because `isolate: false` only avoids + // re-evaluating modules, the server transforms each of them once either way + importTime += Math.max((file.collectDuration || 0) - (file.collectFetchDuration || 0), 0) + trackedTime += trackedFileTime(file) + } + const durations = this.ctx.state.metadata[project.name]?.duration + return { + name: project.name, + pool: project.config.pool, + isolate: project.config.isolate, + browser: project.config.browser.enabled, + isolateProvided: project.config.providedOptions.isolate, + importTime, + trackedTime, + fetchCounts: durations ? Object.values(durations).map(times => times.length) : [], + fileCount: projectFiles.length, + parallelism: Math.max(1, Math.min(projectFiles.length, maxWorkers)), + executionTime, + } + }) + + const diagnostics = getImportDiagnostics(inputs) + if (!diagnostics.length) { + return false + } + + for (const diagnostic of diagnostics) { + const project = this.ctx.projects.find(p => p.name === diagnostic.name) + this.log() + this.log( + padSummaryTitle('Import'), + formatProjectName(project) + + c.yellow(`${diagnostic.uniqueModules} modules were evaluated ${diagnostic.totalFetches} times`) + + c.dim(` · ${formatTime(diagnostic.importTime)} total, ${Math.round(diagnostic.share * 100)}% of tracked time`), + ) + this.log( + padSummaryTitle(''), + c.dim(`~${formatTime(diagnostic.estimatedSaving)} faster with `) + + c.yellow('isolate: false') + + c.dim(' — shared modules are evaluated once per worker instead of once per file'), + ) + this.log( + padSummaryTitle(''), + c.dim('learn more: https://vitest.dev/guide/improving-performance#test-isolation'), + ) + } + + return true + } + + /** + * Surfaces transform-dominated runs: without the fs module cache every + * `vitest run` transforms the whole module graph from scratch. Enabling + * `fsModuleCache` persists the results so the next run skips them. + */ + private reportTransformDiagnostic(files: File[]): boolean { + if (this.ctx.config.watch || this.ctx.state.blobs || !this.ctx.config.experimental.diagnostics.transform) { + return false + } + + const executionTime = this.end - this.start + const inputs = this.ctx.projects.map((project) => { + const projectFiles = files.filter(file => (file.projectName || '') === project.name) + let transformTime = 0 + let trackedTime = 0 + for (const file of projectFiles) { + transformTime += (file.setupFetchDuration || 0) + (file.collectFetchDuration || 0) + trackedTime += trackedFileTime(file) + } + return { + name: project.name, + transformTime, + trackedTime, + fsModuleCache: project.config.fsModuleCache === true, + fsModuleCacheProvided: project.config.providedOptions.fsModuleCache, + executionTime, + } + }) + + const diagnostics = getTransformDiagnostics(inputs) + if (!diagnostics.length) { + return false + } + + for (const diagnostic of diagnostics) { + const project = this.ctx.projects.find(p => p.name === diagnostic.name) + this.log() + this.log( + padSummaryTitle('Transform'), + formatProjectName(project) + + c.yellow(`transforming modules took ${formatTime(diagnostic.transformTime)}`) + + c.dim(` · ${Math.round(diagnostic.share * 100)}% of tracked time, re-done on every run`), + ) + this.log( + padSummaryTitle(''), + c.dim('persist transforms across runs with ') + + c.yellow('fsModuleCache: true'), + ) + if (isCI) { + this.log( + padSummaryTitle(''), + c.dim('on CI this only helps when the cache directory is persisted between runs'), + ) + } + this.log( + padSummaryTitle(''), + c.dim('learn more: https://vitest.dev/guide/improving-performance#caching-between-reruns'), + ) + } + + return true + } + + /** + * Surfaces the cost of `isolate: true`: with isolation enabled Vitest spawns a + * fresh worker (and re-creates the test environment) for every test file. When + * that repeated startup cost is significant, hint that `isolate: false` would + * reuse workers across files. + */ + private reportIsolateDiagnostic(files: File[]): void { + // opt-out via `experimental.diagnostics.isolate`; the timers it relies on + // are only shown for a full (non-watch) run + if (this.ctx.config.watch || !this.ctx.config.experimental.diagnostics.isolate) { + return + } + + const state = this.ctx.state + const numWorkers = state.workersSpawned + // only meaningful when at least one non-browser project isolates workers + // without the user having explicitly chosen isolation + const isolates = this.ctx.projects.some( + project => project.config.isolate + && !project.config.browser.enabled + && !project.config.providedOptions.isolate, + ) + if (!numWorkers || !isolates) { + return + } + + const numFiles = files.length + // `startupTime` is the summed (across workers) time spent spawning the worker, + // loading its bundle and setting up the environment. The environment setup is + // already part of this window, so it is not added separately. + const startupTime = state.startupTime + const avgStartup = startupTime / numWorkers + + // with `isolate: false` the same files would run in ~`parallelism` reused + // workers instead of spawning a fresh worker for every file + const parallelism = Math.max(1, Math.min(numFiles, this.getEffectiveMaxWorkers())) + + // nothing was actually spawned per-file (e.g. a single worker handled everything) + if (numWorkers <= parallelism) { + return + } + + // Spawns are spread across ~`parallelism` lanes, so the wall-clock cost is the + // summed startup divided by parallelism. Reusing workers leaves ~1 spawn per + // lane, so the reducible wall-clock time is the rest. + const wallStartup = startupTime / parallelism + + // Reused workers also keep evaluated modules alive, so every module a later + // file would re-evaluate is saved as well. Per-module evaluation times are + // only collected when `experimental.importDurations` is enabled — without + // them the spawn saving is reported as a lower bound ("at least"). + const measuresModules = this.ctx.config.experimental.importDurations.limit > 0 + let moduleSavings = 0 + if (measuresModules) { + // vm pools re-create the module graph per VM context regardless of + // `isolate`, so only files of `forks`/`threads` projects count + const eligibleProjects = new Set(this.ctx.projects + .filter(project => (project.config.pool === 'forks' || project.config.pool === 'threads') + && project.config.isolate + && !project.config.browser.enabled + && !project.config.providedOptions.isolate) + .map(project => project.name)) + const moduleSelfTimes = new Map() + for (const file of files) { + if (!eligibleProjects.has(file.projectName || '') || !file.importDurations) { + continue + } + for (const moduleId in file.importDurations) { + let times = moduleSelfTimes.get(moduleId) + if (!times) { + times = [] + moduleSelfTimes.set(moduleId, times) + } + times.push(file.importDurations[moduleId].selfTime) + } + } + moduleSavings = estimateModuleEvaluationSaving(moduleSelfTimes.values(), parallelism) + } + + const estimatedSavings = wallStartup - avgStartup + moduleSavings + + if (!isSavingWorthHinting(estimatedSavings, this.end - this.start)) { + return + } + + this.log() + this.log( + padSummaryTitle('Isolate'), + c.yellow(`${numWorkers} workers spawned`) + + c.dim(` · ~${formatTime(avgStartup)} startup each (spawn + environment, per file)`), + ) + this.log( + padSummaryTitle(''), + c.dim(`${measuresModules ? '' : 'at least '}~${formatTime(estimatedSavings)} faster with `) + + c.yellow('isolate: false') + + c.dim(measuresModules + ? ' — reuses workers across files and evaluates shared modules once per worker' + : ' — reuses workers across files instead of one per file'), + ) + } + private reportImportDurations() { const { print, failOnDanger, thresholds } = this.ctx.config.experimental.importDurations if (!print && !failOnDanger) { @@ -1093,6 +1418,18 @@ function sum(items: T[], cb: (_next: T) => number | undefined) { }, 0) } +/** + * Summed time of all tracked phases of a file. The transform wait is part of + * `setupDuration`/`collectDuration`, so it is not added separately. + */ +function trackedFileTime(file: File): number { + return (file.environmentLoad || 0) + + (file.setupDuration || 0) + + (file.collectDuration || 0) + + (file.prepareDuration || 0) + + (file.result?.duration || 0) +} + function getIndentation(suite: Task, level = 1): number { if (suite.suite && !('filepath' in suite.suite)) { return getIndentation(suite.suite, level + 1) diff --git a/packages/vitest/src/node/reporters/blob.ts b/packages/vitest/src/node/reporters/blob.ts index d62d98d52..09f635732 100644 --- a/packages/vitest/src/node/reporters/blob.ts +++ b/packages/vitest/src/node/reporters/blob.ts @@ -76,7 +76,6 @@ export class BlobReporter implements Reporter { coverage, executionTime, environmentModules, - this.ctx.state.transformTime, ] satisfies MergeReport) let outputFile = this.options.outputFile ?? getOutputFile(this.ctx.config, 'blob') @@ -128,7 +127,7 @@ export async function readBlobs( ) } const content = await readFile(fullPath, 'utf-8') - const [version, files, errors, coverage, executionTime, environmentModules, transformTime] = parse( + const [version, files, errors, coverage, executionTime, environmentModules] = parse( content, ) as MergeReport if (!version) { @@ -136,7 +135,7 @@ export async function readBlobs( `vitest.mergeReports() expects all paths in "${blobsDirectory}" to be files generated by the blob reporter, but "${filename}" is not a valid blob file`, ) } - return { version, files, errors, coverage, file: filename, executionTime, environmentModules, transformTime } + return { version, files, errors, coverage, file: filename, executionTime, environmentModules } }) const blobs = await Promise.all(promises) @@ -192,14 +191,12 @@ export async function readBlobs( const errors = blobs.flatMap(blob => blob.errors) const coverages = blobs.map(blob => blob.coverage) const executionTimes = blobs.map(blob => blob.executionTime) - const transformTimes = blobs.map(blob => blob.transformTime) return { files, errors, coverages, executionTimes, - transformTimes, } } @@ -208,7 +205,6 @@ export interface MergedBlobs { errors: unknown[] coverages: unknown[] executionTimes: number[] - transformTimes: number[] } export type MergeReport = [ @@ -218,7 +214,6 @@ export type MergeReport = [ coverage: unknown, executionTime: number, environmentModules: MergeReportEnvironmentModules, - transformTime: number, ] interface MergeReportEnvironmentModules { diff --git a/packages/vitest/src/node/reporters/diagnostics.ts b/packages/vitest/src/node/reporters/diagnostics.ts new file mode 100644 index 000000000..c3136f094 --- /dev/null +++ b/packages/vitest/src/node/reporters/diagnostics.ts @@ -0,0 +1,288 @@ +const DOM_ENVIRONMENTS = new Set(['jsdom', 'happy-dom']) + +/** Minimum summed environment setup time before the hint is worth printing. */ +const MIN_ENVIRONMENT_TIME = 2_000 +/** Minimum share of the project's tracked time spent setting up environments. */ +const MIN_ENVIRONMENT_SHARE = 0.25 + +/** + * A hint has to be worth acting on: the estimated saving must be noticeable. + * Run-to-run noise of real suites is commonly a few percent, so anything below + * ~5% of the wall time cannot even be confirmed by trying the change - except + * on long runs, where 10 seconds is worth attention regardless of percentage. + */ +export function isSavingWorthHinting(saving: number, executionTime: number): boolean { + if (saving < 250) { + return false + } + return saving >= executionTime * 0.05 || saving >= 10_000 +} + +export interface EnvironmentDiagnosticInput { + name: string + environment: string + pool: string + isolate: boolean + browser: boolean + /** The user explicitly configured the pool, so don't suggest changing it. */ + poolProvided: boolean + /** The user explicitly configured isolation, so don't suggest disabling it. */ + isolateProvided: boolean + /** Summed time spent creating the environment, across all files. */ + environmentTime: number + /** Number of files that created an environment. */ + environmentCount: number + /** Summed time of all tracked phases of this project. */ + trackedTime: number + /** How many workers the environment setups were spread across. */ + parallelism: number + /** Wall time of the whole run. */ + executionTime: number +} + +export interface EnvironmentDiagnostic { + name: string + environment: string + environmentTime: number + environmentCount: number + /** Share of the project's tracked time, 0-1. */ + share: number + /** Whether suggesting `isolate: false` is appropriate. */ + suggestIsolate: boolean +} + +/** Minimum summed import time before the hint is worth printing. */ +const MIN_IMPORT_TIME = 2_000 +/** Minimum share of the project's tracked time spent importing modules. */ +const MIN_IMPORT_SHARE = 0.25 +/** + * Minimum fraction of module fetches that re-evaluate an already evaluated + * module. Below this the test files import mostly disjoint graphs and + * reusing workers would not meaningfully reduce the import work. + */ +const MIN_IMPORT_DUPLICATION = 0.2 + +export interface ImportDiagnosticInput { + name: string + pool: string + isolate: boolean + browser: boolean + /** The user explicitly configured isolation, so don't suggest disabling it. */ + isolateProvided: boolean + /** Summed time spent importing test files and their module graphs. */ + importTime: number + /** Summed time of all tracked phases of this project. */ + trackedTime: number + /** + * How many times each module was served to a worker. With `isolate: true` + * every test file re-fetches (and re-evaluates) its whole module graph, so + * counts above the worker parallelism are repeated evaluations of the same + * module that `isolate: false` would avoid. + */ + fetchCounts: number[] + fileCount: number + /** How many workers the imports were spread across. */ + parallelism: number + /** Wall time of the whole run. */ + executionTime: number +} + +export interface ImportDiagnostic { + name: string + importTime: number + /** Share of the project's tracked time, 0-1. */ + share: number + totalFetches: number + uniqueModules: number + /** Fraction of fetches that re-evaluated an already evaluated module, 0-1. */ + duplication: number + /** Estimated wall-clock saving of `isolate: false`. */ + estimatedSaving: number +} + +/** + * Detects projects where test files repeatedly evaluate the same module + * graph. Typical for barrel-file imports: every test file pulls hundreds of + * shared modules to use a few of them, and `isolate: true` re-evaluates that + * graph for every file. The duplication is measured from the server-side + * fetch counts, so suites with disjoint per-file graphs - where reusing + * workers would not help - stay quiet. + */ +export function getImportDiagnostics( + projects: ImportDiagnosticInput[], +): ImportDiagnostic[] { + const diagnostics: ImportDiagnostic[] = [] + for (const project of projects) { + if ( + // vm pools re-create the module graph per VM context regardless of + // `isolate`, so reusing workers would not reduce the import work + (project.pool !== 'forks' && project.pool !== 'threads') + || !project.isolate + || project.isolateProvided + || project.browser + || project.fileCount <= project.parallelism + || project.importTime < MIN_IMPORT_TIME + || project.trackedTime <= 0 + || project.importTime / project.trackedTime < MIN_IMPORT_SHARE + ) { + continue + } + const parallelism = Math.max(1, project.parallelism) + let totalFetches = 0 + let avoidableFetches = 0 + for (const count of project.fetchCounts) { + totalFetches += count + // reused workers still fetch a module once per lane that needs it + avoidableFetches += Math.max(0, count - parallelism) + } + if (totalFetches === 0) { + continue + } + const duplication = avoidableFetches / totalFetches + if (duplication < MIN_IMPORT_DUPLICATION) { + continue + } + // imports are spread across the worker lanes, so the reducible wall time + // is the duplicated share of the summed import time divided by lanes + const estimatedSaving = (project.importTime * duplication) / parallelism + if (!isSavingWorthHinting(estimatedSaving, project.executionTime)) { + continue + } + diagnostics.push({ + name: project.name, + importTime: project.importTime, + share: project.importTime / project.trackedTime, + totalFetches, + uniqueModules: project.fetchCounts.length, + duplication, + estimatedSaving, + }) + } + return diagnostics +} + +/** + * Estimates the wall-clock time saved by evaluating shared modules once per + * worker instead of once per test file. `moduleSelfTimes` holds, per module, + * the module's own evaluation time in every test file that evaluated it. + * Reused workers keep ~`parallelism` evaluations of each module (one per + * lane); the rest of the summed time is avoidable and spread across the + * lanes. + */ +export function estimateModuleEvaluationSaving( + moduleSelfTimes: Iterable, + parallelism: number, +): number { + const lanes = Math.max(1, parallelism) + let avoidable = 0 + for (const times of moduleSelfTimes) { + if (times.length <= lanes) { + continue + } + let sum = 0 + for (const time of times) { + sum += time + } + avoidable += (sum * (times.length - lanes)) / times.length + } + return avoidable / lanes +} + +/** Minimum summed transform time before the hint is worth printing. */ +const MIN_TRANSFORM_TIME = 2_000 +/** Minimum share of the project's tracked time spent transforming modules. */ +const MIN_TRANSFORM_SHARE = 0.25 + +export interface TransformDiagnosticInput { + name: string + /** Summed time spent transforming and serving modules. */ + transformTime: number + /** Summed time of all tracked phases of this project. */ + trackedTime: number + /** The fs module cache is already enabled - transforms persist across runs. */ + fsModuleCache: boolean + /** The user explicitly configured the cache, so don't suggest enabling it. */ + fsModuleCacheProvided: boolean + /** Wall time of the whole run. */ + executionTime: number +} + +export interface TransformDiagnostic { + name: string + transformTime: number + /** Share of the project's tracked time, 0-1. */ + share: number +} + +/** + * Detects projects that spend the run transforming modules. Without the fs + * module cache every `vitest run` starts from scratch and transforms the + * whole module graph again; `fsModuleCache` persists the results on disk so + * repeated runs skip them. + */ +export function getTransformDiagnostics( + projects: TransformDiagnosticInput[], +): TransformDiagnostic[] { + return projects + .filter((project) => { + if ( + project.fsModuleCache + || project.fsModuleCacheProvided + || project.transformTime < MIN_TRANSFORM_TIME + || project.trackedTime <= 0 + || project.transformTime / project.trackedTime < MIN_TRANSFORM_SHARE + ) { + return false + } + // the next run skips the persisted transforms, so the (mostly serial, + // main-thread) transform time itself bounds the saving + return isSavingWorthHinting(project.transformTime, project.executionTime) + }) + .map(project => ({ + name: project.name, + transformTime: project.transformTime, + share: project.transformTime / project.trackedTime, + })) +} + +/** + * Detects projects where re-creating a DOM environment for every test file + * dominates the run. With an isolating pool the environment is set up once + * per file; `vmThreads`/`vmForks` set it up once per worker while still + * giving every file a fresh VM context. + */ +export function getEnvironmentDiagnostics( + projects: EnvironmentDiagnosticInput[], +): EnvironmentDiagnostic[] { + return projects + .filter((project) => { + if ( + !DOM_ENVIRONMENTS.has(project.environment) + || (project.pool !== 'forks' && project.pool !== 'threads') + || !project.isolate + || project.browser + || project.poolProvided + || project.environmentCount <= 1 + || project.environmentTime < MIN_ENVIRONMENT_TIME + || project.trackedTime <= 0 + || project.environmentTime / project.trackedTime < MIN_ENVIRONMENT_SHARE + ) { + return false + } + // setups are spread across the worker lanes; a vm pool would still pay + // one setup per lane, so the reducible wall time is the rest + const parallelism = Math.max(1, project.parallelism) + const saving + = project.environmentTime / parallelism + - project.environmentTime / project.environmentCount + return isSavingWorthHinting(saving, project.executionTime) + }) + .map(project => ({ + name: project.name, + environment: project.environment, + environmentTime: project.environmentTime, + environmentCount: project.environmentCount, + share: project.environmentTime / project.trackedTime, + suggestIsolate: !project.isolateProvided, + })) +} diff --git a/packages/vitest/src/node/reporters/durationBreakdown.ts b/packages/vitest/src/node/reporters/durationBreakdown.ts new file mode 100644 index 000000000..7d65912fc --- /dev/null +++ b/packages/vitest/src/node/reporters/durationBreakdown.ts @@ -0,0 +1,72 @@ +import type { File } from '../../runtime/runner/types' + +export interface DurationPhase { + name: string + time: number + /** Share of the tracked time, in percent (0-100). */ + percent: number +} + +export interface DurationBreakdown { + /** Summed time of all tracked phases. */ + total: number + /** Phases sorted by time, descending. Phases below half a percent are dropped. */ + phases: DurationPhase[] +} + +export interface DurationBreakdownInput { + files: File[] + /** Total typecheck time across all projects. */ + typecheckTime: number +} + +export function computeDurationBreakdown( + input: DurationBreakdownInput, +): DurationBreakdown { + const sums = { + transform: 0, + setup: 0, + import: 0, + tests: 0, + environment: 0, + worker: 0, + typecheck: input.typecheckTime, + } + for (const file of input.files) { + // setup and collect wall times include the time the worker spent waiting + // for module transforms; report that wait as its own "transform" phase so + // every phase is a disjoint sum of per-worker time + const setupFetch = file.setupFetchDuration || 0 + const collectFetch = file.collectFetchDuration || 0 + sums.transform += setupFetch + collectFetch + sums.setup += Math.max((file.setupDuration || 0) - setupFetch, 0) + sums.import += Math.max((file.collectDuration || 0) - collectFetch, 0) + sums.tests += file.result?.duration || 0 + sums.environment += file.environmentLoad || 0 + sums.worker += file.prepareDuration || 0 + } + + const entries = Object.entries(sums) + const total = entries.reduce((acc, [, time]) => acc + time, 0) + const phases = entries + .map(([name, time]) => ({ + name, + time, + percent: total > 0 ? (time / total) * 100 : 0, + })) + .filter(phase => phase.percent >= 0.5) + .sort((a, b) => b.time - a.time) + + return { total, phases } +} + +export function formatDurationBreakdown(breakdown: DurationBreakdown): string { + return breakdown.phases + .map(phase => `${phase.name} ${formatPercent(phase.percent)}`) + .join(', ') +} + +function formatPercent(percent: number): string { + // sub-1% shares round to "1%" instead of a misleading "0%" + return `${Math.max(1, Math.round(percent))}%` +} diff --git a/packages/vitest/src/node/state.ts b/packages/vitest/src/node/state.ts index fdb9296cf..f9eddaeac 100644 --- a/packages/vitest/src/node/state.ts +++ b/packages/vitest/src/node/state.ts @@ -1,6 +1,5 @@ import type { File, FileSpecification, Task, TaskResultPack } from '../runtime/runner/types' import type { AsyncLeak, UserConsoleLog } from '../types/general' -import type { TransformClock } from './environments/fetchModule' import type { TestProject } from './project' import type { MergedBlobs } from './reporters/blob' import type { OnUnhandledErrorCallback } from './types/config' @@ -16,7 +15,7 @@ function isAggregateError(err: unknown): err is AggregateError { return err instanceof Error && 'errors' in err } -export class StateManager implements TransformClock { +export class StateManager { filesMap: Map = new Map() pathsSet: Set = new Set() idMap: Map = new Map() @@ -26,28 +25,13 @@ export class StateManager implements TransformClock { reportedTasksMap: WeakMap = new WeakMap() blobs?: MergedBlobs /** - * Wall time during which the server's module transform pipeline was busy, - * measured as the union of in-flight fetch intervals. Individual fetch - * durations cannot be summed instead: concurrent fetches (parallel workers, - * the vm pool graph prewarm) all wait on the same deduplicated in-flight - * transforms, so per-caller wall times overcount the actual work by orders - * of magnitude. + * Total time spent starting test workers (spawning the process/thread, loading + * the worker bundle and setting up the test environment). Used to surface the + * cost of `isolate: true`, which spawns a fresh worker per test file. */ - transformTime = 0 - private _transformsInflight = 0 - private _transformsBusyStart = 0 - - transformStarted(): void { - if (this._transformsInflight++ === 0) { - this._transformsBusyStart = performance.now() - } - } - - transformFinished(): void { - if (--this._transformsInflight === 0) { - this.transformTime += performance.now() - this._transformsBusyStart - } - } + startupTime = 0 + /** Number of test workers that were started during the run. */ + workersSpawned = 0 metadata: Record diff --git a/packages/vitest/src/node/types/config.ts b/packages/vitest/src/node/types/config.ts index 7c1128812..09da4d63e 100644 --- a/packages/vitest/src/node/types/config.ts +++ b/packages/vitest/src/node/types/config.ts @@ -1013,6 +1013,35 @@ export interface InlineConfig { * This will apply `.only` flag and test name pattern across all files without running them. */ preParse?: boolean + + /** + * Print performance hints after the run when the collected timings show + * that a configuration change would make the run significantly faster. + * Hints are never printed for options that were set explicitly. + * + * Set to `false` to disable all hints, or disable them individually: + * - `isolate`: hint when `isolate: true` spends a significant amount of + * time spawning a fresh worker (and re-creating the environment) for + * every test file, estimating how much `isolate: false` could save. + * - `environment`: hint when re-creating a DOM environment for every test + * file dominates the run and a `vm` pool would set it up once per worker. + * - `import`: hint when test files repeatedly evaluate the same module + * graph (typical for barrel-file imports) and `isolate: false` would + * evaluate it once per worker. + * - `transform`: hint when transforming modules dominates the run and + * `fsModuleCache` would persist the results across runs. + * @default true + */ + diagnostics?: boolean | { + /** @default true */ + isolate?: boolean + /** @default true */ + environment?: boolean + /** @default true */ + import?: boolean + /** @default true */ + transform?: boolean + } } /** @@ -1269,7 +1298,7 @@ export interface ResolvedConfig tagsFilter?: string[] mergeReportsLabel?: string - experimental: Omit['experimental'], 'importDurations'> & { + experimental: Omit['experimental'], 'importDurations' | 'diagnostics'> & { importDurations: { print: boolean | 'on-warn' limit: number @@ -1279,6 +1308,25 @@ export interface ResolvedConfig danger: number } } + diagnostics: { + isolate: boolean + environment: boolean + import: boolean + transform: boolean + } + } + + /** + * Options that were explicitly provided by the user, as opposed to resolved + * defaults. Used by diagnostics to avoid suggesting changes to options the + * user chose deliberately. + * @internal + */ + providedOptions: { + pool: boolean + isolate: boolean + environment: boolean + fsModuleCache: boolean } cliOptions: CliOptions diff --git a/packages/vitest/src/runtime/moduleRunner/startVitestModuleRunner.ts b/packages/vitest/src/runtime/moduleRunner/startVitestModuleRunner.ts index f9ae4d98c..e3d8543b0 100644 --- a/packages/vitest/src/runtime/moduleRunner/startVitestModuleRunner.ts +++ b/packages/vitest/src/runtime/moduleRunner/startVitestModuleRunner.ts @@ -43,6 +43,25 @@ export function startVitestModuleRunner(options: ContextModuleRunnerOptions): Vi getSafeWorkerState() || options.state const rpc = () => state().rpc + // Wall time the worker spends blocked on server round-trips, measured as the + // union of in-flight intervals: sibling imports await fetches concurrently, + // so summing individual call durations would overcount the blocked time. + let fetchesInflight = 0 + let fetchesBusyStart = 0 + async function trackFetchTime(fetchPromise: Promise): Promise { + if (fetchesInflight++ === 0) { + fetchesBusyStart = performance.now() + } + try { + return await fetchPromise + } + finally { + if (--fetchesInflight === 0) { + state().durations.fetch += performance.now() - fetchesBusyStart + } + } + } + const environment = () => { const environment = state().environment return environment.viteEnvironment || environment.name @@ -173,7 +192,7 @@ export function startVitestModuleRunner(options: ContextModuleRunnerOptions): Vi // its import graph is connected on the server, so the snapshot // actually covers the file's transitive dependencies if (importer != null) { - const warm = await fetchWarmModules() + const warm = await trackFetchTime(fetchWarmModules()) // the null prototype is not preserved by the IPC serialization, so // ids like "constructor" must not fall through to Object.prototype const warmResult = warm && ( @@ -200,13 +219,13 @@ export function startVitestModuleRunner(options: ContextModuleRunnerOptions): Vi } const otelCarrier = traces?.getContextCarrier() - const result = await rpc().fetch( + const result = await trackFetchTime(rpc().fetch( id, importer, environment(), options, otelCarrier, - ) + )) if ('cached' in result) { const code = readFileSync(result.tmp, 'utf-8') return { code, ...result } diff --git a/packages/vitest/src/runtime/runVmTests.ts b/packages/vitest/src/runtime/runVmTests.ts index 707c0608d..0725f23a7 100644 --- a/packages/vitest/src/runtime/runVmTests.ts +++ b/packages/vitest/src/runtime/runVmTests.ts @@ -89,8 +89,11 @@ export async function run( testRunner.cancel?.(reason) }) + // unlike other pools, the vm pool creates the environment inside the + // prepare window; subtract it so `prepare` excludes the environment + // load time in every pool workerState.durations.prepare - = performance.now() - workerState.durations.prepare + = performance.now() - workerState.durations.prepare - workerState.durations.environment const { vi } = VitestIndex diff --git a/packages/vitest/src/runtime/runner/collect.ts b/packages/vitest/src/runtime/runner/collect.ts index de639f27a..6f9635992 100644 --- a/packages/vitest/src/runtime/runner/collect.ts +++ b/packages/vitest/src/runtime/runner/collect.ts @@ -64,6 +64,7 @@ export async function collectTests( clearCollectorContext(file, runner) const setupFiles = toArray(config.setupFiles) + const fetchBeforeSetup = runner.getModuleFetchDuration?.() if (setupFiles.length) { const setupStart = now() await runSetupFiles(config, setupFiles, runner) @@ -74,6 +75,11 @@ export async function collectTests( file.setupDuration = 0 } + const fetchBeforeCollect = runner.getModuleFetchDuration?.() + if (fetchBeforeSetup != null && fetchBeforeCollect != null) { + file.setupFetchDuration = fetchBeforeCollect - fetchBeforeSetup + } + const collectStart = now() await runner.importFile(filepath, 'collect') @@ -107,6 +113,10 @@ export async function collectTests( setHooks(file, fileHooks) file.collectDuration = now() - collectStart + const fetchAfterCollect = runner.getModuleFetchDuration?.() + if (fetchBeforeCollect != null && fetchAfterCollect != null) { + file.collectFetchDuration = fetchAfterCollect - fetchBeforeCollect + } } catch (e) { const errors = e instanceof AggregateError diff --git a/packages/vitest/src/runtime/runner/types.ts b/packages/vitest/src/runtime/runner/types.ts index fe12518fd..dcd3f976b 100644 --- a/packages/vitest/src/runtime/runner/types.ts +++ b/packages/vitest/src/runtime/runner/types.ts @@ -326,10 +326,20 @@ export interface File extends Suite { * This time also includes importing all the file dependencies. */ collectDuration?: number + /** + * The portion of `collectDuration` the worker spent waiting for the server + * to resolve and transform modules. + */ + collectFetchDuration?: number /** * The time it took to import the setup file. */ setupDuration?: number + /** + * The portion of `setupDuration` the worker spent waiting for the server + * to resolve and transform modules. + */ + setupFetchDuration?: number /** * Whether the file is initiated without running any tests. * This is done to populate state on the server side by Vitest. @@ -1729,6 +1739,12 @@ export interface VitestRunner { * Gets the time spent importing each individual non-externalized file that Vitest collected. */ getImportDurations?: () => Record + /** + * Gets the cumulative time the worker has spent waiting for the server to + * resolve and transform modules. Used to attribute the transform wait to the + * setup and collect phases. + */ + getModuleFetchDuration?: () => number /** * Publicly available configuration. */ diff --git a/packages/vitest/src/runtime/runners/test.ts b/packages/vitest/src/runtime/runners/test.ts index 19a833897..0a3f06b53 100644 --- a/packages/vitest/src/runtime/runners/test.ts +++ b/packages/vitest/src/runtime/runners/test.ts @@ -281,6 +281,10 @@ export class TestRunner implements VitestTestRunner { return importDurations } + getModuleFetchDuration(): number { + return this.workerState.durations.fetch + } + trace = (name: string, attributes: Record | (() => T), cb?: () => T): T => { const options: SpanOptions = typeof attributes === 'object' ? { attributes } : {} return this._otel.$(`vitest.test.runner.${name}`, options, cb || attributes as () => T) diff --git a/packages/vitest/src/runtime/worker.ts b/packages/vitest/src/runtime/worker.ts index 16b3fb177..483e2b401 100644 --- a/packages/vitest/src/runtime/worker.ts +++ b/packages/vitest/src/runtime/worker.ts @@ -39,6 +39,7 @@ async function execute(method: 'run' | 'collect', ctx: ContextRPC, worker: Vites durations: { environment: 0, prepare: prepareStart, + fetch: 0, }, rpc, onCancel, diff --git a/packages/vitest/src/types/worker.ts b/packages/vitest/src/types/worker.ts index 1fce11fcc..53a511529 100644 --- a/packages/vitest/src/types/worker.ts +++ b/packages/vitest/src/types/worker.ts @@ -87,6 +87,11 @@ export interface WorkerGlobalState { durations: { environment: number prepare: number + /** + * Wall time the worker spent blocked on module fetch requests to the + * server, measured as the union of in-flight intervals. + */ + fetch: number } onFilterStackTrace?: (trace: string) => string } diff --git a/test/e2e/fixtures/doctor-failing/ok.test.ts b/test/e2e/fixtures/doctor-failing/ok.test.ts new file mode 100644 index 000000000..8110f7561 --- /dev/null +++ b/test/e2e/fixtures/doctor-failing/ok.test.ts @@ -0,0 +1,5 @@ +import { expect, test } from 'vitest' + +test('adds', () => { + expect(1 + 1).toBe(2) +}) diff --git a/test/e2e/fixtures/doctor-failing/vitest.config.ts b/test/e2e/fixtures/doctor-failing/vitest.config.ts new file mode 100644 index 000000000..a75f88493 --- /dev/null +++ b/test/e2e/fixtures/doctor-failing/vitest.config.ts @@ -0,0 +1,8 @@ +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + environment: 'jsdom', + watch: false, + }, +}) diff --git a/test/e2e/fixtures/doctor-failing/vm-hostile.test.ts b/test/e2e/fixtures/doctor-failing/vm-hostile.test.ts new file mode 100644 index 000000000..5ed1bfd08 --- /dev/null +++ b/test/e2e/fixtures/doctor-failing/vm-hostile.test.ts @@ -0,0 +1,6 @@ +import { expect, test } from 'vitest' + +// fails only under vm pools, so `vitest doctor` has a failing candidate to report +test('does not run under a vm pool', () => { + expect(process.execArgv.join(' ')).not.toContain('experimental-vm-modules') +}) diff --git a/test/e2e/fixtures/doctor-projects/dom.test.ts b/test/e2e/fixtures/doctor-projects/dom.test.ts new file mode 100644 index 000000000..fde83aa9e --- /dev/null +++ b/test/e2e/fixtures/doctor-projects/dom.test.ts @@ -0,0 +1,5 @@ +import { expect, test } from 'vitest' + +test('runs in a DOM environment', () => { + expect(typeof document).toBe('object') +}) diff --git a/test/e2e/fixtures/doctor-projects/node.test.ts b/test/e2e/fixtures/doctor-projects/node.test.ts new file mode 100644 index 000000000..5e39fcc84 --- /dev/null +++ b/test/e2e/fixtures/doctor-projects/node.test.ts @@ -0,0 +1,6 @@ +import { expect, test } from 'vitest' + +// fails if the doctor environment swap leaks beyond the jsdom project +test('keeps the node environment', () => { + expect(typeof document).toBe('undefined') +}) diff --git a/test/e2e/fixtures/doctor-projects/vitest.config.ts b/test/e2e/fixtures/doctor-projects/vitest.config.ts new file mode 100644 index 000000000..427082e11 --- /dev/null +++ b/test/e2e/fixtures/doctor-projects/vitest.config.ts @@ -0,0 +1,28 @@ +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + watch: false, + fsModuleCache: true, + projects: [ + { + test: { + name: 'dom', + environment: 'jsdom', + pool: 'threads', + isolate: false, + include: ['dom.test.ts'], + }, + }, + { + test: { + name: 'node', + environment: 'node', + pool: 'threads', + isolate: false, + include: ['node.test.ts'], + }, + }, + ], + }, +}) diff --git a/test/e2e/fixtures/doctor/basic-1.test.ts b/test/e2e/fixtures/doctor/basic-1.test.ts new file mode 100644 index 000000000..8110f7561 --- /dev/null +++ b/test/e2e/fixtures/doctor/basic-1.test.ts @@ -0,0 +1,5 @@ +import { expect, test } from 'vitest' + +test('adds', () => { + expect(1 + 1).toBe(2) +}) diff --git a/test/e2e/fixtures/doctor/basic-2.test.ts b/test/e2e/fixtures/doctor/basic-2.test.ts new file mode 100644 index 000000000..58ed617e5 --- /dev/null +++ b/test/e2e/fixtures/doctor/basic-2.test.ts @@ -0,0 +1,5 @@ +import { expect, test } from 'vitest' + +test('multiplies', () => { + expect(2 * 2).toBe(4) +}) diff --git a/test/e2e/fixtures/doctor/vitest.config.ts b/test/e2e/fixtures/doctor/vitest.config.ts new file mode 100644 index 000000000..2f35653f1 --- /dev/null +++ b/test/e2e/fixtures/doctor/vitest.config.ts @@ -0,0 +1,7 @@ +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + watch: false, + }, +}) diff --git a/test/e2e/test/artifacts.test.ts b/test/e2e/test/artifacts.test.ts index b1786e1c9..66f3dbef7 100644 --- a/test/e2e/test/artifacts.test.ts +++ b/test/e2e/test/artifacts.test.ts @@ -371,6 +371,7 @@ describe('reporters', () => { .replace(/\d+\.\d+\.\d+(-beta\.\d+)?/, '') .replace(ctx!.config.root, '') .replace(/\d+:\d+:\d+/, '