feat(e2e): track per-test setup/hook timings - #24281
Merged
PhilWindle merged 5 commits intoJun 26, 2026
Merged
Conversation
Capture per-test timing for e2e jest tests, distinguishing function-level time inside setup()/teardown() from hook-level time across jest before/after hooks. - Add a TimingEnvironment jest env (src/shared/timing_env.mjs) that subclasses foundation's CustomEnvironment, times circus hook/body/total events, and writes one JSONL file per worker process. Gated entirely on E2E_TIMING_FILE; a no-op delegate otherwise. - Instrument setup()/teardown() in fixtures/setup.ts to push function-level spans to a collector shared on the env's global, attributed to the running test (or the suite line during beforeAll). - exec_test sets E2E_TIMING_FILE and uploads the gzipped JSONL to s3://aztec-ci-artifacts/logs/e2e-timings/<RUN_ID>/<NAME>.log.gz after each test command. - Add a ci.sh e2e-timings <run_id> <folder> command to download and gunzip a run's timings.
…UN_ID; round ms; guard upload - E2E_TIMING_FILE → TEST_TIMING_FILE (temp file also .test_timing_ prefix) - E2E_LOG_ID → LOG_ID in run_test_cmd and exec_test - e2e-timings → test-timings S3 subfolder and ci.sh subcommand - Upload guard: skip upload with a warning when CI_LOG_ID or LOG_ID is unset (no unknown fallback) - Forward RUN_ID into docker_isolate container so runId is non-null in JSONL - Round all *Ms fields to integers in toLine() to avoid float noise from performance.now()
PhilWindle
approved these changes
Jun 26, 2026
PhilWindle
added a commit
that referenced
this pull request
Jun 26, 2026
## Problem PR #24281 added `end-to-end/src/shared/timing_env.mjs` and set the jest `testEnvironment` to `./shared/timing_env.mjs` directly in `end-to-end/package.json`. But `testEnvironment` is an **inherited** field: the package.json generator (`scripts/update_package_jsons.mjs`) shallow-merges each package's `jest` block with the parent winning, and `package.common.json` sets `testEnvironment` to `../../foundation/src/jest/env.mjs`. As a result, `yarn prepare` reverts the override back to the foundation env, and `yarn prepare:check` (run by the pre-commit hook) fails. The inconsistency reached `merge-train/spartan-v5` because GitHub squash-merge doesn't run the local pre-commit hook, so anyone merging this base and committing locally now hits the failure. ## Fix Move the `testEnvironment` override into `end-to-end/package.local.json`, which the generator applies **last**, so the timing test environment survives `prepare` and the generated `end-to-end/package.json` stays consistent with the inherits sources. Verified: `node scripts/update_package_jsons.mjs --check` passes with this change and leaves `end-to-end/package.json` pointing at `./shared/timing_env.mjs`.
spalladino
added a commit
that referenced
this pull request
Jul 1, 2026
## 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" } ```
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What
Adds per-test timing capture to the e2e suite (A-1178, Phase 1), distinguishing function-level time inside our
setup()/teardown()from hook-level time across jest's before/after hooks, and uploads one JSONL file per test to S3 with aci.shcommand to pull a run's timings back.This is the PR-independent subset that does not depend on the e2e consolidation reorg (#24201). The reorg-gated pieces (
wait:*/compute body split, multi-node/prover-node start attribution) are deliberately deferred — those files don't exist on this base.Fixes A-1180
Fixes A-1181
How
yarn-project/end-to-end/src/shared/timing_env.mjs(new) — aTimingEnvironmentsubclass of foundation'sCustomEnvironment. Callsawait super.handleTestEvent()first (preserves the base env's unhandled-rejection patching), then times jest-circus events (hook_start/hook_success/hook_failureby hook type,test_fn_*for the body,test_start/test_donefor total). Installs a collector onthis.globaland flushes JSONL on envteardown. Entirely gated onE2E_TIMING_FILE; a pure delegate otherwise.package.json—jest.testEnvironment→./shared/timing_env.mjs.fixtures/setup.ts— wraps the exportedsetup()and the innerteardownclosure (bothctx.teardown()and the exportedteardown(context)funnel through it) in try/finally, pushing their durations toglobalThis.__e2eTimings, tagged with the running test (ornullduringbeforeAll/afterAll).ci3/exec_test— exportsE2E_TIMING_FILEand, after the test, uploads the gzipped file viacache_s3_transfer_to.ci3/run_test_cmd— passes the attempt's log id toexec_testasE2E_LOG_ID(tracksrotate_logon retries).ci.sh— newe2e-timings <ci_log_id> <folder>command:aws s3 cp --recursivethe job's prefix and gunzip each file to<log_id>.jsonl.tsconfig.json/eslint.config.js— exclude/ignore the env.mjs(it imports foundation's env across packages and jest loads it from source), matching how foundation already ignores its ownsrc/jest/*.mjs.JSONL schema (one line per test)
{ "suite":"e2e_fees", "name":"pays fee via private payment", "status":"passed", "commit":"abc1234", "branch":"merge-train/spartan-v5", "runId":"177...", "startedAt":"2026-06-24T12:00:02.000Z", "setupFnMs":42000, "beforeHooksMs":47000, "bodyMs":13000, "teardownFnMs":2500, "afterHooksMs":3000, "totalMs":63000 }beforeAll/afterAll(once per describe) are emitted on a single suite-scoped line withname: null.Examples from this PR's CI run
Storage & retrieval
s3://aztec-ci-artifacts/logs/e2e-timings/<CI_LOG_ID>/<LOG_ID>.log.gz(gzipped JSONL).CI_LOG_ID= the job's top-level log id (the decimal id in a job'sci.aztec-labs.com/<id>URL) — per-job, so it's collision-free under grind.LOG_ID= the test's individual log id, the same id as the test's log atci.aztec-labs.com/<log_id>, so a test log maps straight to its timing file../ci.sh e2e-timings <ci_log_id> <folder>→<folder>/<LOG_ID>.jsonlper test (thesuite/namefields inside identify the test).Notes
ci-no-squashlabel — single commit on merge.