Skip to content

feat(e2e): track per-test setup/hook timings - #24281

Merged
PhilWindle merged 5 commits into
merge-train/spartan-v5from
spl/a-1178-track-running-times
Jun 26, 2026
Merged

feat(e2e): track per-test setup/hook timings#24281
PhilWindle merged 5 commits into
merge-train/spartan-v5from
spl/a-1178-track-running-times

Conversation

@spalladino

@spalladino spalladino commented Jun 24, 2026

Copy link
Copy Markdown
Contributor

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 a ci.sh command 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) — a TimingEnvironment subclass of foundation's CustomEnvironment. Calls await super.handleTestEvent() first (preserves the base env's unhandled-rejection patching), then times jest-circus events (hook_start/hook_success/hook_failure by hook type, test_fn_* for the body, test_start/test_done for total). Installs a collector on this.global and flushes JSONL on env teardown. Entirely gated on E2E_TIMING_FILE; a pure delegate otherwise.
  • package.jsonjest.testEnvironment./shared/timing_env.mjs.
  • fixtures/setup.ts — wraps the exported setup() and the inner teardown closure (both ctx.teardown() and the exported teardown(context) funnel through it) in try/finally, pushing their durations to globalThis.__e2eTimings, tagged with the running test (or null during beforeAll/afterAll).
  • ci3/exec_test — exports E2E_TIMING_FILE and, after the test, uploads the gzipped file via cache_s3_transfer_to.
  • ci3/run_test_cmd — passes the attempt's log id to exec_test as E2E_LOG_ID (tracks rotate_log on retries).
  • ci.sh — new e2e-timings <ci_log_id> <folder> command: aws s3 cp --recursive the 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 own src/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 with name: null.

Examples from this PR's CI run

  // type:"test" — per-test, with beforeEach setup on the test line
  { "suite":"epochs_invalidate_block.parallel", "type":"test",
    "name":"e2e_epochs/epochs_invalidate_block proposer invalidates previous checkpoint…",
    "status":"passed", "setupFnMs":14330, "beforeHooksMs":19357, "bodyMs":179667,
    "teardownFnMs":732, "afterHooksMs":765, "totalMs":199797,
    "startedAt":"2026-06-25T12:58:34.643Z",
    "commit":"1925654a900…", "branch":"spl/a-1178-track-running-times", "runId":"28171484400" }
  // type:"suite" — the former name:null line (beforeAll/afterAll for the whole file)
  { "suite":"e2e_amm", "type":"suite", "name":null, "status":"passed",
    "setupFnMs":32591, "beforeHooksMs":61200, "teardownFnMs":102, "afterHooksMs":103, "totalMs":61303,
    "commit":"1925654a900…", "branch":"spl/a-1178-track-running-times", "runId":"28171484400" }

Storage & retrieval

  • S3 object: 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's ci.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 at ci.aztec-labs.com/<log_id>, so a test log maps straight to its timing file.
  • Download: ./ci.sh e2e-timings <ci_log_id> <folder><folder>/<LOG_ID>.jsonl per test (the suite/name fields inside identify the test).

Notes

  • References A-1178 / A-1179 / A-1180 / A-1181 (Phase-1 subset; no auto-closing keywords).
  • No ci-no-squash label — single commit on merge.

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.
@spalladino
spalladino requested a review from charlielye as a code owner June 24, 2026 20:54
…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
PhilWindle merged commit 320932b into merge-train/spartan-v5 Jun 26, 2026
21 checks passed
@PhilWindle
PhilWindle deleted the spl/a-1178-track-running-times branch June 26, 2026 08:54
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`.
vezenovm added a commit that referenced this pull request Jun 29, 2026
An earlier prepare:check regen rewrote jest.testEnvironment to the package.common.json template value, which disables #24281's per-test TimingEnvironment. Restore the base value (net-zero vs base; the template mismatch is #24281's pre-existing concern).
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"
}
```
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants