MetaMask / MetaMask/metamask-extension

[P0] Benchmark step timers measure the test harness, not the browser

Open
#46,006 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

INVALID-ISSUE-TEMPLATE Sev2-normal ta-needs-engineer-escalation ta-triaged team-qa
Dominant language
TypeScript
Stars
13.2k
Forks
5.6k
Avg merge
2d 5h
Merged PRs (30d)
451

Description

**Parent Epic:** [#6944 Performance Quality Gates](https://github.com/MetaMask/MetaMask-planning/issues/6944) → [#7182 Benchmarks: Reliability](https://github.com/MetaMask/MetaMask-planning/issues/7182) → [#7181 Benchmark Harness Fixes](https://github.com/MetaMask/MetaMask-planning/issues/7181)
**File:** `test/e2e/benchmarks/utils/timer-helper.ts` (at `2bc3d379f1c`)
**Size:** L | **Hours:** ~16-24

---

## Problem

Every CUF step timer runs its clock in the Node test process, not in the browser, so each measured interval is app work plus WebDriver round-trip plus poll interval with no way to separate them.

`TimerHelper.getDuration()` returns [`performance.now() - timer.start`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/benchmarks/utils/timer-helper.ts#L29-L42), evaluated in the test runner. [`measure(action)`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/benchmarks/utils/timer-helper.ts#L55-L63) opens the timer, awaits `action()`, and closes it — and every `action` the flows pass is a `driver` call.

This is distinct from [#45452 benchmark step timers are not a disjoint partition of the flow they measure](https://github.com/MetaMask/metamask-extension/issues/45452) and survives fixing it. That ticket is about where the boundaries fall; this is about what sits inside them. Boundaries that partition the flow perfectly still bill the harness to the app.

### Mechanism — two harness terms, not one

A step that closes on a wait is quantized to the poll interval. [`driver.js:532-534`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/webdriver/driver.js#L532-L534) calls `this.driver.wait(condition, timeout)` and never passes a fourth argument, so it takes `selenium-webdriver@4.44.0`'s default of `pollTimeout = 200` (`lib/webdriver.js:848`). The metric cannot resolve anything finer than 200 ms, and each poll cycle is a further round-trip.

`swap.fetchAndDisplaySwapQuotes` is the clearest case — it wraps `await swapPage.checkQuoteIsDisplayed({ timeout: 60000 })`, a polled wait, so the published number is `ceil(true_duration / 200) * 200` plus round-trips.

A step that closes on a direct driver call carries only the round-trip. `sendTransactions.openSendPageFromHome` has a p50 of 15 ms and `onboardingImportWallet.metricsToWalletReadyScreen` 31 ms, both under one poll cycle, so the round-trip term alone is on the order of tens of milliseconds. Small, but still not the app.

### Prior art — this mechanism exists and has an author

The in-page readback this ticket proposes extending was built in [#27701 perf: include custom traces in benchmark results](https://github.com/MetaMask/metamask-extension/pull/27701) (`85bf4c361cc`, 2024-10-15), which added `stateHooks.getCustomTraces` and wired it through exactly the four files that still carry it: `shared/lib/trace.ts`, `test/e2e/webdriver/driver.js`, `types/global.d.ts`, and the benchmark entry point of the day.

So this is not a new approach. It is applying an existing one to the steps that never received it — the CUF flows were written against `TimerHelper` instead, and the two mechanisms have coexisted since.

### The positive control is already in this repo

The startup flows do not have this defect, which is what shows the fix is available rather than hypothetical.

[`standard-home.ts:48`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/benchmarks/flows/startup/standard-home.ts#L48) calls `driver.collectMetrics()`, which is [`executeScript(collectMetrics)`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/webdriver/driver.js#L2114-L2147) — the function runs inside the page and reads `performance.getEntriesByType('navigation')` and `window.stateHooks.getCustomTraces()`. `startupStandardHome.load` is `navigationEntry.loadEventEnd`, computed by the browser against navigation start.

`startupStandardHome.loadScripts` is stronger still. Its trace reduces to a single in-page clock read ([`ui.js:79-95`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/app/scripts/ui.js#L79-L95)): `trace()` opens at `performance.timeOrigin` and `endTrace()` closes at `performance.timeOrigin + startTime`, so the duration is exactly `performance.now()` at entry to `start()`. Nothing is bracketed, so nothing can leak in. It rides the app's production `trace()` path, and `durationsByName` is a plain local map populated independent of Sentry sampling ([`trace.ts:123-127`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L123-L127)).

### Scope — 9 of the 12 gated timing metrics

| clock | count | metrics |
|---|---|---|
| in-page (browser) | 2 | `startupStandardHome.load`, `loadScripts` |
| in-page, app-defined marks | 1 | `startupStandardHome.uiStartup` |
| Node test process | **9** | `importSrpHome.loginToHomeScreen`, `homeAfterImportWithNewWallet`, `swap.fetchAndDisplaySwapQuotes`, `sendTransactions.openSendPageFromHome`, `onboardingImportWallet.metricsToWalletReadyScreen`, `onboardingNewWallet.agreeButtonToOnboardingSuccess`, and the three `.total` values built by summing them |

`onboardingImportWallet.total`, `importSrpHome.total` and `swap.total` inherit the Node-process clock by construction. [`performance-tracker.ts:63-80`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/test/e2e/benchmarks/utils/performance-tracker.ts#L63-L80) sums exactly the step durations it records, so every round-trip and poll cycle inside a step is also inside the flow total.

### Why this is not reachable by any fix currently planned

Threshold recalibration ([#43070 empirical threshold recalibration query](https://github.com/MetaMask/metamask-extension/pull/43070)) re-derives ceilings from the same numbers, so it moves the line and not the measurement. Deterministic waits ([#7202 deterministic render-complete waits for account menu and swap](https://github.com/MetaMask/MetaMask-planning/issues/7202)) remove the *variance* in how many poll cycles elapse but not the cycles themselves. Disjoint boundaries ([#45452](https://github.com/MetaMask/metamask-extension/issues/45452)) fix where the harness cost is billed, not that it is billed. Each is worth doing and none of them makes a CUF step timer measure the application.

---

## Solution

1. Move the clock into the page. Bracket each CUF step with `trace()` / `endTrace()` from `shared/lib/trace.ts`, read back through `stateHooks.getCustomTraces()` — the mechanism `startupStandardHome.loadScripts` already uses.

**Use the no-callback form, and only that form.** `trace.ts` carries two clocks. `trace(request)` with no callback routes to [`startTrace`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L689-L714), which stamps `getPerformanceTimestamp()` — `performance.timeOrigin + performance.now()`, monotonic and sub-millisecond. `trace(request, fn)` routes to [`traceCallback`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L402-L433), which stamps `Date.now()` at both ends — millisecond resolution on a wall clock that can step. Both write to the same `durationsByName`, so the two are indistinguishable downstream. The callback form is the ergonomic one for wrapping a step, which makes it the one a reader reaches for by default.

That divergence is worth a separate fix and is not in this ticket's scope: a benchmark-grade timer has no reason to be on `Date.now()`, and nothing marks which form produced a given entry.

`trace()` is the Sentry integration — it imports `@sentry/browser` types, its `TraceContext` is `Sentry.Span | null`, and `startTrace` runs through `sentryStartSpanManual`. Using it here does not make the benchmark depend on Sentry, and the reason is a checkable one rather than an argument. [`sentryStartSpanManual`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L687-L698) is `const actual = globalThis.sentry?.startSpanManual; if (!actual) return callback(null);`, so with Sentry unloaded the pending trace is still built with `span: null`. The duration is then computed entirely from the browser clock and written to a local map: [`getPerformanceTimestamp()`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L601-L603) returns `performance.timeOrigin + performance.now()`, and [`logTrace`](https://github.com/MetaMask/metamask-extension/blob/2bc3d379f1c3c23526ee782a695a330a2dd3f910/shared/lib/trace.ts#L574-L587) writes `durationsByName[name] = endTime - startTime` under a single `process.env.IN_TEST` guard, with no span, sampling or `hasSpansEnabled()` check on that path.

Three constraints this puts on the design. The map is populated only in test builds, which is where benchmarks run. `trace()` records in whichever realm the module is loaded, so a step whose boundaries fall in different realms — UI page opening it, background worker closing it — needs its boundaries chosen within one realm, or a defined way to join them.

And `durationsByName` is flat: `{ [name: string]: number }`, a name and a duration with no parent. Any parent-child structure lives in the Sentry span, which this readback path does not expose. That is sufficient for this ticket, whose objective is the interval and not the tree — but it means fixing this does not advance passive attribution, and a step that needs to be decomposed later will need a different readback than `getCustomTraces()`.
2. Where a step has no natural app-side trace boundary, mark it with `performance.mark()` in the page and read the measure back, rather than timing the driver call.
3. Keep the harness-side timer as a separate, explicitly-named metric. The wall-clock cost of a flow is a real thing to watch; it is just not the app's latency, and it should not share a name with it.
4. Until 1-3 land, publish the poll interval beside every wait-terminated metric so a reader can see the resolution floor.

---

## Acceptance Criteria

- [ ] Each gated CUF step metric is derived from a clock read inside the browser
- [ ] No gated metric's value can change when only `pollTimeout` changes; a test asserts this by varying it
- [ ] Harness wall-clock is still published, under a name that does not claim to be app latency
- [ ] The three `.total` values are recomputed from in-page spans rather than summed harness timers
- [ ] `startupStandardHome.load` and `loadScripts` are documented as the reference implementation

---

## Labels

`team-extension-platform`, `area-testSuite`

---

## Dependencies

**Related:** [#45452 benchmark step timers are not a disjoint partition of the flow they measure](https://github.com/MetaMask/metamask-extension/issues/45452), [#45266 onboarding benchmarks are bimodal](https://github.com/MetaMask/metamask-extension/issues/45266) (the polled wait quantizing to its interval is this defect's most visible symptom), [#7280 fix onboarding password-transition timers that measure near-empty windows](https://github.com/MetaMask/MetaMask-planning/issues/7280), [#45205 restore benchmark gate signal](https://github.com/MetaMask/metamask-extension/issues/45205), [#45935 the gate's only blocking metric has overlapping pass and fail ranges](https://github.com/MetaMask/metamask-extension/issues/45935)

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with test/e2e/benchmarks/utils/timer-helper.ts and compare its timing with startupStandardHome.loadScripts, driver.collectMetrics(), and shared/lib/trace.ts. Trace the nine Node-timed gated metrics and the three .total values, then verify against the acceptance criteria, including varying pollTimeout and preserving a separately named harness metric.

Written by the indexing model from the issue text.

Assessment

Tech stack
typescript
Domain
performance, testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
42/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.