Abrenneke/self time reporter

packages/runner/src/types/runner.ts

@@ -157,7 +157,7 @@ export interface VitestRunner {
   /**
    * Gets the time spent importing each individual file that Vitest collected.
    */
-  getImportDurations?: () => Record<string, number>
+  getImportDurations?: () => Record<string, { selfTime: number; totalTime: number }>
   /**
    * Publicly available configuration.
    */

packages/runner/src/types/tasks.ts

@@ -241,7 +241,7 @@ export interface File extends Suite {
   local?: boolean
 
   /** The time spent importing every dependency that Vitest has processed. */
-  importDurations?: Record<string, number>
+  importDurations?: Record<string, { selfTime: number; totalTime: number }>
 }
 
 export interface Test<ExtraContext = object> extends TaskPopulated {

packages/vite-node/src/client.ts

@@ -176,7 +176,19 @@ export class ModuleCacheMap extends Map<string, ModuleCache> {
   }
 }
 
-export type ModuleExecutionInfo = Map<string, { startOffset: number; duration?: number }>
+export type ModuleExecutionInfo = Map<string, {
+  startOffset: number
+  duration?: number
+  selfTime?: number
+  subImportTime?: number
+}>
+
+// Stack to track nested module execution for self-time calculation
+type ExecutionStack = Array<{
+  filename: string
+  startTime: number
+  subImportTime: number
+}>
 
 export class ViteNodeRunner {
   root: string
@@ -189,6 +201,9 @@ export class ViteNodeRunner {
    */
   moduleCache: ModuleCacheMap
 
+  // Stack to track nested executions for self-time calculation
+  private executionStack: ExecutionStack = []
+
   constructor(public options: ViteNodeRunnerOptions) {
     this.root = options.root ?? process.cwd()
     this.moduleCache = options.moduleCache ?? new ModuleCacheMap()
@@ -323,7 +338,7 @@ export class ViteNodeRunner {
 
   /** @internal */
   async dependencyRequest(id: string, fsPath: string, callstack: string[]) {
-    return await this.cachedRequest(id, fsPath, callstack)
+    return this.cachedRequest(id, fsPath, callstack)
   }
 
   private async _fetchModule(id: string, importer?: string) {
@@ -525,6 +540,46 @@ export class ViteNodeRunner {
     return { Object, Reflect, Symbol }
   }
 
+  protected beforeModuleExecution(filename: string, codeDefinitionLength: number): number {
+    const currentTime = performance.now()
+
+    this.executionStack.push({
+      filename,
+      startTime: currentTime,
+      subImportTime: 0,
+    })
+
+    this.options.moduleExecutionInfo?.set(filename, {
+      startOffset: codeDefinitionLength,
+      subImportTime: 0,
+    })
+
+    return currentTime
+  }
+
+  protected afterModuleExecution(filename: string, codeDefinitionLength: number, startTime: number): void {
+    // Calculate timing and update execution info
+    const endTime = performance.now()
+    const totalDuration = endTime - startTime
+
+    // Remove current module from stack
+    const currentExecution = this.executionStack.pop()!
+    const subImportTime = currentExecution.subImportTime
+    const selfTime = totalDuration - subImportTime
+
+    // Update parent's sub-import time if there is a parent
+    if (this.executionStack.length > 0) {
+      this.executionStack.at(-1)!.subImportTime += totalDuration
+    }
+
+    this.options.moduleExecutionInfo?.set(filename, {
+      startOffset: codeDefinitionLength,
+      duration: totalDuration,
+      selfTime,
+      subImportTime,
+    })
+  }
+
   protected async runModule(context: Record<string, any>, transformed: string): Promise<void> {
     // add 'use strict' since ESM enables it by default
     const codeDefinition = `'use strict';async (${Object.keys(context).join(
@@ -537,14 +592,12 @@ export class ViteNodeRunner {
       columnOffset: -codeDefinition.length,
     }
 
-    this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length })
-
-    const start = performance.now()
+    const startTime = this.beforeModuleExecution(options.filename, codeDefinition.length)
 
     const fn = vm.runInThisContext(code, options)
     await fn(...Object.values(context))
 
-    this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length, duration: performance.now() - start })
+    this.afterModuleExecution(options.filename, codeDefinition.length, startTime)
   }
 
   prepareContext(context: Record<string, any>): Record<string, any> {

packages/vitest/src/node/reporters/collect-time.ts

@@ -1,32 +1,59 @@
-import type { File } from '@vitest/runner'
+import type { SerializedError } from '@vitest/utils'
+import type { Vitest } from '../core'
+import type { Reporter, TestRunEndReason } from '../types/reporter'
+import type { TestModule } from './reported-tasks'
+import { relative } from 'pathe'
 import c from 'tinyrainbow'
-import { BaseReporter } from './base'
 import { formatTime } from './renderers/utils'
 
-export class CollectTimeReporter extends BaseReporter {
-  reportTestSummary(files: File[], errors: unknown[]): void {
-    // Call the original summary first
-    super.reportTestSummary(files, errors)
+export interface CollectTimeOptions {
+  order?: 'total-time' | 'self-time'
+  top?: number | 'all'
+}
+
+export class CollectTimeReporter implements Reporter, Required<CollectTimeOptions> {
+  order: 'total-time' | 'self-time'
+  top: number | 'all'
+  private ctx!: Vitest
+
+  constructor(options: CollectTimeOptions = {}) {
+    this.order = options.order ?? 'total-time'
+    this.top = options.top ?? 10
+  }
+
+  onInit(ctx: Vitest): void {
+    this.ctx = ctx
+  }
+
+  onTestRunEnd(testModules: ReadonlyArray<TestModule>, _unhandledErrors: ReadonlyArray<SerializedError>, _reason: TestRunEndReason): void {
+    this.reportCollectTimeSummary(testModules)
+  }
+
+  private log(...messages: any): void {
+    this.ctx.logger.log(...messages)
+  }
 
-    // Then add our custom collect time breakdown
-    this.reportCollectTimeSummary(files)
+  private relative(path: string): string {
+    return relative(this.ctx.config.root, path)
   }
 
-  private reportCollectTimeSummary(files: File[]): void {
+  private reportCollectTimeSummary(testModules: ReadonlyArray<TestModule>): void {
     this.log()
-    this.log(c.bold(c.cyan('📊 Import Duration Breakdown')))
+    this.log(c.bold(c.cyan(`📊 Import Duration Breakdown (ordered by ${this.order === 'self-time' ? 'Self Time' : 'Total Time'})${this.top === 'all' ? '' : ` (Top ${this.top})`}`)))
     this.log()
 
-    // Collect all import durations from all files
-    const allImports: Array<{ path: string; duration: number; testFile: string }> = []
+    // Collect all import durations from all test modules
+    const allImports: Array<{ path: string; selfTime: number; totalTime: number; testFile: string }> = []
 
-    for (const file of files) {
+    for (const testModule of testModules) {
+      const file = testModule.task
       if (file.importDurations) {
-        for (const [importPath, duration] of Object.entries(file.importDurations)) {
-          if (duration > 0) {
+        for (const [importPath, { selfTime, totalTime }] of Object.entries(file.importDurations)) {
+          if (selfTime > 0 || totalTime > 0) {
             allImports.push({
               path: importPath,
-              duration,
+              selfTime,
+              totalTime,
               testFile: this.relative(file.filepath),
             })
           }
@@ -35,58 +62,82 @@ export class CollectTimeReporter extends BaseReporter {
     }
 
     // Group imports by path to combine duplicates
-    const importMap = new Map<string, { duration: number; testFiles: Set<string> }>()
+    const importMap = new Map<string, { selfTime: number; totalTime: number; testFiles: Set<string> }>()
     for (const imp of allImports) {
       const existing = importMap.get(imp.path)
       if (existing) {
-        existing.duration += imp.duration // Sum durations if imported multiple times
+        existing.selfTime += imp.selfTime // Sum durations if imported multiple times
+        existing.totalTime += imp.totalTime
         existing.testFiles.add(imp.testFile)
       }
       else {
-        importMap.set(imp.path, { duration: imp.duration, testFiles: new Set([imp.testFile]) })
+        importMap.set(imp.path, { selfTime: imp.selfTime, totalTime: imp.totalTime, testFiles: new Set([imp.testFile]) })
       }
     }
 
     // Convert to sorted array
     const sortedImports = Array.from(importMap.entries())
-      .map(([path, data]) => ({ path, duration: data.duration, testFiles: Array.from(data.testFiles) }))
-      .sort((a, b) => b.duration - a.duration)
+      .map(([path, data]) => ({ path, selfTime: data.selfTime, totalTime: data.totalTime, testFiles: Array.from(data.testFiles), importCount: data.testFiles.size }))
+      .sort((a, b) => {
+        const aDuration = this.order === 'self-time' ? a.selfTime : a.totalTime
+        const bDuration = this.order === 'self-time' ? b.selfTime : b.totalTime
+        return bDuration - aDuration
+      })
 
     if (sortedImports.length === 0) {
       this.log(c.dim('  No import duration data available'))
       return
     }
 
-    const maxImportTime = Math.max(...sortedImports.map(imp => imp.duration))
-    const maxPathLength = Math.max(...sortedImports.map(imp => this.relative(imp.path).length))
+    const maxOrderTime = Math.max(...sortedImports.map(imp => this.order === 'self-time' ? imp.selfTime : imp.totalTime))
+
+    // Calculate the maximum length of formatted time strings for dynamic padding
+    const itemsToShow = sortedImports.slice(0, this.top === 'all' ? undefined : this.top)
+    const maxSelfTimeLength = Math.max(...itemsToShow.map(imp => formatTime(imp.selfTime).length))
+    const maxTotalTimeLength = Math.max(...itemsToShow.map(imp => formatTime(imp.totalTime).length))
+    const maxImportCountLength = Math.max(...itemsToShow.map(imp => imp.importCount.toString().length))
 
-    for (const importData of sortedImports) {
-      const { path, duration, testFiles } = importData
+    // Use a more reasonable path width - cap at 60 characters but ensure it fits the longest path in the items to show
+    const maxPathLengthInItems = Math.max(...itemsToShow.map(imp => this.relative(imp.path).length))
+    const dynamicPathLength = Math.min(60, Math.max(30, maxPathLengthInItems))
+
+    for (const importData of itemsToShow) {
+      const { path, selfTime, totalTime, importCount } = importData
       const relativePath = this.relative(path)
-      const paddedPath = relativePath.padEnd(maxPathLength)
 
-      // Create a visual bar for the import time
-      const barLength = Math.max(1, Math.round((duration / maxImportTime) * 20))
+      // Truncate path if it's longer than our dynamic width
+      let displayPath = relativePath
+      if (relativePath.length > dynamicPathLength) {
+        const truncatedLength = dynamicPathLength - 3 // Account for "..." prefix
+        displayPath = `...${relativePath.slice(-truncatedLength)}`
+      }
+      const paddedPath = displayPath.padEnd(dynamicPathLength)
+
+      // Create a visual bar for the import time (based on order field)
+      const orderDuration = this.order === 'self-time' ? selfTime : totalTime
+      const barLength = Math.max(1, Math.round((orderDuration / maxOrderTime) * 20))
       const bar = '█'.repeat(barLength)
 
-      // Color coding based on import time
+      // Color coding based on order duration
       let timeColor = c.green
-      if (duration > 100) {
+      if (orderDuration > 100) {
         timeColor = c.yellow
       }
-      if (duration > 500) {
+      if (orderDuration > 500) {
         timeColor = c.red
       }
 
-      const formattedTime = formatTime(duration).padStart(8)
+      const formattedSelfTime = formatTime(selfTime).padStart(maxSelfTimeLength)
+      const formattedTotalTime = formatTime(totalTime).padStart(maxTotalTimeLength)
+      const formattedImportCount = importCount.toString().padStart(maxImportCountLength)
 
-      this.log(`  ${c.dim(paddedPath)} ${timeColor(formattedTime)} ${c.dim(bar)}`)
+      this.log(`  ${c.dim(paddedPath)} ${timeColor(`self: ${formattedSelfTime}  total: ${formattedTotalTime}  imports: ${formattedImportCount}`)} ${c.dim(bar)}`)
     }
 
     this.log()
     this.log(c.dim(`  Total imports: ${sortedImports.length}`))
-    this.log(c.dim(`  Slowest import: ${formatTime(maxImportTime)}`))
-    this.log(c.dim(`  Total import time: ${formatTime(sortedImports.reduce((sum, imp) => sum + imp.duration, 0))}`))
+    this.log(c.dim(`  Slowest import (${this.order}): ${formatTime(maxOrderTime)}`))
+    this.log(c.dim(`  Total import time (self/total): ${formatTime(sortedImports.reduce((sum, imp) => sum + imp.selfTime, 0))} / ${formatTime(sortedImports.reduce((sum, imp) => sum + imp.totalTime, 0))}`))
     this.log()
   }
 }

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

@@ -1,6 +1,7 @@
 import type { Reporter, TestRunEndReason } from '../types/reporter'
 import type { BaseOptions, BaseReporter } from './base'
 import type { BlobOptions } from './blob'
+import type { CollectTimeOptions } from './collect-time'
 import type { DefaultReporterOptions } from './default'
 import type { HTMLOptions } from './html'
 import type { JsonOptions } from './json'
@@ -65,7 +66,7 @@ export type BuiltinReporters = keyof typeof ReportersMap
 export interface BuiltinReporterOptions {
   'default': DefaultReporterOptions
   'basic': BaseOptions
-  'collect-time': BaseOptions
+  'collect-time': CollectTimeOptions
   'verbose': DefaultReporterOptions
   'dot': BaseOptions
   'json': JsonOptions

packages/vitest/src/runtime/execute.ts

@@ -343,9 +343,7 @@ export class VitestExecutor extends ViteNodeRunner {
       columnOffset: -codeDefinition.length,
     }
 
-    this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length })
-
-    const start = performance.now()
+    const startTime = this.beforeModuleExecution(options.filename, codeDefinition.length)
 
     const fn = vm.runInContext(code, vmContext, {
       ...options,
@@ -355,7 +353,7 @@ export class VitestExecutor extends ViteNodeRunner {
     } as any)
     await fn(...Object.values(context))
 
-    this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length, duration: performance.now() - start })
+    this.afterModuleExecution(options.filename, codeDefinition.length, startTime)
   }
 
   public async importExternalModule(path: string): Promise<any> {

packages/vitest/src/runtime/runners/test.ts

@@ -182,8 +182,15 @@ export class VitestTestRunner implements VitestRunner {
     return context
   }
 
-  getImportDurations(): Record<string, number> {
-    return Object.fromEntries((this.workerState.moduleExecutionInfo?.entries() ?? []).map(([filepath, { duration }]) => [filepath, duration ?? 0]))
+  getImportDurations(): Record<string, { selfTime: number; totalTime: number }> {
+    return Object.fromEntries((this.workerState.moduleExecutionInfo?.entries() ?? [])
+      .map(([filepath, { duration, selfTime }]) => [
+        filepath,
+        {
+          selfTime: selfTime ?? 0,
+          totalTime: duration ?? 0,
+        },
+      ]))
   }
 }