misc: write command durations to a csv file

cli/CHANGELOG.md

@@ -12,6 +12,7 @@ _Released 11/18/2025 (PENDING)_
 
 - The keyboard shortcuts modal now displays the keyboard shortcut for saving Studio changes - `⌘` + `s` for Mac or `Ctrl` + `s` for Windows/Linux. Addressed [#32862](https://github.com/cypress-io/cypress/issues/32862). Addressed in [#32864](https://github.com/cypress-io/cypress/pull/32864).
 - The Cursor logo now correctly displays in the External editor dropdown. Addresses [#32062](https://github.com/cypress-io/cypress/issues/32062). Addressed in [#32911](https://github.com/cypress-io/cypress/pull/32911).
+- Command execution can be benchmarked by setting the `CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING` environment variable to `1` or `true`. The performance log is recorded to `./cypress/logs/performance.log` by default. Addressed in [#32938](https://github.com/cypress-io/cypress/pull/32938)
 
 ## 15.6.0
 

packages/driver/src/cypress/command_queue.ts

@@ -229,6 +229,7 @@ export class CommandQueue extends Queue<$Command> {
   }
 
   private runCommand (command: $Command) {
+    const startTime = performance.now()
     const isQuery = command.get('query')
     const name = command.get('name')
 
@@ -362,6 +363,8 @@ export class CommandQueue extends Queue<$Command> {
       command.set({ subject })
       command.pass()
 
+      const numElements = subject ? subject.length ?? 1 : 0
+
       // end / snapshot our logs if they need it
       command.finishLogs()
 
@@ -397,6 +400,19 @@ export class CommandQueue extends Queue<$Command> {
         current: null,
       })
 
+      const duration = performance.now() - startTime
+
+      Cypress.automation('log:command:performance', {
+        name: command?.attributes?.name ?? 'unknown',
+        startTime,
+        duration,
+        detail: {
+          runnable: this.state('runnable') ?? {},
+          spec: Cypress.spec.relative,
+          numElements,
+        },
+      })
+
       return subject
     })
   }

packages/server/lib/automation/automation.ts

@@ -8,6 +8,7 @@ import { cookieJar } from '../util/cookies'
 import type { ServiceWorkerEventHandler } from '@packages/proxy/lib/http/util/service-worker-manager'
 import Debug from 'debug'
 import { AutomationNotImplemented } from './automation_not_implemented'
+import { recordPerformanceEntry } from './commands/record_performance_entry'
 
 const debug = Debug('cypress:server:automation')
 
@@ -174,6 +175,8 @@ export class Automation {
         case 'canceled:download':
         case 'complete:download':
           return data
+        case 'log:command:performance':
+          return recordPerformanceEntry(data)
         default:
           return automate(data)
       }

packages/server/lib/automation/commands/record_performance_entry.ts

@@ -0,0 +1,62 @@
+import Debug from 'debug'
+import type { CommandPerformanceEntry } from '@packages/types'
+import path from 'path'
+import fs from 'fs/promises'
+import fsSync from 'fs'
+
+const debug = Debug('cypress-verbose:server:automation:commands:record_performance_entry')
+
+function logFilePath () {
+  return process.env.CYPRESS_INTERNAL_PERFORMANCE_LOG_FILE_PATH ?? path.join(process.cwd(), 'cypress', 'logs')
+}
+
+function performanceLogsEnabled () {
+  return ['1', 'true'].includes(process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING ?? 'false')
+}
+
+const COLUMNS = [
+  'startTime',
+  'duration',
+  'name',
+  'numElements',
+  'runnableTitle',
+  'spec',
+]
+
+export function initializePerformanceLogFile () {
+  if (!performanceLogsEnabled()) {
+    return
+  }
+
+  debug('initializing performance log file: %s', path.join(logFilePath(), 'performance.log'))
+
+  fsSync.mkdirSync(logFilePath(), { recursive: true })
+  fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' })
+}
+
+export async function recordPerformanceEntry (entry: CommandPerformanceEntry) {
+  debug('recording performance entry %o', entry)
+
+  if (!performanceLogsEnabled()) {
+    return
+  }
+
+  const {
+    startTime,
+    duration,
+    name,
+    detail: {
+      numElements,
+      runnable: {
+        title,
+      },
+      spec,
+    },
+  } = entry
+
+  await fs.writeFile(
+    path.join(logFilePath(), 'performance.log'),
+    [startTime, duration, name, numElements, title, spec].join(',') + '\n',
+    { flag: 'a' },
+  )
+}

packages/server/lib/browsers/bidi_automation.ts

@@ -726,6 +726,8 @@ export class BidiAutomation {
 
           throw new Error('Cannot get AUT title no AUT context initialized')
         }
+        case 'log:command:performance':
+          return recordPerformanceEntry(data)
         default:
           debug('BiDi automation not implemented for message: %s', message)
           throw new AutomationNotImplemented(message, 'BiDiAutomation')

packages/server/lib/browsers/cdp_automation.ts

@@ -8,7 +8,7 @@ import { parseDomain, isLocalhost as isLocalhostNetworkTools } from '@packages/n
 import debugModule from 'debug'
 import { URL } from 'url'
 import { performance } from 'perf_hooks'
-
+import { recordPerformanceEntry } from '../automation/commands/record_performance_entry'
 import type { ResourceType, BrowserPreRequest, BrowserResponseReceived } from '@packages/proxy'
 import type { CDPClient, ProtocolManagerShape, WriteVideoFrame, AutomationMiddleware, AutomationCommands } from '@packages/types'
 import type { Automation } from '../automation'
@@ -662,6 +662,8 @@ export class CdpAutomation implements CDPClient, AutomationMiddleware {
         return cdpNavigateHistory(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame(), data.historyNumber)
       case 'get:aut:title':
         return cdpGetFrameTitle(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame())
+      case 'log:command:performance':
+        return recordPerformanceEntry(data)
       default:
         throw new Error(`No automation handler registered for: '${message}'`)
     }

packages/server/lib/modes/index.ts

@@ -4,6 +4,7 @@ import _ from 'lodash'
 import { makeDataContext } from '../makeDataContext'
 import { id as randomId } from '../util/random'
 import { telemetry } from '@packages/telemetry'
+import { initializePerformanceLogFile } from '../automation/commands/record_performance_entry'
 
 export = (mode, options) => {
   if (mode === 'smokeTest') {
@@ -24,6 +25,9 @@ export = (mode, options) => {
   }
 
   const span = telemetry.startSpan({ name: `initialize:mode:${mode}` })
+
+  initializePerformanceLogFile()
+
   const ctx = setCtx(makeDataContext({ mode: mode === 'run' ? mode : 'open', modeOptions: options }))
 
   telemetry.getSpan('cypress')?.setAttribute('name', `cypress:${mode}`)

packages/types/src/server.ts

@@ -125,6 +125,20 @@ export interface KeyPressParams {
   key: SupportedKey
 }
 
+export interface CommandPerformanceEntry {
+  name: string
+  startTime: number
+  duration: number
+  detail: {
+    runnable: {
+      type: string
+      title: string
+    }
+    spec: string
+    numElements: number
+  }
+}
+
 export interface AutomationCommands {
   'take:screenshot': CommandSignature
   'get:cookies': CommandSignature
@@ -151,6 +165,7 @@ export interface AutomationCommands {
   'reload:aut:frame': CommandSignature<{ forceReload: boolean }, void>
   'navigate:aut:history': CommandSignature<{ historyNumber: number }, void>
   'get:aut:title': CommandSignature<void, string>
+  'log:command:performance': CommandSignature<CommandPerformanceEntry, void>
 }
 
 export type OnRequestEvent = <T extends keyof AutomationCommands>(message: T, data: AutomationCommands[T]['dataType']) => Promise<AutomationCommands[T]['returnType']>