Report where trace capture time goes, behind DEVTOOLS_CAPTURE_TIMING

.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