misc: write command durations to a csv file

cli/CHANGELOG.md

@@ -30,6 +30,7 @@ _Released 11/19/2025_
 
 - 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/app/src/runner/events/telemetry.ts

@@ -1,104 +1,149 @@
 import { telemetry } from '@packages/telemetry/browser/client'
 
-export const addTelemetryListeners = (Cypress: Cypress.Cypress) => {
-  Cypress.on('test:before:run', (attributes, test) => {
-    // we emit the 'test:before:run' events within various driver tests
-    try {
-      // If a span for a previous test hasn't been ended, end it before starting the new test span
-      const previousTestSpan = telemetry.findActiveSpan((span) => {
-        return span.name.startsWith('test:')
-      })
-
-      if (previousTestSpan) {
-        telemetry.endActiveSpanAndChildren(previousTestSpan)
-      }
+function startTestOtelSpan (attributes: Cypress.ObjectLike, test: Mocha.Test) {
+  // we emit the 'test:before:run' events within various driver tests
+  try {
+    // If a span for a previous test hasn't been ended, end it before starting the new test span
+    const previousTestSpan = telemetry.findActiveSpan((span) => {
+      return span.name.startsWith('test:')
+    })
+
+    if (previousTestSpan) {
+      telemetry.endActiveSpanAndChildren(previousTestSpan)
+    }
 
-      const span = telemetry.startSpan({ name: `test:${test.fullTitle()}`, active: true })
+    const span = telemetry.startSpan({ name: `test:${test.fullTitle()}`, active: true })
 
-      span?.setAttributes({
-        currentRetry: attributes.currentRetry,
-      })
-    } catch (error) {
-      // TODO: log error when client side debug logging is available
-    }
-  })
+    span?.setAttributes({
+      currentRetry: attributes.currentRetry,
+    })
+  } catch (error) {
+    // TODO: log error when client side debug logging is available
+  }
+}
 
-  Cypress.on('test:after:run', (attributes, test) => {
-    try {
-      const span = telemetry.getSpan(`test:${test.fullTitle()}`)
+function endTestOtelSpan (attributes: Cypress.ObjectLike, test: Mocha.Test) {
+  try {
+    const span = telemetry.getSpan(`test:${test.fullTitle()}`)
 
-      span?.setAttributes({
-        timings: JSON.stringify(attributes.timings),
-      })
+    span?.setAttributes({
+      timings: JSON.stringify(attributes.timings),
+    })
 
-      span?.end()
-    } catch (error) {
-      // TODO: log error when client side debug logging is available
-    }
-  })
+    span?.end()
+  } catch (error) {
+    // TODO: log error when client side debug logging is available
+  }
+}
 
-  const commandSpanInfo = (command: Cypress.CommandQueue) => {
-    const runnable = Cypress.state('runnable')
-    const runnableType = runnable.type === 'hook' ? runnable.hookName : runnable.type
+const commandSpanInfo = (command: Cypress.CommandQueue) => {
+  const runnable = Cypress.state('runnable')
+  const runnableType = runnable.type === 'hook' ? runnable.hookName : runnable.type
 
-    return {
-      name: `${runnableType}: ${command.attributes.name}(${command.attributes.args.join(',')})`,
-      runnable,
-      runnableType,
-    }
+  return {
+    name: `${runnableType}: ${command.attributes.name}(${command.attributes.args.join(',')})`,
+    runnable,
+    runnableType,
   }
+}
 
-  Cypress.on('command:start', (command: Cypress.CommandQueue) => {
-    try {
-      const test = Cypress.state('test')
-
-      const { name, runnable, runnableType } = commandSpanInfo(command)
-
-      const span = telemetry.startSpan({
-        name,
-        opts: {
-          attributes: {
-            spec: runnable.invocationDetails.relativeFile,
-            test: `test:${test.fullTitle()}`,
-            'runnable-type': runnableType,
-          },
+function startCommandOtelSpan (command: Cypress.CommandQueue) {
+  try {
+    const test = Cypress.state('test')
+
+    const { name, runnable, runnableType } = commandSpanInfo(command)
+
+    const span = telemetry.startSpan({
+      name,
+      opts: {
+        attributes: {
+          spec: runnable.invocationDetails.relativeFile,
+          test: `test:${test.fullTitle()}`,
+          'runnable-type': runnableType,
         },
-        isVerbose: true,
-      })
+      },
+      isVerbose: true,
+    })
 
-      span?.setAttribute('command-name', command.attributes.name)
-    } catch (error) {
-    // TODO: log error when client side debug logging is available
-    }
-  })
+    span?.setAttribute('command-name', command.attributes.name)
+  } catch (error) {
+  // TODO: log error when client side debug logging is available
+  }
+}
 
-  const onCommandEnd = (command: Cypress.CommandQueue) => {
-    try {
-      const span = telemetry.getSpan(commandSpanInfo(command).name)
+function endCommandOtelSpan (command: Cypress.CommandQueue) {
+  try {
+    const span = telemetry.getSpan(commandSpanInfo(command).name)
 
-      span?.setAttribute('state', command.state)
-      span?.setAttribute('numLogs', command.logs?.length || 0)
-      span?.end()
-    } catch (error) {
-    // TODO: log error when client side debug logging is available
-    }
+    span?.setAttribute('state', command.state)
+    span?.setAttribute('numLogs', command.logs?.length || 0)
+    span?.end()
+  } catch (error) {
+  // TODO: log error when client side debug logging is available
   }
+}
 
-  Cypress.on('command:end', onCommandEnd)
+function failCommandOtelSpan (command: Cypress.CommandQueue, error: Error) {
+  try {
+    const span = telemetry.getSpan(commandSpanInfo(command).name)
 
-  Cypress.on('skipped:command:end', onCommandEnd)
+    span?.setAttribute('state', command.state)
+    span?.setAttribute('numLogs', command.logs?.length || 0)
+    span?.setAttribute('error.name', error.name)
+    span?.setAttribute('error.message', error.message)
+    span?.end()
+  } catch (error) {
+    // TODO: log error when client side debug logging is available
+  }
+}
 
-  Cypress.on('command:failed', (command: Cypress.CommandQueue, error: Error) => {
+function startCommandPerformanceMark (command: Cypress.CommandQueue) {
+  try {
+    performance.mark(`cy:command:${command.attributes.id}:start`)
+  } catch (error) {
+  // TODO: log error when client side debug logging is available
+  }
+}
+
+function endCommandPerformanceMark (Cypress: Cypress.Cypress) {
+  return (command: Cypress.CommandQueue) => {
     try {
-      const span = telemetry.getSpan(commandSpanInfo(command).name)
+      const { id } = command.attributes
+
+      performance.mark(`cy:command:${id}:end`)
+      const measure = performance.measure(`cy:command:${id}:measure`, {
+        start: `cy:command:${id}:start`,
+        end: `cy:command:${id}:end`,
+      })
+
+      if (!measure) {
+        return
+      }
 
-      span?.setAttribute('state', command.state)
-      span?.setAttribute('numLogs', command.logs?.length || 0)
-      span?.setAttribute('error.name', error.name)
-      span?.setAttribute('error.message', error.message)
-      span?.end()
+      Cypress.automation('log:command:performance', {
+        name: command.attributes.name,
+        startTime: measure.startTime,
+        duration: measure.duration,
+      }).catch(() => {}).finally(() => {
+        performance.clearMarks(`cy:command:${id}:start`)
+        performance.clearMarks(`cy:command:${id}:end`)
+        performance.clearMeasures(`cy:command:${id}:measure`)
+      })
     } catch (error) {
-    // TODO: log error when client side debug logging is available
+      // noop
     }
-  })
+  }
+}
+
+export const addTelemetryListeners = (Cypress: Cypress.Cypress) => {
+  Cypress.on('test:before:run', startTestOtelSpan)
+  Cypress.on('test:after:run', endTestOtelSpan)
+  Cypress.on('command:start', startCommandOtelSpan)
+  Cypress.on('command:end', endCommandOtelSpan)
+  Cypress.on('command:failed', failCommandOtelSpan)
+  Cypress.on('skipped:command:end', endCommandOtelSpan)
+
+  Cypress.on('command:start', startCommandPerformanceMark)
+  Cypress.on('command:end', endCommandPerformanceMark(Cypress))
+  Cypress.on('skipped:command:end', endCommandPerformanceMark(Cypress))
 }

packages/driver/cypress/e2e/commands/location.cy.js

@@ -424,7 +424,7 @@ describe('src/cy/commands/location', () => {
         // 1. initial call cy.location('pathname')
         // 2. the should() assertion
         // 3. the then() callback
-        expect(Cypress.automation).to.have.been.calledThrice
+        expect(Cypress.automation.withArgs('get:aut:url')).to.have.been.calledThrice
       })
     })
 

packages/driver/src/cypress/command_queue.ts

@@ -339,7 +339,7 @@ export class CommandQueue extends Queue<$Command> {
 
       return ret
     })
-    .then((subject) => {
+    .then(async (subject) => {
       // we may be given a regular array here so
       // we need to re-wrap the array in jquery
       // if that's the case if the first item

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 { PerformanceLogger } from './performance_logger'
 
 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 PerformanceLogger.write(data)
         default:
           return automate(data)
       }

packages/server/lib/automation/automation_not_implemented.ts

@@ -2,7 +2,7 @@ const AutomationNotImplementedKind = 'AutomationNotImplemented'
 
 export class AutomationNotImplemented extends Error {
   readonly kind = AutomationNotImplementedKind
-  constructor (message: string, automationType: string, ...args) {
+  constructor (message: any, automationType: string, ...args) {
     super(`Automation command '${message}' not implemented by ${automationType}`)
   }