|
| 1 | +import { MAX_TX_LIFETIME } from '@aztec/constants'; |
| 2 | +import { BlockNumber } from '@aztec/foundation/branded-types'; |
| 3 | +import { sum, times } from '@aztec/foundation/collection'; |
| 4 | +import { createLogger } from '@aztec/foundation/log'; |
| 5 | +import { sleep } from '@aztec/foundation/sleep'; |
| 6 | +import { openTmpStore } from '@aztec/kv-store/lmdb-v2'; |
| 7 | +import type { AztecNode } from '@aztec/stdlib/interfaces/server'; |
| 8 | +import { AppTaggingSecretKind, type PrivateLogsQuery, randomLogResult } from '@aztec/stdlib/logs'; |
| 9 | +import { randomAppTaggingSecret } from '@aztec/stdlib/testing'; |
| 10 | +import { BlockHeader } from '@aztec/stdlib/tx'; |
| 11 | + |
| 12 | +import { mkdir, writeFile } from 'fs/promises'; |
| 13 | +import { type MockProxy, mock } from 'jest-mock-extended'; |
| 14 | +import path from 'path'; |
| 15 | + |
| 16 | +import { BenchmarkedNodeFactory } from '../../contract_function_simulator/benchmarked_node.js'; |
| 17 | +import { RecipientTaggingStore } from '../../storage/tagging_store/recipient_tagging_store.js'; |
| 18 | +import { UNFINALIZED_TAGGING_INDEXES_WINDOW_LEN, syncTaggedPrivateLogs } from '../index.js'; |
| 19 | +import { computeSiloedTagForIndex, extractTags } from '../testing/tag_query_test_utils.js'; |
| 20 | + |
| 21 | +/** |
| 22 | + * Benchmark for constrained recipient tag-sync. |
| 23 | + * |
| 24 | + * Measures the per-sync cost of `syncTaggedPrivateLogs` for constrained secrets. Constrained streams are gapless, so |
| 25 | + * the scan uses a doubling first-miss probe (see `INITIAL_CONSTRAINED_PROBE_LEN` in `../constants.ts` for the probe |
| 26 | + * schedule and complexity analysis), stopping at the first missing tag instead of fetching the full window. This only |
| 27 | + * reports costs; the scan behavior itself (probe schedules, round counts) is pinned by the unit tests in |
| 28 | + * `sync_tagged_private_logs.test.ts`, which run in CI while this bench is opt-in. |
| 29 | + * |
| 30 | + * Manual run: |
| 31 | + * ```bash |
| 32 | + * RUN_TAG_SYNC_BENCH=1 JEST_MAX_WORKERS=1 BENCH_OUTPUT=/tmp/tag-sync-bench-current.json \ |
| 33 | + * yarn workspace @aztec/pxe test src/tagging/recipient_sync/sync_tagged_private_logs.bench.test.ts |
| 34 | + * ``` |
| 35 | + * |
| 36 | + * Metrics, per scenario: |
| 37 | + * - `tag-queries`: total tags queried, the throughput win. |
| 38 | + * - `rpc-round-trips`: sequential blocking waits on the node, via `BenchmarkedNodeFactory`. The latency axis: this |
| 39 | + * grows with K per the complexity analysis on `INITIAL_CONSTRAINED_PROBE_LEN`, and depends only on K, not on secret |
| 40 | + * count. A round's tags are chunked at MAX_RPC_LEN (=100) into parallel calls internally, but those overlap, so a |
| 41 | + * wide round is still one round-trip; that is why round-trips, not raw call count, is the latency axis. |
| 42 | + * - `rpc-blocking-time`: measured wall-clock the caller blocks on the node, under a modeled |
| 43 | + * `MODELED_NODE_RPC_LATENCY_MS` per call plus a little per-round overhead. Parallel calls within a round overlap, so |
| 44 | + * it tracks round-trips (a 1000-secret round is many parallel chunks but ~one round-trip of blocking time). |
| 45 | + * |
| 46 | + * Scenario labels: `steady-state` is no new logs (K = 0); `catch-up-K` is K new contiguous logs per secret since the |
| 47 | + * last sync; `secrets=N` is N secrets synced together in one batched pass. Because round-trips depend only on K (not |
| 48 | + * N), the light catch-up scenarios run at both 100 and 1000 secrets to show tag-queries scale with N while round-trips |
| 49 | + * do not. The `mixed` row is the realistic active sync (999 idle secrets + 1 deep straggler at K = 100): it isolates |
| 50 | + * that tag-queries stay dominated by the idle majority while a single straggler alone sets the round-trip count. |
| 51 | + */ |
| 52 | + |
| 53 | +const logger = createLogger('pxe:tagging:bench'); |
| 54 | + |
| 55 | +const FINALIZED_BLOCK_NUMBER = BlockNumber(10); |
| 56 | +const ANCHOR_BLOCK_NUMBER = BlockNumber(100); |
| 57 | +const CURRENT_TIMESTAMP = BigInt(Math.floor(Date.now() / 1000)); |
| 58 | +const ANCHOR_BLOCK_HEADER = BlockHeader.random({ blockNumber: ANCHOR_BLOCK_NUMBER, timestamp: CURRENT_TIMESTAMP }); |
| 59 | +const AGED_TIMESTAMP = CURRENT_TIMESTAMP - BigInt(MAX_TX_LIFETIME) - 1000n; |
| 60 | +const JOB_ID = 'bench-job'; |
| 61 | + |
| 62 | +// Every scenario starts warm: index 0 is already persisted, so the scan resumes at index 1 rather than cold-starting. |
| 63 | +const PRIOR_FINALIZED_INDEX = 0; |
| 64 | + |
| 65 | +// Models per-call node RPC latency so round-trip blocking time is meaningful against an otherwise-instant mock node. |
| 66 | +// The round-trip *count* is independent of this value; only `rpc-blocking-time` scales with it. |
| 67 | +const MODELED_NODE_RPC_LATENCY_MS = 5; |
| 68 | + |
| 69 | +const describeBench = process.env.RUN_TAG_SYNC_BENCH ? describe : describe.skip; |
| 70 | + |
| 71 | +/** One benchmark measurement in the benchmark JSON shape. */ |
| 72 | +type BenchResult = { name: string; value: number; unit: string }; |
| 73 | + |
| 74 | +type Scenario = { |
| 75 | + label: string; |
| 76 | + kind: AppTaggingSecretKind; |
| 77 | + /** Number of secrets the recipient holds for this directional app. */ |
| 78 | + secretCount: number; |
| 79 | + /** New contiguous finalized logs available per secret since the last sync (0 = steady state). */ |
| 80 | + newLogs: number; |
| 81 | + /** |
| 82 | + * Optional heterogeneous load: the first `count` secrets get `newLogs` new logs each, the remaining |
| 83 | + * `secretCount - count` are idle (K = 0). When set, the scenario-level `newLogs` is ignored. Models a realistic |
| 84 | + * sync where most senders are quiet and a few are deep in catch-up. |
| 85 | + */ |
| 86 | + deepCohort?: { count: number; newLogs: number }; |
| 87 | +}; |
| 88 | + |
| 89 | +/** |
| 90 | + * The per-secret new-log distribution for a scenario: `deepCohort.count` secrets at `deepCohort.newLogs`, the rest |
| 91 | + * idle, or a uniform `newLogs` for every secret when no cohort is set. Single source for both log seeding and the |
| 92 | + * seeding sanity check. |
| 93 | + */ |
| 94 | +function newLogsPerSecret(scenario: Scenario): number[] { |
| 95 | + return Array.from({ length: scenario.secretCount }, (_, i) => |
| 96 | + scenario.deepCohort && i < scenario.deepCohort.count ? scenario.deepCohort.newLogs : scenario.newLogs, |
| 97 | + ); |
| 98 | +} |
| 99 | + |
| 100 | +const SCENARIOS: Scenario[] = [ |
| 101 | + // steady-state (K = 0): no new logs since the last sync, across recipient secret counts. The dominant case and where |
| 102 | + // first-miss wins by roughly the window size. |
| 103 | + ...[1, 10, 100, 1000].map(secretCount => ({ |
| 104 | + label: `constrained/steady-state/secrets=${secretCount}`, |
| 105 | + kind: AppTaggingSecretKind.CONSTRAINED, |
| 106 | + secretCount, |
| 107 | + newLogs: 0, |
| 108 | + })), |
| 109 | + // Light catch-up (K new logs per secret) at 100 and 1000 secrets. Round-trips depend only on K and P, not on N, so |
| 110 | + // the two secret counts share a round-trip count and differ only in tag-queries (10x) and blocking time. |
| 111 | + ...[100, 1000].flatMap(secretCount => |
| 112 | + [1, 3].map(newLogs => ({ |
| 113 | + label: `constrained/catch-up-${newLogs}/secrets=${secretCount}`, |
| 114 | + kind: AppTaggingSecretKind.CONSTRAINED, |
| 115 | + secretCount, |
| 116 | + newLogs, |
| 117 | + })), |
| 118 | + ), |
| 119 | + // Deep catch-up at 100 and 1000 secrets (the negative case): round-trips grow one per probe step while tag-queries |
| 120 | + // stay at the K + 1 floor. From a full window up, the WINDOW_LEN cap forces multiple rounds at any P. As with light |
| 121 | + // catch-up, round-trips depend only on K and P (not N), so the two secret counts share a round-trip count and differ |
| 122 | + // only in tag-queries (10x) and blocking time. |
| 123 | + ...[100, 1000].flatMap(secretCount => |
| 124 | + [UNFINALIZED_TAGGING_INDEXES_WINDOW_LEN, 50, 100].map(newLogs => ({ |
| 125 | + label: `constrained/catch-up-${newLogs}/secrets=${secretCount}`, |
| 126 | + kind: AppTaggingSecretKind.CONSTRAINED, |
| 127 | + secretCount, |
| 128 | + newLogs, |
| 129 | + })), |
| 130 | + ), |
| 131 | + // Mixed (the realistic active sync): 999 idle senders + 1 deep straggler (K = 100). Tag-queries stay dominated by the |
| 132 | + // idle majority, but the single straggler alone sets the round-trip count (tags are batched across all secrets per |
| 133 | + // round, so the round count equals the deepest secret's), so round-trips match catch-up-100. |
| 134 | + { |
| 135 | + label: `constrained/mixed/secrets=1000`, |
| 136 | + kind: AppTaggingSecretKind.CONSTRAINED, |
| 137 | + secretCount: 1000, |
| 138 | + newLogs: 0, |
| 139 | + deepCohort: { count: 1, newLogs: 100 }, |
| 140 | + }, |
| 141 | + // Control: unconstrained steady state is unaffected by the optimization (windowed scan cannot first-miss). |
| 142 | + { |
| 143 | + label: `unconstrained/steady-state/secrets=100`, |
| 144 | + kind: AppTaggingSecretKind.UNCONSTRAINED, |
| 145 | + secretCount: 100, |
| 146 | + newLogs: 0, |
| 147 | + }, |
| 148 | +]; |
| 149 | + |
| 150 | +describeBench('syncTaggedPrivateLogs constrained-sync bench', () => { |
| 151 | + const aztecNode: MockProxy<AztecNode> = mock<AztecNode>(); |
| 152 | + |
| 153 | + function makeFinalizedLog() { |
| 154 | + return { |
| 155 | + ...randomLogResult(/* includeEffects */ true), |
| 156 | + blockNumber: FINALIZED_BLOCK_NUMBER, |
| 157 | + blockTimestamp: AGED_TIMESTAMP, |
| 158 | + }; |
| 159 | + } |
| 160 | + |
| 161 | + async function runScenario(scenario: Scenario) { |
| 162 | + const { kind, secretCount } = scenario; |
| 163 | + const perSecretNewLogs = newLogsPerSecret(scenario); |
| 164 | + |
| 165 | + aztecNode.getPrivateLogsByTags.mockReset(); |
| 166 | + const taggingStore = new RecipientTaggingStore(await openTmpStore('bench')); |
| 167 | + const secrets = await Promise.all(Array.from({ length: secretCount }, () => randomAppTaggingSecret(kind))); |
| 168 | + |
| 169 | + // Seed the persisted finalized indexes to simulate a recipient that already synced prior finalized messages. The |
| 170 | + // per-secret writes are independent, so run them concurrently. |
| 171 | + await Promise.all( |
| 172 | + secrets.map(async secret => { |
| 173 | + await taggingStore.updateHighestFinalizedIndex(secret, PRIOR_FINALIZED_INDEX, JOB_ID); |
| 174 | + if (kind === AppTaggingSecretKind.UNCONSTRAINED) { |
| 175 | + await taggingStore.updateHighestAgedIndex(secret, PRIOR_FINALIZED_INDEX, JOB_ID); |
| 176 | + } |
| 177 | + }), |
| 178 | + ); |
| 179 | + |
| 180 | + // Tags that should resolve to a finalized log: per secret, the contiguous run |
| 181 | + // (PRIOR_FINALIZED_INDEX, PRIOR_FINALIZED_INDEX + K]. Computing the tags is independent per (secret, index). |
| 182 | + const hitTagList = await Promise.all( |
| 183 | + secrets.flatMap((secret, s) => |
| 184 | + times(perSecretNewLogs[s], i => computeSiloedTagForIndex(secret, PRIOR_FINALIZED_INDEX + i + 1)), |
| 185 | + ), |
| 186 | + ); |
| 187 | + const hitTags = new Set(hitTagList.map(tag => tag.toString())); |
| 188 | + |
| 189 | + aztecNode.getPrivateLogsByTags.mockImplementation(async (query: PrivateLogsQuery) => { |
| 190 | + await sleep(MODELED_NODE_RPC_LATENCY_MS); |
| 191 | + return extractTags(query).map(tag => (hitTags.has(tag.toString()) ? [makeFinalizedLog()] : [])); |
| 192 | + }); |
| 193 | + |
| 194 | + // Wrap the node so we capture round-trips and blocking time the same way the client_flows app benches do. The |
| 195 | + // Proxy delegates to the underlying mock, so `mock.calls` still records every query for tag counting. |
| 196 | + const benchmarkedNode = BenchmarkedNodeFactory.create(aztecNode); |
| 197 | + |
| 198 | + const logs = await syncTaggedPrivateLogs( |
| 199 | + secrets, |
| 200 | + benchmarkedNode, |
| 201 | + taggingStore, |
| 202 | + ANCHOR_BLOCK_HEADER, |
| 203 | + FINALIZED_BLOCK_NUMBER, |
| 204 | + JOB_ID, |
| 205 | + ); |
| 206 | + |
| 207 | + const calls = aztecNode.getPrivateLogsByTags.mock.calls; |
| 208 | + const tagQueries = sum(calls.map(([query]) => extractTags(query).length)); |
| 209 | + |
| 210 | + // Round-trips and blocking time from the same instrumentation the app benches use. `syncTaggedPrivateLogs` only |
| 211 | + // ever calls `getPrivateLogsByTags`, so every round-trip is that method. |
| 212 | + const { roundTrips } = benchmarkedNode.getStats(); |
| 213 | + const rpcRoundTrips = roundTrips.roundTrips; |
| 214 | + const rpcBlockingTimeMs = roundTrips.totalBlockingTime; |
| 215 | + |
| 216 | + // First-miss floor: each secret pays its K hits + 1 miss. Unconstrained cannot first-miss, so its floor is |
| 217 | + // its current cost. |
| 218 | + const firstMissOptimum = |
| 219 | + kind === AppTaggingSecretKind.CONSTRAINED ? sum(perSecretNewLogs.map(k => k + 1)) : tagQueries; |
| 220 | + |
| 221 | + return { |
| 222 | + ...scenario, |
| 223 | + logsFound: logs.length, |
| 224 | + tagQueries, |
| 225 | + rpcRoundTrips, |
| 226 | + rpcBlockingTimeMs, |
| 227 | + firstMissOptimum, |
| 228 | + }; |
| 229 | + } |
| 230 | + |
| 231 | + it('reports per-sync tag-queries, round-trips, and blocking time', async () => { |
| 232 | + const rows = []; |
| 233 | + for (const scenario of SCENARIOS) { |
| 234 | + const row = await runScenario(scenario); |
| 235 | + rows.push(row); |
| 236 | + logger.info( |
| 237 | + `${row.label.padEnd(42)} tag-queries=${String(row.tagQueries).padStart(6)} ` + |
| 238 | + `first-miss-optimum=${String(row.firstMissOptimum).padStart(6)} ` + |
| 239 | + `reduction=${(row.tagQueries / row.firstMissOptimum).toFixed(1)}x ` + |
| 240 | + `round-trips=${String(row.rpcRoundTrips).padStart(4)} ` + |
| 241 | + `blocking=${row.rpcBlockingTimeMs.toFixed(0).padStart(4)}ms logs=${String(row.logsFound).padStart(5)}`, |
| 242 | + ); |
| 243 | + |
| 244 | + // Seeding sanity check only: every seeded log must be found, or the reported numbers measure a broken harness. |
| 245 | + // Scan behavior (probe schedules, round counts) is pinned by the unit tests, which run in CI while this does not. |
| 246 | + expect(row.logsFound).toBe(sum(newLogsPerSecret(scenario))); |
| 247 | + |
| 248 | + // Steady state is one round trip by construction: every secret first-misses in round one, independent of secret |
| 249 | + // count, so a wide round's chunked parallel RPC calls must count as a single blocking wait. Guards the round-trip |
| 250 | + // accounting at widths the unit tests don't reach (they count RPC calls, not round trips). |
| 251 | + if (scenario.newLogs === 0 && !scenario.deepCohort) { |
| 252 | + expect(row.rpcRoundTrips).toBe(1); |
| 253 | + } |
| 254 | + } |
| 255 | + |
| 256 | + const results: BenchResult[] = rows.flatMap(row => [ |
| 257 | + { name: `TagSync/${row.label}/tag-queries`, value: row.tagQueries, unit: 'tag-queries' }, |
| 258 | + { name: `TagSync/${row.label}/rpc-round-trips`, value: row.rpcRoundTrips, unit: 'round_trips' }, |
| 259 | + { name: `TagSync/${row.label}/rpc-blocking-time`, value: Number(row.rpcBlockingTimeMs.toFixed(2)), unit: 'ms' }, |
| 260 | + ]); |
| 261 | + |
| 262 | + if (process.env.BENCH_OUTPUT) { |
| 263 | + await mkdir(path.dirname(process.env.BENCH_OUTPUT), { recursive: true }); |
| 264 | + await writeFile(process.env.BENCH_OUTPUT, JSON.stringify(results, null, 2)); |
| 265 | + } |
| 266 | + }, 600_000); |
| 267 | +}); |
0 commit comments