diff --git a/.gitignore b/.gitignore index e5d7f1726288a..ffa39038b56ae 100644 --- a/.gitignore +++ b/.gitignore @@ -3,6 +3,8 @@ logs npm-debug.log* yarn-debug.log* yarn-error.log* +*.cpuprofile +*.heapprofile lib-cov coverage !**/integrations/coverage diff --git a/docs/.vitepress/config.ts b/docs/.vitepress/config.ts index b2fc8423dd1b7..964c019c13b94 100644 --- a/docs/.vitepress/config.ts +++ b/docs/.vitepress/config.ts @@ -325,6 +325,10 @@ export default ({ mode }: { mode: string }) => { text: 'Common Errors', link: '/guide/common-errors', }, + { + text: 'Profiling Test Performance', + link: '/guide/profiling-test-performance', + }, { text: 'Improving Performance', link: '/guide/improving-performance', diff --git a/docs/guide/index.md b/docs/guide/index.md index 60bfccbbfc803..26c5197eb15ab 100644 --- a/docs/guide/index.md +++ b/docs/guide/index.md @@ -251,6 +251,7 @@ Learn more about [IDE Integrations](/guide/ide) | `react` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/react) | [Play Online](https://stackblitz.com/fork/github/vitest-dev/vitest/tree/main/examples/react?initialPath=__vitest__/) | | `solid` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/solid) | [Play Online](https://stackblitz.com/fork/github/vitest-dev/vitest/tree/main/examples/solid?initialPath=__vitest__/) | | `sveltekit` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/sveltekit) | [Play Online](https://stackblitz.com/fork/github/vitest-dev/vitest/tree/main/examples/sveltekit?initialPath=__vitest__/) | +| `profiling` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/profiling) | Not Available | | `typecheck` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/typecheck) | [Play Online](https://stackblitz.com/fork/github/vitest-dev/vitest/tree/main/examples/typecheck?initialPath=__vitest__/) | | `workspace` | [GitHub](https://github.com/vitest-dev/vitest/tree/main/examples/workspace) | [Play Online](https://stackblitz.com/fork/github/vitest-dev/vitest/tree/main/examples/workspace?initialPath=__vitest__/) | diff --git a/docs/guide/profiling-test-performance.md b/docs/guide/profiling-test-performance.md new file mode 100644 index 0000000000000..6d732dcae5ad1 --- /dev/null +++ b/docs/guide/profiling-test-performance.md @@ -0,0 +1,188 @@ +# Profiling Test Performance + +When you run Vitest it reports multiple time metrics of your tests: + +> ```bash +> RUN v2.1.1 /x/vitest/examples/profiling +> +> ✓ test/prime-number.test.ts (1) 4517ms +> ✓ generate prime number 4517ms +> +> Test Files 1 passed (1) +> Tests 1 passed (1) +> Start at 09:32:53 +> Duration 4.80s (transform 44ms, setup 0ms, collect 35ms, tests 4.52s, environment 0ms, prepare 81ms) +> # Time metrics ^^ +> ``` + +- Transform: How much time was spent transforming the files. See [File Transform](#file-transform). +- Setup: Time spent for running the [`setupFiles`](/config/#setupfiles) files. +- Collect: Time spent for colleting all tests in the test files. This includes the time it took to import all file dependencies. +- Tests: Time spent for actually running the test cases. +- Environment: Time spent for setting up the test [`environment`](/config/#environment), for example JSDOM. +- Prepare: Time Vitest uses to prepare the test runner. + +## Test runner + +In cases where your test execution time is high, you can generate a profile of the test runner. See NodeJS documentation for following options: + +- [`--cpu-prof`](https://nodejs.org/api/cli.html#--cpu-prof) +- [`--heap-prof`](https://nodejs.org/api/cli.html#--heap-prof) +- [`--prof`](https://nodejs.org/api/cli.html#--prof) + +:::warning +The `--prof` option does not work with `pool: 'threads'` due to `node:worker_threads` limitations. +::: + +To pass these options to Vitest's test runner, define `poolOptions..execArgv` in your Vitest configuration: + +::: code-group +```ts [Forks] +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + pool: 'forks', + poolOptions: { + forks: { + execArgv: [ + '--cpu-prof', + '--cpu-prof-dir=test-runner-profile', + '--heap-prof', + '--heap-prof-dir=test-runner-profile' + ], + + // To generate a single profile + singleFork: true, + }, + }, + }, +}) +``` +```ts [Threads] +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + pool: 'threads', + poolOptions: { + threads: { + execArgv: [ + '--cpu-prof', + '--cpu-prof-dir=test-runner-profile', + '--heap-prof', + '--heap-prof-dir=test-runner-profile' + ], + + // To generate a single profile + singleThread: true, + }, + }, + }, +}) +``` +::: + +After the tests have run there should be a `test-runner-profile/*.cpuprofile` and `test-runner-profile/*.heapprofile` files generated. See [Inspecting profiling records](#inspecting-profiling-records) for instructions how to analyze these files. + +See [Profiling | Examples](https://github.com/vitest-dev/vitest/tree/main/examples/profiling) for example. + +## Main thread + +Profiling main thread is useful for debugging Vitest's Vite usage and [`globalSetup`](/config/#globalsetup) files. +This is also where your Vite plugins are running. + +:::tip +See [Performance | Vite](https://vitejs.dev/guide/performance.html) for more tips about Vite specific profiling. + +We recommend [`vite-plugin-inspect`](https://github.com/antfu-collective/vite-plugin-inspect) for profiling your Vite plugin performance. +::: + +To do this you'll need to pass arguments to the Node process that runs Vitest. + +```bash +$ node --cpu-prof --cpu-prof-dir=main-profile ./node_modules/vitest/vitest.mjs --run +# ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ^^^^^ +# NodeJS arguments Vitest arguments +``` + +After the tests have run there should be a `main-profile/*.cpuprofile` file generated. See [Inspecting profiling records](#inspecting-profiling-records) for instructions how to analyze these files. + +## File transform + +In cases where your test transform and collection time is high, you can use `DEBUG=vite-node:*` environment variable to see which files are being transformed and executed by `vite-node`. + +```bash +$ DEBUG=vite-node:* vitest --run + + RUN v2.1.1 /x/vitest/examples/profiling + + vite-node:server:request /x/vitest/examples/profiling/global-setup.ts +0ms + vite-node:client:execute /x/vitest/examples/profiling/global-setup.ts +0ms + vite-node:server:request /x/vitest/examples/profiling/test/prime-number.test.ts +45ms + vite-node:client:execute /x/vitest/examples/profiling/test/prime-number.test.ts +26ms + vite-node:server:request /src/prime-number.ts +9ms + vite-node:client:execute /x/vitest/examples/profiling/src/prime-number.ts +9ms + vite-node:server:request /src/unnecessary-file.ts +6ms + vite-node:client:execute /x/vitest/examples/profiling/src/unnecessary-file.ts +4ms +... +``` + +This profiling strategy is a good way to identify unnecessary transforms caused by [barrel files](https://vitejs.dev/guide/performance.html#avoid-barrel-files). +If these logs contain files that should not be loaded when your test is run, you might have barrel files that are importing files unnecessarily. + +You can also use [Vitest UI](/guide/ui) to debug slowness caused by barrel file. +The example below shows how importing files without barrel file reduces amount of transformed files by ~85%. + +::: code-group +``` [File tree] +├── src +│ └── utils +│ ├── currency.ts +│ ├── formatters.ts <-- File to test +│ ├── index.ts +│ ├── location.ts +│ ├── math.ts +│ ├── time.ts +│ └── users.ts +├── test +│ └── formatters.test.ts +└── vitest.config.ts +``` +```ts [example.test.ts] +import { expect, test } from 'vitest' +import { formatter } from '../src/utils' // [!code --] +import { formatter } from '../src/utils/formatters' // [!code ++] + +test('formatter works', () => { + expect(formatter).not.toThrow() +}) +``` +::: + +Vitest UI demonstrating barrel file issues + +To see how files are transformed, you can use `VITE_NODE_DEBUG_DUMP` environment variable to write transformed files in the file system: + +```bash +$ VITE_NODE_DEBUG_DUMP=true vitest --run + +[vite-node] [debug] dump modules to /x/examples/profiling/.vite-node/dump + + RUN v2.1.1 /x/vitest/examples/profiling +... + +$ ls .vite-node/dump/ +_x_examples_profiling_global-setup_ts-1292904907.js +_x_examples_profiling_test_prime-number_test_ts-1413378098.js +_src_prime-number_ts-525172412.js +``` + +## Inspecting profiling records + +You can inspect the contents of `*.cpuprofile` and `*.heapprofile` with various tools. See list below for examples. + +- [Speedscope](https://www.speedscope.app/) +- [Performance Profiling JavaScript in Visual Studio Code](https://code.visualstudio.com/docs/nodejs/profiling#_analyzing-a-profile) +- [Profile Node.js performance with the Performance panel | developer.chrome.com](https://developer.chrome.com/docs/devtools/performance/nodejs#analyze) +- [Memory panel overview | developer.chrome.com](https://developer.chrome.com/docs/devtools/memory-problems/heap-snapshots#view_snapshots) diff --git a/docs/public/module-graph-barrel-file.png b/docs/public/module-graph-barrel-file.png new file mode 100644 index 0000000000000..dae0382b5d77b Binary files /dev/null and b/docs/public/module-graph-barrel-file.png differ diff --git a/examples/profiling/global-setup.ts b/examples/profiling/global-setup.ts new file mode 100644 index 0000000000000..9fb58538a55d7 --- /dev/null +++ b/examples/profiling/global-setup.ts @@ -0,0 +1,6 @@ +import { rmSync } from 'node:fs' + +export function setup() { + rmSync('./threads-profile', { force: true, recursive: true }) + rmSync('./forks-profile', { force: true, recursive: true }) +} diff --git a/examples/profiling/package.json b/examples/profiling/package.json new file mode 100644 index 0000000000000..8941e996a6076 --- /dev/null +++ b/examples/profiling/package.json @@ -0,0 +1,13 @@ +{ + "name": "@vitest/example-profiling", + "type": "module", + "private": true, + "license": "MIT", + "scripts": { + "test": "vitest" + }, + "devDependencies": { + "vite": "latest", + "vitest": "latest" + } +} diff --git a/examples/profiling/src/prime-number.ts b/examples/profiling/src/prime-number.ts new file mode 100644 index 0000000000000..345f6c56df082 --- /dev/null +++ b/examples/profiling/src/prime-number.ts @@ -0,0 +1,82 @@ +/* eslint-disable unicorn/no-new-array */ + +const store: bigint[] = [] + +export default function getPrimeNumber(bitLength: number): bigint { + if (!bitLength) { + throw new Error('bitLength is required') + } + + const number = randomBigInt(bitLength) + + if (isPrimeNumber(number) && !store.includes(number)) { + store.push(number) + + return number + } + + return getPrimeNumber(bitLength) +} + +/** + * Generate random `BigInt` with given bit length + * e.g. randomBigInt(8) -> 153n (1001 1001) + */ +function randomBigInt(bitLength: number): bigint { + const binaryString: string = new Array(bitLength) + // MSB should be one to guarantee bit length + .fill('1') + // Fill string with 0s and 1s + .reduce(bin => bin + Math.round(Math.random()).toString()) + + return BigInt(`0b${binaryString}`) +} + +function isPrimeNumber(number: bigint): boolean { + if (number <= 2n) { + return false + } + + if (number % 2n === 0n) { + return false + } + + if (number === 3n) { + return true + } + + const squareRoot = bigIntSquareRoot(number) + + // Intentionally unefficient to highlight performance issues + for (let i = 3n; i < squareRoot; i += 2n) { + if (number % i === 0n) { + return false + } + } + + return true +} + +function bigIntSquareRoot(number: bigint): bigint { + if (number < 0n) { + throw new Error('Negative numbers are not supported') + } + if (number < 2n) { + return number + } + + function iterate(value: bigint, guess: bigint): bigint { + const nextGuess = (value / guess + guess) >> 1n + + if (guess === nextGuess) { + return guess + } + if (guess === nextGuess - 1n) { + return guess + } + + return iterate(value, nextGuess) + } + + return iterate(number, 1n) +} diff --git a/examples/profiling/test/prime-number.test.ts b/examples/profiling/test/prime-number.test.ts new file mode 100644 index 0000000000000..046a9d89d8edb --- /dev/null +++ b/examples/profiling/test/prime-number.test.ts @@ -0,0 +1,11 @@ +import { expect, test } from 'vitest' +import getPrimeNumber from '../src/prime-number' + +const BITS = 62 + +test('generate prime number', () => { + const prime = getPrimeNumber(BITS) + + expect(prime).toBeGreaterThanOrEqual(0) + expect(prime).toBeLessThanOrEqual(2 ** BITS) +}) diff --git a/examples/profiling/vitest.config.ts b/examples/profiling/vitest.config.ts new file mode 100644 index 0000000000000..41a4f3ae1c750 --- /dev/null +++ b/examples/profiling/vitest.config.ts @@ -0,0 +1,43 @@ +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + watch: false, + globalSetup: './global-setup.ts', + + // Switch between forks|threads + pool: 'forks', + + poolOptions: { + threads: { + execArgv: [ + // https://nodejs.org/api/cli.html#--cpu-prof + '--cpu-prof', + '--cpu-prof-dir=threads-profile', + + // https://nodejs.org/api/cli.html#--heap-prof + '--heap-prof', + '--heap-prof-dir=threads-profile', + ], + + // Generate a single profile + singleThread: true, + }, + + forks: { + execArgv: [ + // https://nodejs.org/api/cli.html#--cpu-prof + '--cpu-prof', + '--cpu-prof-dir=forks-profile', + + // https://nodejs.org/api/cli.html#--heap-prof + '--heap-prof', + '--heap-prof-dir=forks-profile', + ], + + // Generate a single profile + singleFork: true, + }, + }, + }, +}) diff --git a/packages/vitest/src/runtime/worker.ts b/packages/vitest/src/runtime/worker.ts index e3039dfbcbf66..aae84c8c747c3 100644 --- a/packages/vitest/src/runtime/worker.ts +++ b/packages/vitest/src/runtime/worker.ts @@ -29,7 +29,7 @@ if (isChildProcess()) { } // this is what every pool executes when running tests -async function execute(mehtod: 'run' | 'collect', ctx: ContextRPC) { +async function execute(method: 'run' | 'collect', ctx: ContextRPC) { disposeInternalListeners() const prepareStart = performance.now() @@ -92,7 +92,7 @@ async function execute(mehtod: 'run' | 'collect', ctx: ContextRPC) { providedContext: ctx.providedContext, } satisfies WorkerGlobalState - const methodName = mehtod === 'collect' ? 'collectTests' : 'runTests' + const methodName = method === 'collect' ? 'collectTests' : 'runTests' if (!worker[methodName] || typeof worker[methodName] !== 'function') { throw new TypeError( diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index e09dbd5da3ff1..7fe80877de64d 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -285,6 +285,15 @@ importers: specifier: workspace:* version: link:../../packages/vitest + examples/profiling: + devDependencies: + vite: + specifier: ^5.4.0 + version: 5.4.0(@types/node@22.5.2)(terser@5.22.0) + vitest: + specifier: workspace:* + version: link:../../packages/vitest + examples/react: dependencies: react: