Report where trace capture time goes, behind DEVTOOLS_CAPTURE_TIMING

Trace mode is slower than live mode because of the per-action capture, and
nothing measured where that time goes per platform, so any proposal to make
capture cheaper was a guess (#516). With DEVTOOLS_CAPTURE_TIMING set, every
capture records each probe's issue and settle times, its service time apart
from the time it queued behind the driver's earlier requests, and what
triggered it (an action, a wait's poll, a matcher's poll). At trace export
the run prints a summary per probe and writes the raw records as NDJSON.

It only measures: probe order, concurrency and what is captured are
unchanged, and with the variable unset no timer is created. All three JS
adapters get it from core; Python mirrors it, with the summary checked by
shared mirror vectors.

Refs #516

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Author: vishnuv688

.changeset/capture-timing.md

@@ -0,0 +1,7 @@
+---
+'@wdio/devtools-service': minor
+'@wdio/selenium-devtools': minor
+'@wdio/nightwatch-devtools': minor
+---
+
+Setting `DEVTOOLS_CAPTURE_TIMING=1` on a trace-mode run times every per-action capture. When the trace is written, the run prints a table with each probe's count, total, median, p95 and max (url, title, page source, accessibility tree, element list, screenshot, and the in-process step that builds the snapshot), plus how much of the run's wall time went to capturing. The raw records are appended to `capture-timing-<pid>.ndjson` beside the trace. Each record names the command and whether the capture was a wait's or a matcher's poll. The variable only measures: nothing is captured differently, and with it unset nothing is timed or written.

CLAUDE.md

@@ -211,7 +211,7 @@ The venv's editable install of `selenium_devtools` points at the primary checkou
 
 ### Logic implemented in both TypeScript and Python
 
-The Python adapter cannot import `core`, so some pure logic exists twice. `packages/shared/mirror-vectors.json` holds input/expected-output cases for it, one section per mirrored function; `packages/selenium-devtools/tests/mirror-vectors.test.ts` runs every section against the TypeScript side under `pnpm test`, and `packages/selenium-devtools-py/tests/test_mirror_vectors.py` runs the same file against the Python side in the Python CI job (whose path filter includes the file). Both runners refuse a section they do not handle. Covered today: assertion target resolution, native-session detection, run id, output directory, command row id range, wait poll keys, nested-wait identity, wait row naming (whose negated case the TypeScript runner skips, selenium-webdriver having no negated wait) and performance payload shaping; `notCovered` in the file says why screencast thinning is not. Add a case whenever a change touches either side of a mirrored function, and a section when new logic is mirrored, provided its output is deterministic without a driver. A deliberate difference between the two goes in the section's `notes`, not around the case.
+The Python adapter cannot import `core`, so some pure logic exists twice. `packages/shared/mirror-vectors.json` holds input/expected-output cases for it, one section per mirrored function; `packages/selenium-devtools/tests/mirror-vectors.test.ts` runs every section against the TypeScript side under `pnpm test`, and `packages/selenium-devtools-py/tests/test_mirror_vectors.py` runs the same file against the Python side in the Python CI job (whose path filter includes the file). Both runners refuse a section they do not handle. Covered today: assertion target resolution, native-session detection, run id, output directory, command row id range, wait poll keys, nested-wait identity, wait row naming (whose negated case the TypeScript runner skips, selenium-webdriver having no negated wait), performance payload shaping and the capture timing summary; `notCovered` in the file says why screencast thinning is not. Add a case whenever a change touches either side of a mirrored function, and a section when new logic is mirrored, provided its output is deterministic without a driver. A deliberate difference between the two goes in the section's `notes`, not around the case.
 
 ### Trace zips from older writers
 
@@ -393,6 +393,7 @@ Documented divergences from the conventions above. They exist today as debt to b
 
 ### What a per-action trace capture costs
 
+- **Measure before proposing a change: `DEVTOOLS_CAPTURE_TIMING=1`.** Every adapter then times each probe of each capture (issue and settle, so a probe's own service time is separable from its wait behind the probes the driver served first) and, when the trace is written, prints a per-probe table and appends the raw records to `capture-timing-<pid>.ndjson` beside the trace. The JS recording is `core/capture-timing.ts`, wired once in `captureActionSnapshot` and reported from `finalizeTraceExport`, so no adapter carries more than the capture's trigger (action, wait poll, matcher poll, final); Python mirrors it in `capture_timing.py`, held to the same summary by `mirror-vectors.json`. Off, it costs a flag read per capture. The per-platform commands are in the README's "Measuring capture cost".
 - **One capture per action means two driver round trips per action, and the platform decides which half is expensive.** Measured on Appium 3.7.0 / UiAutomator2 (emulator-5554, Android API 37, 1080×2424): `GET /screenshot` 1.18–2.22 s (steady ~1.20 s) at 1.86 MB, `GET /source` (page-source XML) 0.09–0.53 s at 40 KB, `window/rect` 0.015 s — the screenshot dominates by ~10× on Android. **iOS is unmeasured**; the issue claims the split inverts there, and the native example (`examples/wdio/mocha/wdio.native.conf.ts`) is what makes it measurable. Measured per action: two captures 2.41 s against one capture 1.19 s; end-to-end on the native example 19.1 s against 12.4 s, with live mode (no per-action capture) at 5.9 s. That is the case for the `beforeCommand` capture, and the reason an eager post-action capture is not worth re-adding: it cost a second capture per action and existed only to be patched by a `readyState` poll that could not tell a document that had not navigated yet from one that was loading.
 - **Locator generation from a native page source must stay linear, and iOS is where it did not.** Every native action snapshot builds element locators from the page-source XML (`core/locators`), and each uniqueness check was a `//*[@name="…"]` XPath run by the `xpath` library over the whole document, several per element. Measured on the iOS Settings page source tiled up: 38 KB 82 ms, 188 KB 1.4 s, 752 KB 23.5 s, which is what a reporter saw as trace mode adding 1.5 min to a 2 min 20 s iOS test while Android, with smaller flatter trees, added 10 s. `locators/xpath-index.ts` indexes the document once per `generateAllElementLocators` walk (`withXPathIndex`) and answers `//*`, `//Tag` and `//Tag[@a="x" and …]` from it: 15 ms, 49 ms, 268 ms for the same three, identical elements. It is scoped to the walk so a caller of the exported `evaluateXPath` that edits its document is never answered stale, and it declines a namespaced document, where XPath name tests resolve namespaces and the index does not. The page-source request itself remains: 0.75-1.2 s per action on XCUITest even for Settings, against 0.09-0.5 s on UiAutomator2.
 - A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending after the stop or clearing its successor's latch.

README.md

@@ -298,6 +298,54 @@ services: [[DevToolsHookService, {
 
 > **Requires BiDi.** Trace mode uses a WebDriver BiDi preload script. Both Chrome (≥114) and Firefox (≥130) enable BiDi automatically — no capability flags needed.
 
+#### Measuring capture cost
+
+A trace-mode run is slower than a live one because, for every action, the adapter reads the page through the driver: url, title, accessibility tree, element list and a screenshot, plus the page source on a native app. Set `DEVTOOLS_CAPTURE_TIMING=1` on a trace-mode run to see where that time goes. It only measures; nothing is captured differently, and with it unset nothing is timed or written.
+
+When the trace is written, the run prints a table to stderr and appends the raw records, one line per capture, to `capture-timing-<pid>.ndjson` beside the trace (one file per worker process):
+
+```text
+[devtools] capture timing: 4 captures (0 native; action 2, wait-poll 1, matcher-poll 1), busy 1.6 s of 10.0 s wall (15.8%)
+ms = issue to settle; the driver serves one request at a time, so svc (settle minus the previous probe's settle) is a probe's own cost and the rest is queueing
+probe (ms)  n  total  median   p95   max  svc total  svc median
+url         4     16       4     4     4         16           4
+screenshot  4   1616     254  1004  1004       1600         250
+process     4     24       6     6     6         24           6
+capture     4   1640     260  1010  1010       1640         260
+raw records: /out/capture-timing-1.ndjson
+```
+
+(Illustrative numbers from a unit-test fixture, not a real run.)
+
+- **Columns.** The JS adapters issue every read of a capture at once and the driver serves them in order, so a read's time from issue to settle includes waiting behind the reads before it. `svc` subtracts that wait: it is the read's own cost. `process` is the in-process step that turns the reads into a snapshot (page-source parsing and locator generation on native). `capture` is the whole capture.
+- **Busy and wall.** `busy` is the time at least one capture was running, overlapping captures counted once; `wall` is the time since the process started, or since the previous report in the same process.
+- **Triggers.** `action` is a capture for a user command, `wait-poll` one for a command a wait issued, `matcher-poll` one taken while a WebdriverIO `expect` matcher was polling, and `final` the WebdriverIO capture of the last action's result. Matcher polls are told apart on WebdriverIO only, and only with `captureAssertions` on; Selenium and Nightwatch matchers expose no hook to tell them by.
+- **Python.** It reads one thing at a time, so `svc` equals the read's duration; it records the screenshot and the two page reads, and has no url, title or `process` rows.
+
+To measure each platform from the repo's examples (the desktop examples other than Selenium's drive Chrome only):
+
+```sh
+# Desktop Chrome, one per adapter
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 pnpm demo:wdio
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 pnpm demo:selenium
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 pnpm demo:nightwatch
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 pnpm demo:python:pytest
+
+# Desktop Firefox and Safari, through selenium-webdriver's SELENIUM_BROWSER (Safari needs `safaridriver --enable` once)
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 SELENIUM_BROWSER=firefox pnpm --filter @wdio/selenium-devtools example:mocha
+DEVTOOLS_MODE=trace DEVTOOLS_CAPTURE_TIMING=1 SELENIUM_BROWSER=safari pnpm --filter @wdio/selenium-devtools example:mocha
+
+# Android native (Clock app) and Android Chrome (prerequisites in examples/MOBILE.md)
+DEVTOOLS_CAPTURE_TIMING=1 pnpm demo:wdio:mobile
+DEVTOOLS_CAPTURE_TIMING=1 DEVTOOLS_MOBILE=web pnpm demo:wdio:mobile
+
+# iOS native (Settings) and iOS Safari
+DEVTOOLS_CAPTURE_TIMING=1 DEVTOOLS_MOBILE_PLATFORM=ios pnpm demo:wdio:mobile
+DEVTOOLS_CAPTURE_TIMING=1 DEVTOOLS_MOBILE_PLATFORM=ios DEVTOOLS_MOBILE=web pnpm demo:wdio:mobile
+```
+
+The mobile lines work the same with `demo:selenium:mobile`, `demo:nightwatch:mobile` and `demo:python:mobile`, which also run in trace mode by default.
+
 #### 📱 Mobile testing
 
 Appium sessions are captured in both live and trace mode. What gets captured depends on one question — **does this session have a web document right now?** — because every DOM drain, page script and viewport read is a round trip that can only fail without one.

packages/conformance/src/capability-options.ts

@@ -98,7 +98,11 @@ export const PYTHON_OPTIONS: Record<string, OptionTarget> = {
   DEVTOOLS_FILMSTRIP: { feature: 'filmstrip' },
   DEVTOOLS_A11Y: { feature: 'a11y-overlay' },
   DEVTOOLS_TRACE_POLICY: { feature: 'retry-retention' },
-  DEVTOOLS_TRACE_GRANULARITY: { feature: 'per-test-granularity' }
+  DEVTOOLS_TRACE_GRANULARITY: { feature: 'per-test-granularity' },
+  DEVTOOLS_CAPTURE_TIMING: {
+    notFeature:
+      'A diagnostic that times trace capture; it changes nothing the run captures.'
+  }
 }
 
 export const OPTION_MAPS: Record<

packages/core/src/action-snapshot.ts

@@ -8,6 +8,7 @@ import {
   serializeMobileSnapshot
 } from './element-snapshot.js'
 import type { AccessibilityNode, BrowserElementInfo } from './element-types.js'
+import { performance } from 'node:perf_hooks'
 import { xmlToJSON } from './locators/xml-parsing.js'
 import {
   generateAllElementLocators,
@@ -18,7 +19,13 @@ import {
   SNAPSHOT_PROBE_TIMEOUT_MS,
   withTimeout
 } from './with-timeout.js'
-import type { ActionSnapshot, TestRunnerId } from '@wdio/devtools-shared'
+import { startCaptureTimer, type CaptureTimer } from './capture-timing.js'
+import type {
+  ActionSnapshot,
+  CaptureProbe,
+  CaptureTrigger,
+  TestRunnerId
+} from '@wdio/devtools-shared'
 
 export type ScriptRunner = (scriptSrc: string) => Promise<unknown>
 
@@ -40,6 +47,18 @@ export interface CaptureActionSnapshotInput {
   /** Runner this capture belongs to — decides which text-locator dialect the
    *  injected scripts emit. Omitted → the portable XPath form. */
   runner?: TestRunnerId
+  /** Why this capture ran, for the opt-in capture timing report. Omitted → `action`. */
+  trigger?: CaptureTrigger
+}
+
+/** `pending` unchanged; with a timer and a probe that will really be issued, also timed. */
+function timed<T>(
+  timer: CaptureTimer | undefined,
+  probe: CaptureProbe,
+  issued: unknown,
+  pending: Promise<T>
+): Promise<T> {
+  return timer && issued ? timer.track(probe, pending) : pending
 }
 
 async function runWith<T>(
@@ -123,41 +142,82 @@ function fromPageSource(
   }
 }
 
+/**
+ * Issue every probe of one capture together.
+ *
+ * Probe order is load-bearing, not cosmetic. A driver serialises requests per
+ * session, so `Promise.all` starting them together still has them served in
+ * the order issued, and the screenshot is by far the slowest. Issued first, it
+ * delayed the cheap reads behind it by hundreds of ms, long enough for the next
+ * command to navigate: a fill on the login page reported the page its submit
+ * had already reached. Cheapest-and-most-order-sensitive first, screenshot
+ * last; the screenshot is served no later than before.
+ */
+function readProbes(
+  input: CaptureActionSnapshotInput,
+  isNativeMobile: boolean,
+  timer: CaptureTimer | undefined
+) {
+  // The same pair the backend serves the Python adapter, so the two cannot
+  // capture different things. `elements` carries bounds: the per-action
+  // element rects drive A8 input points.
+  const scripts = buildElementScripts(input.runner)
+  return Promise.all([
+    timed(timer, 'url', input.getUrl, probe(input.getUrl)),
+    timed(timer, 'title', input.getTitle, probe(input.getTitle)),
+    isNativeMobile
+      ? timed(timer, 'pageSource', true, probe(input.getPageSource))
+      : undefined,
+    timed(
+      timer,
+      'accessibilityTree',
+      input.runScript,
+      runWith<AccessibilityNode[]>(
+        input.runScript,
+        scripts.accessibilityTree,
+        []
+      )
+    ),
+    timed(
+      timer,
+      'elements',
+      input.runScript,
+      runWith<BrowserElementInfo[]>(input.runScript, scripts.elements, [])
+    ),
+    timed(
+      timer,
+      'screenshot',
+      input.takeScreenshot,
+      probe(input.takeScreenshot)
+    )
+  ])
+}
+
 export async function captureActionSnapshot(
   input: CaptureActionSnapshotInput
 ): Promise<ActionSnapshot | null> {
   try {
     const timestamp = input.timestamp ?? Date.now()
     const isNativeMobile = !input.runScript && !!input.getPageSource
-    // The same pair the backend serves the Python adapter, so the two cannot
-    // capture different things. `elements` carries bounds — the per-action
-    // element rects drive A8 input points.
-    const scripts = buildElementScripts(input.runner)
-
-    // Probe order is load-bearing, not cosmetic. A driver serialises requests
-    // per session, so `Promise.all` starting them together still has them served
-    // in the order issued — and the screenshot is by far the slowest. Issued
-    // first, it delayed the cheap reads behind it by hundreds of ms, long enough
-    // for the next command to navigate: a fill on the login page reported the
-    // page its submit had already reached. Cheapest-and-most-order-sensitive
-    // first, screenshot last; the screenshot is served no later than before.
-    const [url, title, pageSource, tree, elements, shot] = await Promise.all([
-      probe(input.getUrl),
-      probe(input.getTitle),
-      isNativeMobile ? probe(input.getPageSource) : undefined,
-      runWith<AccessibilityNode[]>(
-        input.runScript,
-        scripts.accessibilityTree,
-        []
-      ),
-      runWith<BrowserElementInfo[]>(input.runScript, scripts.elements, []),
-      probe(input.takeScreenshot)
-    ])
+    const timer = startCaptureTimer(
+      input.command,
+      input.trigger ?? 'action',
+      isNativeMobile
+    )
+    const [url, title, pageSource, tree, elements, shot] = await readProbes(
+      input,
+      isNativeMobile,
+      timer
+    )
 
+    const processedFrom = timer ? performance.now() : 0
     const mobile =
       isNativeMobile && pageSource
         ? fromPageSource(pageSource, input.platform ?? 'android')
         : undefined
+    const snapshotText =
+      mobile?.snapshotText ?? serializeWebSnapshot(tree, { url, title })
+    timer?.finish(processedFrom)
 
     return {
       timestamp,
@@ -166,8 +226,7 @@ export async function captureActionSnapshot(
       title,
       screenshot: shot ?? undefined,
       elements: mobile?.elements ?? elements,
-      snapshotText:
-        mobile?.snapshotText ?? serializeWebSnapshot(tree, { url, title })
+      snapshotText
     }
   } catch {
     return null