Commit 7f6211c
authored
test(e2e): instrument common spans for wall-clock tracking (#24407)
## Motivation
A-1178 (#24281) measures each e2e test's wall-clock as four coarse
buckets (`setupFnMs`, `beforeHooksMs`, `bodyMs`, `afterHooksMs`). That
tells us a test is slow but not *where* it loses time. Most e2e tests
spend their wall-clock in the same handful of operations — standing up
the environment, waiting for a tx to be mined/checkpointed/proven,
waiting for a committee to form or an offense to be detected,
client-side proving of seed txs, and warp scans hunting for a proposer
slot.
This decomposes that time into **named spans** so a single aggregate
query over a full CI run answers *"across the suite, how much total
wall-clock goes into proving / spinning up nodes / waiting for
checkpoints?"* — a ranked list of where to invest in speedups. It
extends A-1178 and builds on the consolidation (#24201/#24310) and
helpers (#24404) work that turned each repeated operation into one
shared definition, so wrapping it once instruments every test with no
per-test edits.
This is **instrumentation / data-gathering only** — no test behavior or
timing changes.
## Approach
- A generic `testSpan(name, fn)` / `testSpanSync(name, fn)` wrapper
(`fixtures/timing.ts`) records `{ owner, name, start, end }` into the
shared collector installed by the timing environment. When
`TEST_TIMING_FILE` is unset there is no collector, so `testSpan()` calls
`fn()` directly — exactly zero-cost, with no clock reads.
- At flush, the timing environment groups spans by owner then tag and
computes four numbers per `(owner, tag)`:
- `count` — multiplicity is itself a signal (waited for a checkpoint 14×
points at a loop to batch).
- `totalMs` — naive sum (correct for serial repeats).
- `busyMs` — duration of the **union** of the spans' intervals;
concurrency-correct, so a `Promise.all` of 12 concurrent 3s spans reads
~3s instead of ~36s. The `busyMs ≪ totalMs` signature flags work that is
run serially where it could be parallel.
- `maxMs` — longest single occurrence, to catch one pathological wait
hiding in a cheap average.
- The aggregates attach as an additive `spans` map on each `type:"test"`
/ `type:"suite"` JSONL line. `setupFnMs` / `teardownFnMs` are kept for
back-compat, now derived from the `setup:env:<mode>` / `teardown:env`
tags.
- Tags follow a stable `category:label` taxonomy (`setup:`, `wait:`,
`tx:`, `warp:`, `wallet:`, `deploy:`, `other:`), tagged **by concept,
not by function** — e.g. every checkpoint waiter maps to
`wait:checkpoint` — so a label is a forever aggregation key regardless
of which helper a test happened to call.
- **One clock.** All spans use `performance.now()`. I verified Node's
`perf_hooks` clock is process-wide: a `performance.now()` taken inside a
fresh `vm` context (the jest sandbox realm) shares the same monotonic
origin as the host realm (delta ~0.002ms; a fresh
`perf_hooks.performance` inside a separate context anchors to the same
`timeOrigin`). Interval-merging for `busyMs` across the sandbox and host
realms is therefore valid, so **`busyMs` is included** (no fallback to
`totalMs`-only needed).
- **Background loop.** `startMempoolFeeder` runs interleaved with
arbitrary tests; without care its prove/send spans would smear onto
whichever test was current when each round fired. Its production is run
inside an `AsyncLocalStorage`-scoped owner override
(`other:mempool-feeder`), which pins every span in its async call tree
to a fixed owner — isolated from concurrent test-body spans. That owner
matches no test/suite record, so the feeder's spans are cleanly excluded
from the per-test view.
## Changes by phase
- **Phase 0 — collector + `testSpan()` + flush aggregation.** New
`fixtures/timing.ts` (`testSpan`/`testSpanSync`/`withTestSpanOwner`).
`timing_env.mjs` collector generalized from `fnSpans` to a `spans`
array; `finalizeAndFlush` groups by owner/tag, merges intervals for
`busyMs`, attaches the `spans` map, and derives the back-compat fields.
- **Phase 1 — shared waits + `setup:node`.** Wrapped the waiters in
`fixtures/wait_helpers.ts` (`wait:proposed` / `wait:proven`,
`wait:checkpoint` / `wait:proven-checkpoint`, `wait:tx-mined`,
`wait:l2-to-l1-witness`, `wait:pending-tx`, `wait:sequencer-state`) and
the wait methods on `SingleNodeTestContext` / `MultiNodeTestContext`
(`wait:epoch`, `wait:slot`, `wait:proof-window`, `wait:node-sync`,
`wait:proof-submitted`, `wait:offense`, the multi-node
`wait:checkpoint`/`wait:proven-checkpoint`/`wait:block` convergence
waiters). Wrapped `createNode`/`createProverNode` with `setup:node`.
- **Phase 2 — decompose `setup:env`.** Cracked the opaque setup in
`fixtures/setup.ts` into `setup:env:anvil`, `:l1-deploy`,
`:sequencer-start`, `:prover-node`, `:pxe`, and `wallet:create`. The
top-level `setup:env` is tagged with the prover mode (`setup:env:none` /
`:fake` / `:real`) so the three factories are comparable.
- **Phase 3 — tx leaf wraps.** `proveInteraction` → `tx:prove`,
`ProvenTx.send` → `tx:send`; everything else
(`proveTxs`/`proveAndSendTxs`/the submit helpers) aggregates through
those leaves. `startMempoolFeeder` handled as above.
- **Phase 4 — slashing/governance waiters.** Wrapped
`awaitCommitteeExists` (`wait:committee`), `awaitOffenseDetected`
(`wait:offense`), `awaitCommitteeKicked` (`wait:committee-kicked`),
`awaitProposalExecution` (`wait:slash-execution`), and the
`findUpcomingProposerSlot` / `advanceToEpochBeforeProposer` /
`findSlotsWithProposers` scans (`warp:find-proposer`).
- **Phase 5 — reporting.** The JSONL schema now carries the per-line
`spans` map, and `TEST_TIMING_SPANS=1` emits one `type:"span"` line per
occurrence (owner, name, ms) for deep dives. The repo now also ships a
`track-e2e-times` skill (`yarn-project/.claude/skills/track-e2e-times/`)
covering how to **collect and aggregate** the span timings locally: run
the suite with `TEST_TIMING_FILE` set, find the per-worker JSONL, and
print per-test sums plus the ranked span leaderboard (via the bundled
`row.sh`). Only the step of publishing aggregate numbers to a running
tracking log remains a separate out-of-band workflow. The leaderboard
rollup is a small additive jq over the new `spans` maps:
```
jq -rs '[ .[] | select(.type=="test" or .type=="suite") | (.spans // {})
| to_entries[] ]
| group_by(.key)
| map({ tag: .[0].key, count: (map(.value.count) | add),
busyMs: (map(.value.busyMs) | add), maxMs: (map(.value.maxMs) | max) })
| sort_by(-.busyMs) | .[] | "\(.busyMs)\t\(.count)\t\(.maxMs)\t\(.tag)"'
```
The existing `row.sh` is unaffected — it filters `type=="test"` and
reads the unchanged `setupFnMs`/`bodyMs`/etc., ignoring the new `spans`
key and `type:"span"` lines.
## Notes
- `waitForEpoch`/`waitForSlot` (added to `@aztec/ethereum`'s
`rollup_cheat_codes.ts` by #24404) are deliberately **not** instrumented
in-package: that package should not depend on the e2e timing collector,
and the `wait:epoch`/`wait:slot` concepts they cover are already
captured at the e2e-context wrapper layer (`waitUntilEpochStarts`, the
slot waiters). They have no e2e callers yet; a future call site picks
them up via its context wrapper.
- Spans do not partition `bodyMs` — a parent span includes its children,
so `sum(spans) ≠ bodyMs`. Tagging is at the leaf wait/setup/tx level
where additivity holds; the few intentional nests (e.g.
`wait:committee-kicked` contains `wait:slash-execution`) carry distinct
tags.
Verified: `yarn build`, `yarn lint end-to-end`, `yarn format --check
end-to-end` all pass. The flush aggregation (busyMs interval merge,
back-compat derivation, feeder-owner exclusion, opt-in raw lines) is
covered by unit tests in `end-to-end/src/shared/timing_env.test.ts`,
which exercise the extracted `aggregateSpans` / `foldSpansInto` pure
functions directly.
Fixes A-1179
## Example timing output
Each e2e test run in CI emits one JSONL record per test and per suite,
carrying a `spans` map keyed by `category:label` tag, where each value
is `{count, totalMs, busyMs, maxMs}` (`busyMs` is the de-overlapped
union duration, so concurrent occurrences of a span are counted once).
An illustrative `type:"test"` line from CI run 28469687883 (commit
de3635e):
```json
{
"suite": "optimistic.parallel",
"type": "test",
"name": "single-node/proving/optimistic happy path proves multiple epochs via checkpoint-driven flow",
"status": "passed",
"setupFnMs": 4707,
"beforeHooksMs": 4717,
"bodyMs": 327324,
"teardownFnMs": 615,
"afterHooksMs": 624,
"totalMs": 332668,
"startedAt": "2026-06-30T19:20:58.279Z",
"spans": {
"setup:env:anvil": {
"count": 1,
"totalMs": 82,
"busyMs": 82,
"maxMs": 82
},
"setup:env:l1-deploy": {
"count": 1,
"totalMs": 470,
"busyMs": 470,
"maxMs": 470
},
"setup:env:sequencer-start": {
"count": 1,
"totalMs": 3141,
"busyMs": 3141,
"maxMs": 3141
},
"setup:env:prover-node": {
"count": 1,
"totalMs": 139,
"busyMs": 139,
"maxMs": 139
},
"setup:env:pxe": {
"count": 1,
"totalMs": 391,
"busyMs": 391,
"maxMs": 391
},
"wallet:create": {
"count": 1,
"totalMs": 79,
"busyMs": 79,
"maxMs": 79
},
"setup:env:fake": {
"count": 1,
"totalMs": 4707,
"busyMs": 4707,
"maxMs": 4707
},
"wait:epoch": {
"count": 5,
"totalMs": 180210,
"busyMs": 180210,
"maxMs": 36067
},
"tx:prove": {
"count": 4,
"totalMs": 2123,
"busyMs": 2123,
"maxMs": 621
},
"tx:send": {
"count": 4,
"totalMs": 144305,
"busyMs": 144305,
"maxMs": 36124
},
"wait:proven-checkpoint": {
"count": 4,
"totalMs": 0,
"busyMs": 0,
"maxMs": 0
},
"wait:node-sync": {
"count": 4,
"totalMs": 401,
"busyMs": 401,
"maxMs": 101
},
"teardown:env": {
"count": 1,
"totalMs": 615,
"busyMs": 615,
"maxMs": 615
}
},
"commit": "de3635e74eb89071b52939d1583d072ba2c3852c",
"branch": "spl/a1179-track-common-spans",
"runId": "28469687883"
}
```1 parent 9dc804b commit 7f6211c
12 files changed
Lines changed: 1137 additions & 471 deletions
File tree
- yarn-project
- .claude/skills/track-e2e-times
- end-to-end/src
- fixtures
- multi-node
- slashing
- single-node
- test-wallet
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
| 1 | + | |
| 2 | + | |
| 3 | + | |
| 4 | + | |
| 5 | + | |
| 6 | + | |
| 7 | + | |
| 8 | + | |
| 9 | + | |
| 10 | + | |
| 11 | + | |
| 12 | + | |
| 13 | + | |
| 14 | + | |
| 15 | + | |
| 16 | + | |
| 17 | + | |
| 18 | + | |
| 19 | + | |
| 20 | + | |
| 21 | + | |
| 22 | + | |
| 23 | + | |
| 24 | + | |
| 25 | + | |
| 26 | + | |
| 27 | + | |
| 28 | + | |
| 29 | + | |
| 30 | + | |
| 31 | + | |
| 32 | + | |
| 33 | + | |
| 34 | + | |
| 35 | + | |
| 36 | + | |
| 37 | + | |
| 38 | + | |
| 39 | + | |
| 40 | + | |
| 41 | + | |
| 42 | + | |
| 43 | + | |
| 44 | + | |
| 45 | + | |
| 46 | + | |
| 47 | + | |
| 48 | + | |
| 49 | + | |
| 50 | + | |
| 51 | + | |
| 52 | + | |
| 53 | + | |
| 54 | + | |
| 55 | + | |
| 56 | + | |
| 57 | + | |
| 58 | + | |
| 59 | + | |
| 60 | + | |
| 61 | + | |
| 62 | + | |
| 63 | + | |
| 64 | + | |
| 65 | + | |
| 66 | + | |
| 67 | + | |
| 68 | + | |
| 69 | + | |
| 70 | + | |
| 71 | + | |
| 72 | + | |
| 73 | + | |
| 74 | + | |
| 75 | + | |
| 76 | + | |
| 77 | + | |
| 78 | + | |
| 79 | + | |
| 80 | + | |
| 81 | + | |
| 82 | + | |
| 83 | + | |
| 84 | + | |
| 85 | + | |
| 86 | + | |
| 87 | + | |
| 88 | + | |
| 89 | + | |
| 90 | + | |
| 91 | + | |
| 92 | + | |
| 93 | + | |
| 94 | + | |
| 95 | + | |
| 96 | + | |
| 97 | + | |
| 98 | + | |
| 99 | + | |
| 100 | + | |
| 101 | + | |
| 102 | + | |
| 103 | + | |
| 104 | + | |
| 105 | + | |
| 106 | + | |
| 107 | + | |
| 108 | + | |
| 109 | + | |
| 110 | + | |
| 111 | + | |
| 112 | + | |
| 113 | + | |
| 114 | + | |
| 115 | + | |
| 116 | + | |
| 117 | + | |
| 118 | + | |
| 119 | + | |
| 120 | + | |
| 121 | + | |
| 122 | + | |
| 123 | + | |
| 124 | + | |
| 125 | + | |
| 126 | + | |
| 127 | + | |
| 128 | + | |
| 129 | + | |
| 130 | + | |
| 131 | + | |
| 132 | + | |
| 133 | + | |
| 134 | + | |
| 135 | + | |
| 136 | + | |
| 137 | + | |
| 138 | + | |
| 139 | + | |
| 140 | + | |
| 141 | + | |
| 142 | + | |
| 143 | + | |
| 144 | + | |
| 145 | + | |
| 146 | + | |
| 147 | + | |
| 148 | + | |
| 149 | + | |
| 150 | + | |
| 151 | + | |
| 152 | + | |
| 153 | + | |
| 154 | + | |
| 155 | + | |
| 156 | + | |
| 157 | + | |
| 158 | + | |
| 159 | + | |
| 160 | + | |
| 161 | + | |
| 162 | + | |
| 163 | + | |
| 164 | + | |
| 165 | + | |
| 166 | + | |
| 167 | + | |
| 168 | + | |
| 169 | + | |
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
| 1 | + | |
| 2 | + | |
| 3 | + | |
| 4 | + | |
| 5 | + | |
| 6 | + | |
| 7 | + | |
| 8 | + | |
| 9 | + | |
| 10 | + | |
| 11 | + | |
| 12 | + | |
| 13 | + | |
| 14 | + | |
| 15 | + | |
| 16 | + | |
| 17 | + | |
| 18 | + | |
| 19 | + | |
| 20 | + | |
| 21 | + | |
| 22 | + | |
| 23 | + | |
| 24 | + | |
| 25 | + | |
| 26 | + | |
| 27 | + | |
| 28 | + | |
| 29 | + | |
| 30 | + | |
| 31 | + | |
| 32 | + | |
| 33 | + | |
| 34 | + | |
| 35 | + | |
| 36 | + | |
| 37 | + | |
| 38 | + | |
| 39 | + | |
| 40 | + | |
| 41 | + | |
| 42 | + | |
| 43 | + | |
| 44 | + | |
| 45 | + | |
| 46 | + | |
| 47 | + | |
| 48 | + | |
| 49 | + | |
| 50 | + | |
| 51 | + | |
| 52 | + | |
| 53 | + | |
| 54 | + | |
| 55 | + | |
| 56 | + | |
| 57 | + | |
| 58 | + | |
| 59 | + | |
| 60 | + | |
| 61 | + | |
| 62 | + | |
| 63 | + | |
| 64 | + | |
| 65 | + | |
| 66 | + | |
| 67 | + | |
| 68 | + | |
| 69 | + | |
| 70 | + | |
| 71 | + | |
| 72 | + | |
| 73 | + | |
| 74 | + | |
0 commit comments