From 94001f1b1fcd72edc50c1577621f09b3f2371538 Mon Sep 17 00:00:00 2001 From: kyscott18 <43524469+kyscott18@users.noreply.github.com> Date: Tue, 13 Oct 2026 18:50:18 +0000 Subject: [PATCH 1/3] test(bench): measure the real execute cost and runtime throughput MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - execute.benchmark: report µs and add erc20 and nested-CALL workloads. The bare counter finished the gas-limit search in one run, so it did not show the cost of that search. - counter/harness benchmarks: capture console output instead of printing it, so they measure the runtime and not terminal I/O. Report evm execute / accept batch / persist batch durations from the runtime's debug logs. - counter benchmark: run with 1 client, 32 clients, and open-loop senders at 4,000 and 8,000 mutations/s. One sequential client cannot show batching or pipelining, and closed-loop clients move in lockstep with batches. --- .../typewriter-evm/test/execute.benchmark.ts | 143 +++++++++++----- packages/typewriter/test/benchmark-utils.ts | 83 +++++++++ packages/typewriter/test/counter.benchmark.ts | 158 +++++++++++------- packages/typewriter/test/harness.benchmark.ts | 47 +----- 4 files changed, 292 insertions(+), 139 deletions(-) create mode 100644 packages/typewriter/test/benchmark-utils.ts diff --git a/packages/typewriter-evm/test/execute.benchmark.ts b/packages/typewriter-evm/test/execute.benchmark.ts index fe2de4d9..3ffc7b57 100644 --- a/packages/typewriter-evm/test/execute.benchmark.ts +++ b/packages/typewriter-evm/test/execute.benchmark.ts @@ -1,6 +1,21 @@ import { test } from "bun:test"; import { Effect } from "effect"; -import { createEVM } from "../src/index.ts"; +import { + createEVM, + type ExecuteParams, + type InitParams, +} from "../src/index.ts"; +import { + callBurnData, + loadCallGasCallee, + loadCallGasCaller, + loadTestToken, + RECIPIENT_ADDR, + SCHEDULER_ADDR, + TOKEN_ADDR, + tokenInit, + transferData, +} from "./utils"; const MUTATION_COUNT = 10_000; @@ -9,6 +24,14 @@ const MUTATION_COUNT = 10_000; const COUNTER_CODE = "0x60008054600101905500"; const COUNTER_ADDR = "0x0000000000000000000000000000000000000c01"; const CALLER = "0x000000000000000000000000000000000000ca11"; +const CALL_BURN_CALLEE_ADDR = "0x000000000000000000000000000000000000ca1e"; +const CALL_BURN_CALLER_ADDR = "0x000000000000000000000000000000000000ca1f"; + +type Workload = { + readonly name: string; + readonly init: InitParams; + readonly call: ExecuteParams; +}; function percentile(values: readonly number[], p: number): number { const index = Math.min( @@ -18,52 +41,92 @@ function percentile(values: readonly number[], p: number): number { return values[index]!; } -function formatMs(durationMs: number): string { - return `${durationMs.toFixed(2)}ms`; +function formatUs(durationMs: number): string { + return `${(durationMs * 1_000).toFixed(1)}µs`; } -test(`typewriter-evm execute accepts ${MUTATION_COUNT.toLocaleString()} calls`, async () => { - const program = Effect.gen(function* () { - const evm = yield* createEVM(); - yield* evm.init({ - accounts: { - [COUNTER_ADDR]: { code: COUNTER_CODE }, +async function loadWorkloads(): Promise { + const token = await loadTestToken(); + const callee = await loadCallGasCallee(); + const caller = await loadCallGasCaller(); + return [ + { + // Bare SLOAD/SSTORE. Gas estimation converges on the first attempt, so + // this is the floor for one execute round trip. + name: "counter", + init: { accounts: { [COUNTER_ADDR]: { code: COUNTER_CODE } } }, + call: { from: CALLER, to: COUNTER_ADDR, data: "0x" }, + }, + { + name: "erc20 transfer", + init: tokenInit(token).params, + call: { + from: SCHEDULER_ADDR, + to: TOKEN_ADDR, + data: transferData(RECIPIENT_ADDR, 1n), }, - }); + }, + { + // A nested CALL adds EIP-150 63/64 headroom, so gas_used is not a + // sufficient gas limit. Real Typewriter mutations have this shape: + // signature verification calls a precompile. + name: "nested call", + init: { + chain_id: 31337, + accounts: { + [CALL_BURN_CALLEE_ADDR]: { code: callee.deployedBytecode.object }, + [CALL_BURN_CALLER_ADDR]: { code: caller.deployedBytecode.object }, + }, + }, + call: { + from: SCHEDULER_ADDR, + to: CALL_BURN_CALLER_ADDR, + data: callBurnData(CALL_BURN_CALLEE_ADDR, 10n), + }, + }, + ]; +} + +test(`typewriter-evm execute accepts ${MUTATION_COUNT.toLocaleString()} calls`, async () => { + const workloads = await loadWorkloads(); + const rows: string[] = []; - const mutationDurationsMs = new Array(MUTATION_COUNT); - const totalStart = performance.now(); + for (const workload of workloads) { + const program = Effect.gen(function* () { + const evm = yield* createEVM(); + yield* evm.init(workload.init); - for (let index = 0; index < MUTATION_COUNT; index += 1) { - const mutationStart = performance.now(); - const result = yield* evm.execute({ - from: CALLER, - to: COUNTER_ADDR, - data: "0x", - }); - if (result.success !== true) { - throw new Error("execute failed during benchmark"); + const durationsMs = new Array(MUTATION_COUNT); + const totalStart = performance.now(); + for (let index = 0; index < MUTATION_COUNT; index += 1) { + const start = performance.now(); + const result = yield* evm.execute(workload.call); + if (result.success !== true) { + throw new Error(`${workload.name} execute failed during benchmark`); + } + durationsMs[index] = performance.now() - start; } - mutationDurationsMs[index] = performance.now() - mutationStart; - } + const totalMs = performance.now() - totalStart; - const totalDurationMs = performance.now() - totalStart; - const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); - const averageDurationMs = - mutationDurationsMs.reduce((total, duration) => total + duration, 0) / - MUTATION_COUNT; - const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); + const sorted = durationsMs.toSorted((a, b) => a - b); + rows.push( + [ + workload.name.padStart(14), + formatUs(totalMs / MUTATION_COUNT).padStart(9), + formatUs(percentile(sorted, 0.5)).padStart(9), + formatUs(percentile(sorted, 0.99)).padStart(9), + Math.round(MUTATION_COUNT / (totalMs / 1_000)) + .toLocaleString() + .padStart(10), + ].join(" "), + ); + }); + await Effect.runPromise(Effect.scoped(program)); + } - console.log(` + console.log(` typewriter-evm execute benchmark -mutations: ${MUTATION_COUNT.toLocaleString()} -total: ${formatMs(totalDurationMs)} -average: ${formatMs(averageDurationMs)} -p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} -p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} -p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} -throughput: ${mutationsPerSecond.toFixed(2)} calls/s`); - }); - - await Effect.runPromise(Effect.scoped(program)); +calls per workload: ${MUTATION_COUNT.toLocaleString()} + workload average p50 p99 calls/s +${rows.join("\n")}`); }, 300_000); diff --git a/packages/typewriter/test/benchmark-utils.ts b/packages/typewriter/test/benchmark-utils.ts new file mode 100644 index 00000000..882d9428 --- /dev/null +++ b/packages/typewriter/test/benchmark-utils.ts @@ -0,0 +1,83 @@ +export function percentile(values: readonly number[], p: number): number { + const index = Math.min( + values.length - 1, + Math.floor((values.length - 1) * p), + ); + return values[index]!; +} + +export function formatMs(durationMs: number): string { + return `${durationMs.toFixed(2)}ms`; +} + +// Runtime debug logs that carry a `duration` annotation, keyed by message. +const PHASES = { + "executed mutation": "evm execute (per mutation)", + "batched mutations": "accept batch (per batch)", + "persisted accepted mutations": "persist batch (per batch)", +} as const; + +type Phase = keyof typeof PHASES; + +// Runs `run` with console output captured instead of printed, so the +// benchmark measures the runtime and not terminal I/O. Log formatting and +// serialization still run, as they do in production. +export async function withCapturedLogs( + run: () => Promise, +): Promise<{ result: T; phases: string }> { + const original = { + debug: console.debug, + error: console.error, + info: console.info, + log: console.log, + warn: console.warn, + }; + const lines: unknown[] = []; + const capture = (line: unknown) => { + lines.push(line); + }; + + console.debug = capture; + console.error = capture; + console.info = capture; + console.log = capture; + console.warn = capture; + + let result: T; + try { + result = await run(); + } finally { + console.debug = original.debug; + console.error = original.error; + console.info = original.info; + console.log = original.log; + console.warn = original.warn; + } + + const durations = new Map(); + for (const line of lines) { + if (typeof line !== "string" || !line.startsWith("{")) continue; + const entry = JSON.parse(line) as { + message?: string; + annotations?: { duration?: number }; + }; + const message = entry.message as Phase | undefined; + const duration = entry.annotations?.duration; + if (message === undefined || !(message in PHASES)) continue; + if (duration === undefined) continue; + const values = durations.get(message) ?? []; + values.push(duration); + durations.set(message, values); + } + + const phases = (Object.keys(PHASES) as Phase[]) + .map((phase) => { + const values = durations.get(phase) ?? []; + if (values.length === 0) return `${PHASES[phase]}: n/a`; + const total = values.reduce((sum, value) => sum + value, 0); + return `${PHASES[phase]}: avg ${formatMs(total / values.length)} x ${values.length.toLocaleString()} = ${formatMs(total)}`; + }) + .join("\n"); + + return { result, phases }; +} diff --git a/packages/typewriter/test/counter.benchmark.ts b/packages/typewriter/test/counter.benchmark.ts index 99fd0b92..44ef248a 100644 --- a/packages/typewriter/test/counter.benchmark.ts +++ b/packages/typewriter/test/counter.benchmark.ts @@ -1,6 +1,7 @@ import { test } from "bun:test"; import { anvil } from "viem/chains"; import type { TypewriterConfig } from "../src"; +import { formatMs, percentile, withCapturedLogs } from "./benchmark-utils"; import Counter from "./contracts/src/Counter.sol"; import { SCHEDULER_ACCOUNT, @@ -18,6 +19,29 @@ process.env.NODE_ENV = "production"; const MUTATION_COUNT = 10_000; +// How the benchmark sends mutations: +// - closed: `inFlight` clients that each wait for a response before they send +// the next mutation. 1 client measures pure latency. Closed-loop clients +// move in lockstep with batches, so work cannot overlap a commit. +// - open: send at a fixed rate whatever the responses, like many independent +// users. Above the runtime's capacity, latency grows with each mutation. +type Load = + | { readonly mode: "closed"; readonly inFlight: number } + | { readonly mode: "open"; readonly perSecond: number }; + +const LOADS: readonly Load[] = [ + { mode: "closed", inFlight: 1 }, + { mode: "closed", inFlight: 32 }, + { mode: "open", perSecond: 4_000 }, + { mode: "open", perSecond: 8_000 }, +]; + +function describeLoad(load: Load): string { + return load.mode === "closed" + ? `${load.inFlight} in flight` + : `open loop at ${load.perSecond.toLocaleString()}/s`; +} + function counterAddMutation(params: { readonly address: `0x${string}`; readonly amount: bigint; @@ -32,72 +56,92 @@ function counterAddMutation(params: { }); } -function percentile(values: readonly number[], p: number): number { - const index = Math.min( - values.length - 1, - Math.floor((values.length - 1) * p), - ); - return values[index]!; -} - -function formatMs(durationMs: number): string { - return `${durationMs.toFixed(2)}ms`; -} - -test(`counter accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async () => { - const { createTypewriter } = await import("../src"); - const address = await deployCounter(); - const config = { - address, - account: SCHEDULER_ACCOUNT, - chainId: anvil.id, - rpcUrl: TEST_RPC_URL, - sequencing: { order: "fifo", submitIntervalMs: 3_600_000 }, - database: { url: TEST_DB_URL, maxConnections: 2 }, - blockPollingIntervalMs: 3_600_000, - } as const satisfies TypewriterConfig; +for (const load of LOADS) { + test(`counter accepts ${MUTATION_COUNT.toLocaleString()} mutations, ${describeLoad(load)}`, async () => { + const { createTypewriter } = await import("../src"); + const address = await deployCounter(); + const config = { + address, + account: SCHEDULER_ACCOUNT, + chainId: anvil.id, + rpcUrl: TEST_RPC_URL, + sequencing: { order: "fifo", submitIntervalMs: 3_600_000 }, + database: { url: TEST_DB_URL, maxConnections: 2 }, + blockPollingIntervalMs: 3_600_000, + } as const satisfies TypewriterConfig; - const typewriter = await createTypewriter(Counter, config); + const typewriter = await createTypewriter(Counter, config); - await typewriter.execute( - await prepareCounterCreateAccount({ + const createAccount = await prepareCounterCreateAccount({ privateKey: USER_PRIVATE_KEY, address, chainId: anvil.id, - }), - ); - - const mutations = await Promise.all( - Array.from({ length: MUTATION_COUNT }, (_, index) => - counterAddMutation({ - address, - amount: 1n, - nonce: BigInt(index), - }), - ), - ); - - const mutationDurationsMs: number[] = []; - const totalStart = performance.now(); - - for (const mutation of mutations) { - const mutationStart = performance.now(); - await typewriter.execute(mutation); - mutationDurationsMs.push(performance.now() - mutationStart); - } - - const totalDurationMs = performance.now() - totalStart; - const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); - const averageDurationMs = totalDurationMs / MUTATION_COUNT; - const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); - - console.log(` + }); + await withCapturedLogs(() => typewriter.execute(createAccount)); + + const mutations = await Promise.all( + Array.from({ length: MUTATION_COUNT }, (_, index) => + counterAddMutation({ + address, + amount: 1n, + nonce: BigInt(index), + }), + ), + ); + + const mutationDurationsMs = new Array(MUTATION_COUNT); + const totalStart = performance.now(); + + // Mutations are always sent in nonce order. + let nextIndex = 0; + const send = async () => { + const index = nextIndex++; + const mutationStart = performance.now(); + await typewriter.execute(mutations[index]!); + mutationDurationsMs[index] = performance.now() - mutationStart; + }; + + const { phases } = await withCapturedLogs(async () => { + if (load.mode === "closed") { + const client = async () => { + while (nextIndex < MUTATION_COUNT) await send(); + }; + await Promise.all(Array.from({ length: load.inFlight }, client)); + return; + } + + // Timers fire about every 1ms at best, so send all due mutations on + // each tick. + const sent: Promise[] = []; + while (nextIndex < MUTATION_COUNT) { + const elapsedSeconds = (performance.now() - totalStart) / 1_000; + const due = Math.min( + MUTATION_COUNT, + Math.floor(elapsedSeconds * load.perSecond) + 1, + ); + while (nextIndex < due) sent.push(send()); + await Bun.sleep(1); + } + await Promise.all(sent); + }); + + const totalDurationMs = performance.now() - totalStart; + const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); + const averageDurationMs = + mutationDurationsMs.reduce((total, duration) => total + duration, 0) / + MUTATION_COUNT; + const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); + + console.log(` Counter benchmark mutations: ${MUTATION_COUNT.toLocaleString()} +load: ${describeLoad(load)} total: ${formatMs(totalDurationMs)} average: ${formatMs(averageDurationMs)} p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} -throughput: ${mutationsPerSecond.toFixed(2)} mutations/s`); -}, 120_000); +throughput: ${mutationsPerSecond.toFixed(2)} mutations/s +${phases}`); + }, 120_000); +} diff --git a/packages/typewriter/test/harness.benchmark.ts b/packages/typewriter/test/harness.benchmark.ts index 2f7d3805..290de69c 100644 --- a/packages/typewriter/test/harness.benchmark.ts +++ b/packages/typewriter/test/harness.benchmark.ts @@ -1,6 +1,7 @@ import { test } from "bun:test"; import { anvil } from "viem/chains"; import type { TypewriterConfig } from "../src"; +import { formatMs, percentile, withCapturedLogs } from "./benchmark-utils"; import Harness from "./contracts/src/Harness.sol"; import { SCHEDULER_ACCOUNT, @@ -39,45 +40,6 @@ function harnessCreditMutation(params: { }); } -function percentile(values: readonly number[], p: number): number { - const index = Math.min( - values.length - 1, - Math.floor((values.length - 1) * p), - ); - return values[index]!; -} - -function formatMs(durationMs: number): string { - return `${durationMs.toFixed(2)}ms`; -} - -async function withoutConsoleOutput(run: () => Promise): Promise { - const original = { - debug: console.debug, - error: console.error, - info: console.info, - log: console.log, - warn: console.warn, - }; - const noop = () => {}; - - console.debug = noop; - console.error = noop; - console.info = noop; - console.log = noop; - console.warn = noop; - - try { - return await run(); - } finally { - console.debug = original.debug; - console.error = original.error; - console.info = original.info; - console.log = original.log; - console.warn = original.warn; - } -} - test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async () => { const { createTypewriter } = await import("../src"); const address = await deployHarness(); @@ -108,7 +70,7 @@ test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async address, chainId: anvil.id, }); - await withoutConsoleOutput(() => typewriter.execute(createAccount)); + await withCapturedLogs(() => typewriter.execute(createAccount)); const mutations = await Promise.all( Array.from({ length: MUTATION_COUNT }, (_, index) => @@ -124,7 +86,7 @@ test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async const mutationDurationsMs = new Array(MUTATION_COUNT); const totalStart = performance.now(); - await withoutConsoleOutput(async () => { + const { phases } = await withCapturedLogs(async () => { const promises = mutations.map(async (mutation, index) => { const mutationStart = performance.now(); await typewriter.execute(mutation); @@ -150,5 +112,6 @@ average: ${formatMs(averageDurationMs)} p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} -throughput: ${mutationsPerSecond.toFixed(2)} mutations/s`); +throughput: ${mutationsPerSecond.toFixed(2)} mutations/s +${phases}`); }, 300_000); From 3af39e3d8103e8c78f97d6a9630b6e8d2f68dc17 Mon Sep 17 00:00:00 2001 From: kyscott18 <43524469+kyscott18@users.noreply.github.com> Date: Tue, 13 Oct 2026 18:50:18 +0000 Subject: [PATCH 2/3] chore: remove the stale executeMany plan The plan describes runtime-batch.ts, main.rs, and an IPC sidecar, which no longer exist. Measured on the napi addon, the per-call wrapper (JSON, semaphore, Effect) costs about 4us against about 96us of native EVM time per mutation, so batching execute calls would gain little. --- packages/typewriter/PLAN_execute_many.md | 80 ------------------------ 1 file changed, 80 deletions(-) delete mode 100644 packages/typewriter/PLAN_execute_many.md diff --git a/packages/typewriter/PLAN_execute_many.md b/packages/typewriter/PLAN_execute_many.md deleted file mode 100644 index 2c936c97..00000000 --- a/packages/typewriter/PLAN_execute_many.md +++ /dev/null @@ -1,80 +0,0 @@ -# executeMany Plan - -## Goal - -Reduce JS <-> Rust overhead in `packages/typewriter/src/runtime-batch.ts` by batching multiple EVM `execute` calls into one typewriter-evm request. - -## Why this matters - -`acceptBatch` already collects mutations into a list. Today each mutation still pays a separate IPC round trip to typewriter-evm. A batched request should keep the current sequential semantics while removing most of the transport overhead. - -## Proposed shape - -### Request - -Add a new wire method in typewriter-evm: - -```rust -ExecuteMany { id: u64, params: ExecuteManyParams } - -struct ExecuteManyParams { - calls: Vec, -} -``` - -`ExecuteParams` stays unchanged: - -```ts -{ - from: Address; - to: Address; - data: Hex; - value?: Hex; -} -``` - -### Response - -Return results in the same order as the input calls: - -```rust -struct ExecuteManyOk { - results: Vec, -} -``` - -## Runtime-batch usage - -Use `executeMany` first in `acceptBatch`. - -1. Collect the mutations that are about to be accepted. -2. Resolve and encode them into a single `calls` array. -3. Send one `executeMany` request to typewriter-evm. -4. Zip the returned `ExecuteOk[]` back onto the original mutations by index. -5. Preserve existing per-mutation behavior: - - reject individual failures - - assign `journalId` on success - - invalidate storage cache from returned slot writes - - collect new keccak preimages - - persist accepted mutations - - emit the same events - -`watchProgram` can stay on single-call `execute` initially. - -## Rollout order - -1. Add `ExecuteMany` to `packages/typewriter-evm/src/main.rs` and `packages/typewriter-evm/src/types.ts`. -2. Add `executeMany` to `packages/typewriter-evm/src/index.ts`. -3. Add a batched helper in `packages/typewriter/src/runtime-batch.ts`. -4. Switch `acceptBatch` to use the batched helper. -5. Benchmark against the current baseline. - -## Non-goals - -- Changing acceptance semantics. -- Retrying or skipping failures inside typewriter-evm. -- Replacing the sidecar with `napi-rs` or WASM. - -## Measurement target - -The first question is whether batching the IPC call produces a meaningful win before any deeper runtime or transport changes. From 7cdcac17f781ad08b637e0839f4a634a4f758cca Mon Sep 17 00:00:00 2001 From: kyscott18 <43524469+kyscott18@users.noreply.github.com> Date: Tue, 13 Oct 2026 20:11:44 +0000 Subject: [PATCH 3/3] test(bench): measure single-user latency and max throughput on Harness Use one Harness benchmark with production defaults, so submit and block polling run. Remove the counter benchmark, the log-phase parser and the synthetic EVM workloads. Add a benchmark script that builds the release typewriter-evm addon first. --- .../typewriter-evm/test/execute.benchmark.ts | 143 +++++------------ packages/typewriter/package.json | 1 + packages/typewriter/test/benchmark-utils.ts | 83 ---------- packages/typewriter/test/counter.benchmark.ts | 147 ------------------ packages/typewriter/test/harness.benchmark.ts | 122 +++++++-------- 5 files changed, 97 insertions(+), 399 deletions(-) delete mode 100644 packages/typewriter/test/benchmark-utils.ts delete mode 100644 packages/typewriter/test/counter.benchmark.ts diff --git a/packages/typewriter-evm/test/execute.benchmark.ts b/packages/typewriter-evm/test/execute.benchmark.ts index 3ffc7b57..fe2de4d9 100644 --- a/packages/typewriter-evm/test/execute.benchmark.ts +++ b/packages/typewriter-evm/test/execute.benchmark.ts @@ -1,21 +1,6 @@ import { test } from "bun:test"; import { Effect } from "effect"; -import { - createEVM, - type ExecuteParams, - type InitParams, -} from "../src/index.ts"; -import { - callBurnData, - loadCallGasCallee, - loadCallGasCaller, - loadTestToken, - RECIPIENT_ADDR, - SCHEDULER_ADDR, - TOKEN_ADDR, - tokenInit, - transferData, -} from "./utils"; +import { createEVM } from "../src/index.ts"; const MUTATION_COUNT = 10_000; @@ -24,14 +9,6 @@ const MUTATION_COUNT = 10_000; const COUNTER_CODE = "0x60008054600101905500"; const COUNTER_ADDR = "0x0000000000000000000000000000000000000c01"; const CALLER = "0x000000000000000000000000000000000000ca11"; -const CALL_BURN_CALLEE_ADDR = "0x000000000000000000000000000000000000ca1e"; -const CALL_BURN_CALLER_ADDR = "0x000000000000000000000000000000000000ca1f"; - -type Workload = { - readonly name: string; - readonly init: InitParams; - readonly call: ExecuteParams; -}; function percentile(values: readonly number[], p: number): number { const index = Math.min( @@ -41,92 +18,52 @@ function percentile(values: readonly number[], p: number): number { return values[index]!; } -function formatUs(durationMs: number): string { - return `${(durationMs * 1_000).toFixed(1)}µs`; -} - -async function loadWorkloads(): Promise { - const token = await loadTestToken(); - const callee = await loadCallGasCallee(); - const caller = await loadCallGasCaller(); - return [ - { - // Bare SLOAD/SSTORE. Gas estimation converges on the first attempt, so - // this is the floor for one execute round trip. - name: "counter", - init: { accounts: { [COUNTER_ADDR]: { code: COUNTER_CODE } } }, - call: { from: CALLER, to: COUNTER_ADDR, data: "0x" }, - }, - { - name: "erc20 transfer", - init: tokenInit(token).params, - call: { - from: SCHEDULER_ADDR, - to: TOKEN_ADDR, - data: transferData(RECIPIENT_ADDR, 1n), - }, - }, - { - // A nested CALL adds EIP-150 63/64 headroom, so gas_used is not a - // sufficient gas limit. Real Typewriter mutations have this shape: - // signature verification calls a precompile. - name: "nested call", - init: { - chain_id: 31337, - accounts: { - [CALL_BURN_CALLEE_ADDR]: { code: callee.deployedBytecode.object }, - [CALL_BURN_CALLER_ADDR]: { code: caller.deployedBytecode.object }, - }, - }, - call: { - from: SCHEDULER_ADDR, - to: CALL_BURN_CALLER_ADDR, - data: callBurnData(CALL_BURN_CALLEE_ADDR, 10n), - }, - }, - ]; +function formatMs(durationMs: number): string { + return `${durationMs.toFixed(2)}ms`; } test(`typewriter-evm execute accepts ${MUTATION_COUNT.toLocaleString()} calls`, async () => { - const workloads = await loadWorkloads(); - const rows: string[] = []; + const program = Effect.gen(function* () { + const evm = yield* createEVM(); + yield* evm.init({ + accounts: { + [COUNTER_ADDR]: { code: COUNTER_CODE }, + }, + }); - for (const workload of workloads) { - const program = Effect.gen(function* () { - const evm = yield* createEVM(); - yield* evm.init(workload.init); + const mutationDurationsMs = new Array(MUTATION_COUNT); + const totalStart = performance.now(); - const durationsMs = new Array(MUTATION_COUNT); - const totalStart = performance.now(); - for (let index = 0; index < MUTATION_COUNT; index += 1) { - const start = performance.now(); - const result = yield* evm.execute(workload.call); - if (result.success !== true) { - throw new Error(`${workload.name} execute failed during benchmark`); - } - durationsMs[index] = performance.now() - start; + for (let index = 0; index < MUTATION_COUNT; index += 1) { + const mutationStart = performance.now(); + const result = yield* evm.execute({ + from: CALLER, + to: COUNTER_ADDR, + data: "0x", + }); + if (result.success !== true) { + throw new Error("execute failed during benchmark"); } - const totalMs = performance.now() - totalStart; + mutationDurationsMs[index] = performance.now() - mutationStart; + } - const sorted = durationsMs.toSorted((a, b) => a - b); - rows.push( - [ - workload.name.padStart(14), - formatUs(totalMs / MUTATION_COUNT).padStart(9), - formatUs(percentile(sorted, 0.5)).padStart(9), - formatUs(percentile(sorted, 0.99)).padStart(9), - Math.round(MUTATION_COUNT / (totalMs / 1_000)) - .toLocaleString() - .padStart(10), - ].join(" "), - ); - }); - await Effect.runPromise(Effect.scoped(program)); - } + const totalDurationMs = performance.now() - totalStart; + const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); + const averageDurationMs = + mutationDurationsMs.reduce((total, duration) => total + duration, 0) / + MUTATION_COUNT; + const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); - console.log(` + console.log(` typewriter-evm execute benchmark -calls per workload: ${MUTATION_COUNT.toLocaleString()} - workload average p50 p99 calls/s -${rows.join("\n")}`); +mutations: ${MUTATION_COUNT.toLocaleString()} +total: ${formatMs(totalDurationMs)} +average: ${formatMs(averageDurationMs)} +p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} +p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} +p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} +throughput: ${mutationsPerSecond.toFixed(2)} calls/s`); + }); + + await Effect.runPromise(Effect.scoped(program)); }, 300_000); diff --git a/packages/typewriter/package.json b/packages/typewriter/package.json index eebf66f8..a06710e0 100644 --- a/packages/typewriter/package.json +++ b/packages/typewriter/package.json @@ -8,6 +8,7 @@ "type": "module", "private": true, "scripts": { + "benchmark": "bun run --filter typewriter-evm build && bun test ./test/harness.benchmark.ts", "test": "bun test --timeout 30000", "typecheck": "tsc --noEmit" }, diff --git a/packages/typewriter/test/benchmark-utils.ts b/packages/typewriter/test/benchmark-utils.ts deleted file mode 100644 index 882d9428..00000000 --- a/packages/typewriter/test/benchmark-utils.ts +++ /dev/null @@ -1,83 +0,0 @@ -export function percentile(values: readonly number[], p: number): number { - const index = Math.min( - values.length - 1, - Math.floor((values.length - 1) * p), - ); - return values[index]!; -} - -export function formatMs(durationMs: number): string { - return `${durationMs.toFixed(2)}ms`; -} - -// Runtime debug logs that carry a `duration` annotation, keyed by message. -const PHASES = { - "executed mutation": "evm execute (per mutation)", - "batched mutations": "accept batch (per batch)", - "persisted accepted mutations": "persist batch (per batch)", -} as const; - -type Phase = keyof typeof PHASES; - -// Runs `run` with console output captured instead of printed, so the -// benchmark measures the runtime and not terminal I/O. Log formatting and -// serialization still run, as they do in production. -export async function withCapturedLogs( - run: () => Promise, -): Promise<{ result: T; phases: string }> { - const original = { - debug: console.debug, - error: console.error, - info: console.info, - log: console.log, - warn: console.warn, - }; - const lines: unknown[] = []; - const capture = (line: unknown) => { - lines.push(line); - }; - - console.debug = capture; - console.error = capture; - console.info = capture; - console.log = capture; - console.warn = capture; - - let result: T; - try { - result = await run(); - } finally { - console.debug = original.debug; - console.error = original.error; - console.info = original.info; - console.log = original.log; - console.warn = original.warn; - } - - const durations = new Map(); - for (const line of lines) { - if (typeof line !== "string" || !line.startsWith("{")) continue; - const entry = JSON.parse(line) as { - message?: string; - annotations?: { duration?: number }; - }; - const message = entry.message as Phase | undefined; - const duration = entry.annotations?.duration; - if (message === undefined || !(message in PHASES)) continue; - if (duration === undefined) continue; - const values = durations.get(message) ?? []; - values.push(duration); - durations.set(message, values); - } - - const phases = (Object.keys(PHASES) as Phase[]) - .map((phase) => { - const values = durations.get(phase) ?? []; - if (values.length === 0) return `${PHASES[phase]}: n/a`; - const total = values.reduce((sum, value) => sum + value, 0); - return `${PHASES[phase]}: avg ${formatMs(total / values.length)} x ${values.length.toLocaleString()} = ${formatMs(total)}`; - }) - .join("\n"); - - return { result, phases }; -} diff --git a/packages/typewriter/test/counter.benchmark.ts b/packages/typewriter/test/counter.benchmark.ts deleted file mode 100644 index 44ef248a..00000000 --- a/packages/typewriter/test/counter.benchmark.ts +++ /dev/null @@ -1,147 +0,0 @@ -import { test } from "bun:test"; -import { anvil } from "viem/chains"; -import type { TypewriterConfig } from "../src"; -import { formatMs, percentile, withCapturedLogs } from "./benchmark-utils"; -import Counter from "./contracts/src/Counter.sol"; -import { - SCHEDULER_ACCOUNT, - TEST_DB_URL, - TEST_RPC_URL, - USER_PRIVATE_KEY, -} from "./setup"; -import { - deployCounter, - prepareCounterAdd, - prepareCounterCreateAccount, -} from "./utils"; - -process.env.NODE_ENV = "production"; - -const MUTATION_COUNT = 10_000; - -// How the benchmark sends mutations: -// - closed: `inFlight` clients that each wait for a response before they send -// the next mutation. 1 client measures pure latency. Closed-loop clients -// move in lockstep with batches, so work cannot overlap a commit. -// - open: send at a fixed rate whatever the responses, like many independent -// users. Above the runtime's capacity, latency grows with each mutation. -type Load = - | { readonly mode: "closed"; readonly inFlight: number } - | { readonly mode: "open"; readonly perSecond: number }; - -const LOADS: readonly Load[] = [ - { mode: "closed", inFlight: 1 }, - { mode: "closed", inFlight: 32 }, - { mode: "open", perSecond: 4_000 }, - { mode: "open", perSecond: 8_000 }, -]; - -function describeLoad(load: Load): string { - return load.mode === "closed" - ? `${load.inFlight} in flight` - : `open loop at ${load.perSecond.toLocaleString()}/s`; -} - -function counterAddMutation(params: { - readonly address: `0x${string}`; - readonly amount: bigint; - readonly nonce: bigint; -}) { - return prepareCounterAdd({ - privateKey: USER_PRIVATE_KEY, - amount: params.amount, - sequence: params.nonce, - address: params.address, - chainId: anvil.id, - }); -} - -for (const load of LOADS) { - test(`counter accepts ${MUTATION_COUNT.toLocaleString()} mutations, ${describeLoad(load)}`, async () => { - const { createTypewriter } = await import("../src"); - const address = await deployCounter(); - const config = { - address, - account: SCHEDULER_ACCOUNT, - chainId: anvil.id, - rpcUrl: TEST_RPC_URL, - sequencing: { order: "fifo", submitIntervalMs: 3_600_000 }, - database: { url: TEST_DB_URL, maxConnections: 2 }, - blockPollingIntervalMs: 3_600_000, - } as const satisfies TypewriterConfig; - - const typewriter = await createTypewriter(Counter, config); - - const createAccount = await prepareCounterCreateAccount({ - privateKey: USER_PRIVATE_KEY, - address, - chainId: anvil.id, - }); - await withCapturedLogs(() => typewriter.execute(createAccount)); - - const mutations = await Promise.all( - Array.from({ length: MUTATION_COUNT }, (_, index) => - counterAddMutation({ - address, - amount: 1n, - nonce: BigInt(index), - }), - ), - ); - - const mutationDurationsMs = new Array(MUTATION_COUNT); - const totalStart = performance.now(); - - // Mutations are always sent in nonce order. - let nextIndex = 0; - const send = async () => { - const index = nextIndex++; - const mutationStart = performance.now(); - await typewriter.execute(mutations[index]!); - mutationDurationsMs[index] = performance.now() - mutationStart; - }; - - const { phases } = await withCapturedLogs(async () => { - if (load.mode === "closed") { - const client = async () => { - while (nextIndex < MUTATION_COUNT) await send(); - }; - await Promise.all(Array.from({ length: load.inFlight }, client)); - return; - } - - // Timers fire about every 1ms at best, so send all due mutations on - // each tick. - const sent: Promise[] = []; - while (nextIndex < MUTATION_COUNT) { - const elapsedSeconds = (performance.now() - totalStart) / 1_000; - const due = Math.min( - MUTATION_COUNT, - Math.floor(elapsedSeconds * load.perSecond) + 1, - ); - while (nextIndex < due) sent.push(send()); - await Bun.sleep(1); - } - await Promise.all(sent); - }); - - const totalDurationMs = performance.now() - totalStart; - const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); - const averageDurationMs = - mutationDurationsMs.reduce((total, duration) => total + duration, 0) / - MUTATION_COUNT; - const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); - - console.log(` -Counter benchmark -mutations: ${MUTATION_COUNT.toLocaleString()} -load: ${describeLoad(load)} -total: ${formatMs(totalDurationMs)} -average: ${formatMs(averageDurationMs)} -p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} -p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} -p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} -throughput: ${mutationsPerSecond.toFixed(2)} mutations/s -${phases}`); - }, 120_000); -} diff --git a/packages/typewriter/test/harness.benchmark.ts b/packages/typewriter/test/harness.benchmark.ts index 290de69c..d5204caa 100644 --- a/packages/typewriter/test/harness.benchmark.ts +++ b/packages/typewriter/test/harness.benchmark.ts @@ -1,7 +1,6 @@ import { test } from "bun:test"; import { anvil } from "viem/chains"; import type { TypewriterConfig } from "../src"; -import { formatMs, percentile, withCapturedLogs } from "./benchmark-utils"; import Harness from "./contracts/src/Harness.sol"; import { SCHEDULER_ACCOUNT, @@ -20,27 +19,10 @@ import { process.env.NODE_ENV = "production"; -const MUTATION_COUNT = 10_000; +const LATENCY_MUTATION_COUNT = 1_000; +const THROUGHPUT_MUTATION_COUNT = 10_000; -function harnessCreditMutation(params: { - readonly address: `0x${string}`; - readonly account: `0x${string}`; - readonly amount: bigint; - readonly nonce: bigint; -}) { - return prepareHarnessMutation({ - mutation: "Credit", - params: { amount: params.amount }, - accountID: params.account, - sequence: params.nonce, - keyType: 2, - privateKey: USER_PRIVATE_KEY, - address: params.address, - chainId: anvil.id, - }); -} - -test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async () => { +test("harness benchmark", async () => { const { createTypewriter } = await import("../src"); const address = await deployHarness(); const config = { @@ -48,21 +30,11 @@ test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async account: SCHEDULER_ACCOUNT, chainId: anvil.id, rpcUrl: TEST_RPC_URL, - sequencing: { - order: "batch", - batchIntervalMs: 10, - submitIntervalMs: 3_600_000, - batchOrder: ["CreateAccount", "Credit"], - }, - database: { url: TEST_DB_URL, maxConnections: 2 }, - blockPollingIntervalMs: 3_600_000, + database: { url: TEST_DB_URL }, } as const satisfies TypewriterConfig; - const typewriter = await createTypewriter(Harness, config); - const rootPublicKey = secp256k1PublicKey(USER_ACCOUNT.address); const account = nativeAccountID(2, rootPublicKey); - const createAccount = prepareHarnessCreateAccount({ keyType: 2, publicKey: rootPublicKey, @@ -70,48 +42,66 @@ test(`harness batch accepts ${MUTATION_COUNT.toLocaleString()} mutations`, async address, chainId: anvil.id, }); - await withCapturedLogs(() => typewriter.execute(createAccount)); - const mutations = await Promise.all( - Array.from({ length: MUTATION_COUNT }, (_, index) => - harnessCreditMutation({ - address, - account, - amount: 1n, - nonce: BigInt(index), - }), + Array.from( + { length: LATENCY_MUTATION_COUNT + THROUGHPUT_MUTATION_COUNT }, + (_, index) => + prepareHarnessMutation({ + mutation: "Credit", + params: { amount: 1n }, + accountID: account, + sequence: BigInt(index), + keyType: 2, + privateKey: USER_PRIVATE_KEY, + address, + chainId: anvil.id, + }), ), ); + const latencyMutations = mutations.slice(0, LATENCY_MUTATION_COUNT); + const throughputMutations = mutations.slice(LATENCY_MUTATION_COUNT); - const mutationDurationsMs = new Array(MUTATION_COUNT); - const totalStart = performance.now(); + // Keep the cost of Debug log formatting, but do not print the lines. + const consoleLog = console.log; + const consoleDebug = console.debug; + console.log = () => {}; + console.debug = () => {}; - const { phases } = await withCapturedLogs(async () => { - const promises = mutations.map(async (mutation, index) => { - const mutationStart = performance.now(); + const latenciesMs: number[] = []; + let throughputDurationMs: number; + try { + const typewriter = await createTypewriter(Harness, config); + await typewriter.execute(createAccount); + + for (const mutation of latencyMutations) { + const start = performance.now(); await typewriter.execute(mutation); - mutationDurationsMs[index] = performance.now() - mutationStart; - }); + latenciesMs.push(performance.now() - start); + } - await Promise.all(promises); - }); + const start = performance.now(); + await Promise.all( + throughputMutations.map((mutation) => typewriter.execute(mutation)), + ); + throughputDurationMs = performance.now() - start; + } finally { + console.log = consoleLog; + console.debug = consoleDebug; + } - const totalDurationMs = performance.now() - totalStart; - const sortedDurationsMs = mutationDurationsMs.toSorted((a, b) => a - b); - const averageDurationMs = - mutationDurationsMs.reduce((total, duration) => total + duration, 0) / - MUTATION_COUNT; - const mutationsPerSecond = MUTATION_COUNT / (totalDurationMs / 1_000); + latenciesMs.sort((a, b) => a - b); + const averageMs = + latenciesMs.reduce((total, latency) => total + latency, 0) / + LATENCY_MUTATION_COUNT; + const p50Ms = latenciesMs[Math.floor(LATENCY_MUTATION_COUNT * 0.5)]!; + const p99Ms = latenciesMs[Math.floor(LATENCY_MUTATION_COUNT * 0.99)]!; + const mutationsPerSecond = + THROUGHPUT_MUTATION_COUNT / (throughputDurationMs / 1_000); console.log(` -Harness batch benchmark -mutations: ${MUTATION_COUNT.toLocaleString()} -batch window: 10ms -total: ${formatMs(totalDurationMs)} -average: ${formatMs(averageDurationMs)} -p50: ${formatMs(percentile(sortedDurationsMs, 0.5))} -p95: ${formatMs(percentile(sortedDurationsMs, 0.95))} -p99: ${formatMs(percentile(sortedDurationsMs, 0.99))} -throughput: ${mutationsPerSecond.toFixed(2)} mutations/s -${phases}`); +Harness benchmark +single user, ${LATENCY_MUTATION_COUNT.toLocaleString()} sequential mutations: + average ${averageMs.toFixed(2)}ms, p50 ${p50Ms.toFixed(2)}ms, p99 ${p99Ms.toFixed(2)}ms +max throughput, ${THROUGHPUT_MUTATION_COUNT.toLocaleString()} concurrent mutations: + ${Math.round(mutationsPerSecond).toLocaleString()} mutations/s`); }, 300_000);