feat: report the duration breakdown as percentages · vitest.dev/vitest@4b54a1a

+20 -2

docs/guide/improving-performance.md

··· 1 1 # Improving Performance 2 2 3 + ## Profile First 4 + 5 + The `Duration` line of the summary breaks the run down into phases, as percentages of all tracked time: 6 + 7 + ``` 8 + Duration 3.76s (environment 79%, import 14%, transform 6%, tests 1%) 9 + ``` 10 + 11 + 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. 12 + 13 + The phases map to configuration options: 14 + 15 + - `environment` - creating the test environment (`jsdom`, `happy-dom`) for test files. 16 + - `transform` - transforming files with Vite. See [Caching Between Reruns](#caching-between-reruns). 17 + - `import` - importing test files and their modules. 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). 18 + - `setup` - running [`setupFiles`](/config/setupfiles). 19 + - `tests` - running the tests themselves. A run dominated by this phase has little to gain from configuration changes. 20 + 3 21 ## Test Isolation 4 22 5 23 By default Vitest runs every test file in an isolated environment based on the [pool](/config/pool): ··· 85 103 86 104 ```shell 87 105 # the first run 88 - Duration 8.75s (transform 4.02s, setup 629ms, import 5.52s, tests 2.52s, environment 0ms, prepare 3ms) 106 + Duration 8.75s (import 43%, transform 32%, tests 20%, setup 5%) 89 107 90 108 # the second run 91 - Duration 5.90s (transform 842ms, setup 543ms, import 2.35s, tests 2.94s, environment 0ms, prepare 3ms) 109 + Duration 5.90s (tests 44%, import 35%, transform 13%, setup 8%) 92 110 ``` 93 111 94 112 ## Node Compile Cache

+4 -2

test/e2e/test/artifacts.test.ts

··· 371 371 .replace(/\d+\.\d+\.\d+(-beta\.\d+)?/, '<version>') 372 372 .replace(ctx!.config.root, '<root>') 373 373 .replace(/\d+:\d+:\d+/, '<time>') 374 + .replace(/$(?:[a-z]+ \d+%(?:, )?)+$/g, '(<breakdown>)') 374 375 .replace(/\d+(?:\.\d+)?m?s/g, '<duration>'), 375 376 ).toMatchInlineSnapshot(` 376 377 " ··· 382 383 Test Files 1 passed (1) 383 384 Tests 2 passed (2) 384 385 Start at <time> 385 - Duration <duration> (transform <duration>, setup <duration>, import <duration>, tests <duration>, environment <duration>) 386 + Duration <duration> (<breakdown>) 386 387 387 388 " 388 389 `) ··· 403 404 .replace(/\d+\.\d+\.\d+(-beta\.\d+)?/, '<version>') 404 405 .replace(ctx!.config.root, '<root>') 405 406 .replace(/\d+:\d+:\d+/, '<time>') 407 + .replace(/$(?:[a-z]+ \d+%(?:, )?)+$/g, '(<breakdown>)') 406 408 .replace(/\d+(?:\.\d+)?m?s/g, '<duration>'), 407 409 ).toMatchInlineSnapshot(` 408 410 " ··· 413 415 Test Files 1 passed (1) 414 416 Tests 2 passed (2) 415 417 Start at <time> 416 - Duration <duration> (transform <duration>, setup <duration>, import <duration>, tests <duration>, environment <duration>) 418 + Duration <duration> (<breakdown>) 417 419 418 420 " 419 421 `)

+14 -10

test/e2e/test/no-unexpected-logging.test.ts

··· 33 33 Test Files 12 passed (12) 34 34 Tests 12 passed (12) 35 35 Start at [...] 36 - Duration [...]ms (transform [...]ms, setup [...]ms, import [...]ms, tests [...]ms, environment [...]ms) 36 + Duration [...]ms (<breakdown>) 37 37 38 38 `.trim()) 39 39 }) 40 40 }) 41 41 42 42 function normalizeOutput(stdtout: string) { 43 - const rows = stdtout.replace(/\d?\.?\d+m?s/g, '[...]ms').split('\n').map((row) => { 44 - if (row.includes('RUN v')) { 45 - return `${row.split('RUN v')[0]}RUN v[...]` 46 - } 43 + const rows = stdtout 44 + .replace(/$(?:[a-z]+ \d+%(?:, )?)+$/g, '(<breakdown>)') 45 + .replace(/\d?\.?\d+m?s/g, '[...]ms') 46 + .split('\n') 47 + .map((row) => { 48 + if (row.includes('RUN v')) { 49 + return `${row.split('RUN v')[0]}RUN v[...]` 50 + } 47 51 48 - if (row.includes('Start at')) { 49 - return row.replace(/\d+:\d+:\d+/, '[...]') 50 - } 51 - return row 52 - }) 52 + if (row.includes('Start at')) { 53 + return row.replace(/\d+:\d+:\d+/, '[...]') 54 + } 55 + return row 56 + }) 53 57 54 58 return rows.join('\n').trim() 55 59 }

+96

test/unit/test/duration-breakdown.test.ts

··· 1 + import type { File } from '../../../packages/vitest/src/runtime/runner/types' 2 + import { describe, expect, it } from 'vitest' 3 + import { 4 + computeDurationBreakdown, 5 + formatDurationBreakdown, 6 + } from '../../../packages/vitest/src/node/reporters/durationBreakdown' 7 + 8 + function makeFile(overrides: { 9 + setup?: number 10 + import?: number 11 + tests?: number 12 + environment?: number 13 + }): File { 14 + return { 15 + setupDuration: overrides.setup ?? 0, 16 + collectDuration: overrides.import ?? 0, 17 + environmentLoad: overrides.environment ?? 0, 18 + result: { state: 'pass', duration: overrides.tests ?? 0 }, 19 + } as unknown as File 20 + } 21 + 22 + describe('computeDurationBreakdown', () => { 23 + it('computes shares relative to the sum of tracked phases', () => { 24 + const breakdown = computeDurationBreakdown({ 25 + files: [ 26 + makeFile({ environment: 600, import: 200, tests: 50 }), 27 + ], 28 + transformTime: 150, 29 + typecheckTime: 0, 30 + }) 31 + 32 + expect(breakdown.total).toBe(1000) 33 + expect(breakdown.phases).toEqual([ 34 + { name: 'environment', time: 600, percent: 60 }, 35 + { name: 'import', time: 200, percent: 20 }, 36 + { name: 'transform', time: 150, percent: 15 }, 37 + { name: 'tests', time: 50, percent: 5 }, 38 + ]) 39 + }) 40 + 41 + it('sums phases across all files and projects', () => { 42 + const breakdown = computeDurationBreakdown({ 43 + files: [ 44 + makeFile({ environment: 900, tests: 100 }), 45 + makeFile({ import: 500, tests: 300 }), 46 + ], 47 + transformTime: 200, 48 + typecheckTime: 0, 49 + }) 50 + 51 + expect(breakdown.total).toBe(2000) 52 + expect(breakdown.phases[0]).toEqual({ name: 'environment', time: 900, percent: 45 }) 53 + }) 54 + 55 + it('drops phases below half a percent', () => { 56 + const breakdown = computeDurationBreakdown({ 57 + files: [makeFile({ import: 1000, setup: 1 })], 58 + transformTime: 0, 59 + typecheckTime: 0, 60 + }) 61 + 62 + expect(breakdown.phases.map(phase => phase.name)).toEqual(['import']) 63 + }) 64 + 65 + it('includes typecheck time', () => { 66 + const breakdown = computeDurationBreakdown({ 67 + files: [makeFile({ tests: 100 })], 68 + transformTime: 0, 69 + typecheckTime: 300, 70 + }) 71 + 72 + expect(breakdown.phases[0]).toEqual({ name: 'typecheck', time: 300, percent: 75 }) 73 + }) 74 + 75 + it('returns no phases when nothing was tracked', () => { 76 + const breakdown = computeDurationBreakdown({ 77 + files: [], 78 + transformTime: 0, 79 + typecheckTime: 0, 80 + }) 81 + expect(breakdown.total).toBe(0) 82 + expect(breakdown.phases).toEqual([]) 83 + }) 84 + }) 85 + 86 + describe('formatDurationBreakdown', () => { 87 + it('formats phases as rounded percentages', () => { 88 + const breakdown = computeDurationBreakdown({ 89 + files: [makeFile({ environment: 856, import: 137, tests: 7 })], 90 + transformTime: 0, 91 + typecheckTime: 0, 92 + }) 93 + 94 + expect(formatDurationBreakdown(breakdown)).toBe('environment 86%, import 14%, tests 1%') 95 + }) 96 + })

+6 -5

test/e2e/test/reporters/merge-reports.test.ts

··· 113 113 114 114 Test Files 2 failed (2) 115 115 Tests 2 failed | 3 passed (5) 116 - Duration <time> (transform <time>, setup <time>, import <time>, tests <time>, environment <time>) 116 + Duration <time> (<breakdown>) 117 117 Per blob <time> <time>" 118 118 `) 119 119 ··· 279 279 expect(stdout).toContain('✓ first.test.ts (1 test)') 280 280 expect(stdout).toContain('✓ second.test.ts (1 test)') 281 281 282 - expect(stdout).toContain('Duration 4.50s (transform 6.00s') 282 + expect(stdout).toContain('Duration 4.50s (transform 100%') 283 283 expect(stdout).toContain('Per blob 1.50s 3.00s') 284 284 }) 285 285 ··· 526 526 527 527 function trimReporterOutput(report: string) { 528 528 const rows = report 529 + .replace(/(?:[a-z]+ \d+%(?:, )?)+/g, '<breakdown>') 529 530 .replace(/\d+ms/g, '<time>') 530 531 .replace(/\d+\.\d+s/g, '<time>') 531 532 .replace(/blob report written to (.*)/g, 'blob report written to <path>') ··· 623 624 624 625 Test Files 1 failed | 1 passed (2) 625 626 Tests 1 failed | 3 passed (4) 626 - Duration <time> (transform <time>, setup <time>, import <time>, tests <time>, environment <time>) 627 + Duration <time> (<breakdown>) 627 628 628 629 blob report written to <path>" 629 630 `) ··· 691 692 692 693 Test Files 2 failed | 2 passed (4) 693 694 Tests 2 failed | 6 passed (8) 694 - Duration <time> (transform <time>, setup <time>, import <time>, tests <time>, environment <time>) 695 + Duration <time> (<breakdown>) 695 696 Per blob <time> <time>" 696 697 `) 697 698 expect(result.stderr).toMatchInlineSnapshot(` ··· 891 892 892 893 Test Files 4 failed (4) 893 894 Tests 4 failed | 8 passed (12) 894 - Duration <time> (transform <time>, setup <time>, import <time>, tests <time>, environment <time>) 895 + Duration <time> (<breakdown>) 895 896 Per blob <time> <time>" 896 897 `) 897 898 expect(result.stderr).toMatchInlineSnapshot(`

+2 -1

test/e2e/test/reporters/summary.test.ts

··· 175 175 Test Files 2 passed (2) 176 176 Tests 6 passed (6) 177 177 Start at <time> 178 - Duration <time> (transform <time>, setup <time>, import <time>, tests <time>, environment <time>) 178 + Duration <time> (<breakdown>) 179 179 180 180 " 181 181 `) ··· 195 195 196 196 function trimReporterOutput(report: string) { 197 197 return report 198 + .replace(/$(?:[a-z]+ \d+%(?:, )?)+$/g, '(<breakdown>)') 198 199 .replace(/\d+ms/g, '<time>') 199 200 .replace(/\d+\.\d+s/g, '<time>') 200 201 .replace(normalize(process.cwd()), '<process-cwd>')

+10 -13

packages/vitest/src/node/reporters/base.ts

··· 15 15 import { isTTY } from '../../utils/env' 16 16 import { getSuites, getTestName, getTests, hasFailed, hasFailedSnapshot } from '../../utils/tasks' 17 17 import { generateCodeFrame, printStack } from '../printError' 18 + import { computeDurationBreakdown, formatDurationBreakdown } from './durationBreakdown' 18 19 import { BENCH_TABLE_HEAD, computeBenchColumnWidths, padBenchRow, renderBenchmarkRow } from './renderers/benchmark-table' 19 20 import { F_CHECK, F_DOWN_RIGHT, F_POINTER } from './renderers/figures' 20 21 import { ··· 638 639 // Execution time is either sum of all runs of `--merge-reports` or the current run's time 639 640 const executionTime = blobs?.executionTimes ? sum(blobs.executionTimes, time => time) : this.end - this.start 640 641 641 - const environmentTime = sum(files, file => file.environmentLoad) 642 - const transformTime = this.ctx.state.transformTime 643 - const typecheck = sum(this.ctx.projects, project => project.typechecker?.getResult().time) 642 + const breakdown = computeDurationBreakdown({ 643 + files, 644 + transformTime: this.ctx.state.transformTime, 645 + typecheckTime: sum(this.ctx.projects, project => project.typechecker?.getResult().time), 646 + }) 644 647 645 - const timers = [ 646 - `transform ${formatTime(transformTime)}`, 647 - `setup ${formatTime(setupTime)}`, 648 - `import ${formatTime(collectTime)}`, 649 - `tests ${formatTime(testsTime)}`, 650 - `environment ${formatTime(environmentTime)}`, 651 - typecheck && `typecheck ${formatTime(typecheck)}`, 652 - ].filter(Boolean).join(', ') 653 - 654 - this.log(padSummaryTitle('Duration'), formatTime(executionTime) + c.dim(` (${timers})`)) 648 + // percentages are relative to the sum of all tracked phases: phases run 649 + // in parallel workers, so their sum is not comparable to the wall time 650 + const timers = breakdown.total > 0 ? formatDurationBreakdown(breakdown) : '' 651 + this.log(padSummaryTitle('Duration'), formatTime(executionTime) + (timers ? c.dim(` (${timers})`) : '')) 655 652 656 653 if (blobs?.executionTimes) { 657 654 this.log(padSummaryTitle('Per blob') + blobs.executionTimes.map(time => ` ${formatTime(time)}`).join(''))

+66

packages/vitest/src/node/reporters/durationBreakdown.ts

··· 1 + import type { File } from '../../runtime/runner/types' 2 + 3 + export interface DurationPhase { 4 + name: string 5 + time: number 6 + /** Share of the tracked time, in percent (0-100). */ 7 + percent: number 8 + } 9 + 10 + export interface DurationBreakdown { 11 + /** Summed time of all tracked phases. */ 12 + total: number 13 + /** Phases sorted by time, descending. Phases below half a percent are dropped. */ 14 + phases: DurationPhase[] 15 + } 16 + 17 + export interface DurationBreakdownInput { 18 + files: File[] 19 + /** Total transform time across all projects. */ 20 + transformTime: number 21 + /** Total typecheck time across all projects. */ 22 + typecheckTime: number 23 + } 24 + 25 + export function computeDurationBreakdown( 26 + input: DurationBreakdownInput, 27 + ): DurationBreakdown { 28 + const sums = { 29 + transform: input.transformTime, 30 + setup: 0, 31 + import: 0, 32 + tests: 0, 33 + environment: 0, 34 + typecheck: input.typecheckTime, 35 + } 36 + for (const file of input.files) { 37 + sums.setup += file.setupDuration || 0 38 + sums.import += file.collectDuration || 0 39 + sums.tests += file.result?.duration || 0 40 + sums.environment += file.environmentLoad || 0 41 + } 42 + 43 + const entries = Object.entries(sums) 44 + const total = entries.reduce((acc, [, time]) => acc + time, 0) 45 + const phases = entries 46 + .map(([name, time]) => ({ 47 + name, 48 + time, 49 + percent: total > 0 ? (time / total) * 100 : 0, 50 + })) 51 + .filter(phase => phase.percent >= 0.5) 52 + .sort((a, b) => b.time - a.time) 53 + 54 + return { total, phases } 55 + } 56 + 57 + export function formatDurationBreakdown(breakdown: DurationBreakdown): string { 58 + return breakdown.phases 59 + .map(phase => `${phase.name} ${formatPercent(phase.percent)}`) 60 + .join(', ') 61 + } 62 + 63 + function formatPercent(percent: number): string { 64 + // sub-1% shares round to "1%" instead of a misleading "0%" 65 + return `${Math.max(1, Math.round(percent))}%` 66 + }

Configure Feed

Configure Feed