feat: measuring node round trips

benesjan · benesjan · commit 5b76b8869519 · 2026-01-14T02:12:33.000Z
diff --git a/yarn-project/cli-wallet/src/utils/profiling.ts b/yarn-project/cli-wallet/src/utils/profiling.ts
@@ -95,7 +95,7 @@ export function printProfileResult(
 
   if (stats.nodeRPCCalls) {
     log(format('\nRPC calls:\n'));
-    for (const [method, { times }] of Object.entries(stats.nodeRPCCalls)) {
+    for (const [method, { times }] of Object.entries(stats.nodeRPCCalls.perMethod)) {
       const calls = times.length;
       const total = times.reduce((acc, time) => acc + time, 0);
       const avg = total / calls;
@@ -112,6 +112,20 @@ export function printProfileResult(
         ),
       );
     }
+
+    const { roundTrips } = stats.nodeRPCCalls;
+    log(format('\nRound trips (actual blocking waits):\n'));
+    log(format('Round trips:'.padEnd(25), `${roundTrips.roundTrips}`.padStart(COLUMN_MAX_WIDTH)));
+    log(
+      format(
+        'Total blocking time:'.padEnd(25),
+        `${roundTrips.totalBlockingTime.toFixed(2)}ms`.padStart(COLUMN_MAX_WIDTH),
+      ),
+    );
+    if (roundTrips.roundTrips > 0) {
+      const avgRoundTrip = roundTrips.totalBlockingTime / roundTrips.roundTrips;
+      log(format('Avg round trip:'.padEnd(25), `${avgRoundTrip.toFixed(2)}ms`.padStart(COLUMN_MAX_WIDTH)));
+    }
   }
 
   log(format('\nSync time:'.padEnd(25), `${timings.sync?.toFixed(2)}ms`.padStart(16)));
diff --git a/yarn-project/end-to-end/src/bench/client_flows/benchmark.ts b/yarn-project/end-to-end/src/bench/client_flows/benchmark.ts
@@ -7,7 +7,13 @@ import {
 import type { Logger } from '@aztec/aztec.js/log';
 import { createLogger } from '@aztec/foundation/log';
 import { type PrivateExecutionStep, serializePrivateExecutionSteps } from '@aztec/stdlib/kernel';
-import type { ProvingStats, ProvingTimings, SimulationStats, SimulationTimings } from '@aztec/stdlib/tx';
+import type {
+  ProvingStats,
+  ProvingTimings,
+  RoundTripStats,
+  SimulationStats,
+  SimulationTimings,
+} from '@aztec/stdlib/tx';
 
 import assert from 'node:assert';
 import { mkdir, writeFile } from 'node:fs/promises';
@@ -119,6 +125,7 @@ type ClientFlowBenchmark = {
   timings: Omit<ProvingTimings & SimulationTimings, 'perFunction'> & { witgen: number };
   maxMemory: number;
   rpc: Record<string, CallRecording>;
+  roundTrips: RoundTripStats;
   proverType: ProverType;
   minimumTrace: StructuredTrace;
   totalGateCount: number;
@@ -212,6 +219,10 @@ export function generateBenchmark(
   }, []);
   const timings = stats.timings;
   const totalGateCount = steps[steps.length - 1].accGateCount;
+  const nodeRPCCalls = stats.nodeRPCCalls ?? {
+    perMethod: {},
+    roundTrips: { roundTrips: 0, totalBlockingTime: 0, roundTripDurations: [] },
+  };
   return {
     name: flow,
     timings: {
@@ -221,7 +232,7 @@ export function generateBenchmark(
       unaccounted: timings.unaccounted,
       witgen: timings.perFunction.reduce((acc, fn) => acc + fn.time, 0),
     },
-    rpc: Object.entries(stats.nodeRPCCalls ?? {}).reduce(
+    rpc: Object.entries(nodeRPCCalls.perMethod).reduce(
       (acc, [RPCName, RPCCalls]) => {
         const total = RPCCalls.times.reduce((sum, time) => sum + time, 0);
         const calls = RPCCalls.times.length;
@@ -236,6 +247,7 @@ export function generateBenchmark(
       },
       {} as Record<string, CallRecording>,
     ),
+    roundTrips: nodeRPCCalls.roundTrips,
     maxMemory,
     proverType,
     minimumTrace: minimumTrace!,
@@ -280,6 +292,16 @@ export function convertProfileToGHBenchmark(benchmark: ClientFlowBenchmark): Git
       value: totalRPCCalls,
       unit: 'calls',
     },
+    {
+      name: `${benchmark.name}/round_trips`,
+      value: benchmark.roundTrips.roundTrips,
+      unit: 'round_trips',
+    },
+    {
+      name: `${benchmark.name}/round_trips_blocking_time`,
+      value: benchmark.roundTrips.totalBlockingTime,
+      unit: 'ms',
+    },
   ];
   if (benchmark.timings.proving) {
     benches.push({
diff --git a/yarn-project/pxe/src/contract_function_simulator/contract_function_simulator.ts b/yarn-project/pxe/src/contract_function_simulator/contract_function_simulator.ts
@@ -331,7 +331,9 @@ export class ContractFunctionSimulator {
    */
   getStats() {
     const nodeRPCCalls =
-      typeof (this.aztecNode as ProxiedNode).getStats === 'function' ? (this.aztecNode as ProxiedNode).getStats() : {};
+      typeof (this.aztecNode as ProxiedNode).getStats === 'function'
+        ? (this.aztecNode as ProxiedNode).getStats()
+        : { perMethod: {}, roundTrips: { roundTrips: 0, totalBlockingTime: 0, roundTripDurations: [] } };
 
     return { nodeRPCCalls };
   }
diff --git a/yarn-project/pxe/src/contract_function_simulator/proxied_node.ts b/yarn-project/pxe/src/contract_function_simulator/proxied_node.ts
@@ -1,30 +1,69 @@
 import { Timer } from '@aztec/foundation/timer';
 import type { AztecNode } from '@aztec/stdlib/interfaces/client';
-import type { NodeStats } from '@aztec/stdlib/tx';
+import type { NodeStats, RoundTripStats } from '@aztec/stdlib/tx';
 
 /*
- * Proxy generator for an AztecNode that tracks the time taken for each RPC call.
+ * Proxy generator for an AztecNode that tracks the time taken for each RPC call
+ * and the number of round trips (actual blocking waits for node responses).
+ *
+ * A round trip is counted when we transition from 0 to 1 in-flight calls,
+ * and ends when all concurrent calls complete. This means parallel calls
+ * in Promise.all count as a single round trip.
  */
 export type ProxiedNode = AztecNode & { getStats(): NodeStats };
 
 export class ProxiedNodeFactory {
-  static create(node: AztecNode) {
-    const stats: Partial<Record<keyof AztecNode, { times: number[] }>> = {};
+  static create(node: AztecNode): ProxiedNode {
+    // Per-method call stats
+    const perMethod: Partial<Record<keyof AztecNode, { times: number[] }>> = {};
+
+    // Round trip tracking
+    let inFlightCount = 0;
+    let currentRoundTripTimer: Timer | null = null;
+    const roundTrips: RoundTripStats = {
+      roundTrips: 0,
+      totalBlockingTime: 0,
+      roundTripDurations: [],
+    };
+
     return new Proxy(node, {
       get(target, prop: keyof ProxiedNode) {
         if (prop === 'getStats') {
-          return () => {
-            return stats;
+          return (): NodeStats => {
+            return { perMethod, roundTrips };
           };
         } else {
           return async function (...args: any[]) {
-            if (!stats[prop]) {
-              stats[prop] = { times: [] };
+            // Track per-method stats
+            if (!perMethod[prop]) {
+              perMethod[prop] = { times: [] };
+            }
+
+            // Start of a new round trip batch?
+            if (inFlightCount === 0) {
+              roundTrips.roundTrips++;
+              currentRoundTripTimer = new Timer();
+            }
+            inFlightCount++;
+
+            const callTimer = new Timer();
+            try {
+              const result = await (target[prop] as any).apply(target, args);
+              return result;
+            } finally {
+              const callTime = callTimer.ms();
+              perMethod[prop].times.push(callTime);
+
+              inFlightCount--;
+
+              // End of round trip batch - all concurrent calls completed
+              if (inFlightCount === 0 && currentRoundTripTimer) {
+                const roundTripTime = currentRoundTripTimer.ms();
+                roundTrips.totalBlockingTime += roundTripTime;
+                roundTrips.roundTripDurations.push(roundTripTime);
+                currentRoundTripTimer = null;
+              }
             }
-            const timer = new Timer();
-            const result = await (target[prop] as any).apply(target, args);
-            stats[prop].times.push(timer.ms());
-            return result;
           };
         }
       },
diff --git a/yarn-project/stdlib/src/tx/profiling.ts b/yarn-project/stdlib/src/tx/profiling.ts
@@ -6,9 +6,32 @@ import { z } from 'zod';
 import type { AztecNode } from '../interfaces/aztec-node.js';
 import { type PrivateExecutionStep, PrivateExecutionStepSchema } from '../kernel/private_kernel_prover_output.js';
 
-export type NodeStats = Partial<Record<keyof AztecNode, { times: number[] }>>;
+export type RoundTripStats = {
+  /** Number of round trips (times we blocked waiting for node responses) */
+  roundTrips: number;
+  /** Total wall-clock time spent waiting on node (excludes parallel overlap) */
+  totalBlockingTime: number;
+  /** Individual round trip durations */
+  roundTripDurations: number[];
+};
+
+const RoundTripStatsSchema = z.object({
+  roundTrips: z.number(),
+  totalBlockingTime: z.number(),
+  roundTripDurations: z.array(z.number()),
+});
+
+export type NodeStats = {
+  /** Per-method call stats */
+  perMethod: Partial<Record<keyof AztecNode, { times: number[] }>>;
+  /** Round trip stats tracking actual blocking waits */
+  roundTrips: RoundTripStats;
+};
 
-const NodeStatsSchema = z.record(z.string(), z.object({ times: z.array(z.number()) }));
+const NodeStatsSchema = z.object({
+  perMethod: z.record(z.string(), z.object({ times: z.array(z.number()) })),
+  roundTrips: RoundTripStatsSchema,
+});
 
 type FunctionTiming = {
   functionName: string;
@@ -105,7 +128,10 @@ export class TxProfileResult {
         },
       ],
       {
-        nodeRPCCalls: { getBlockHeader: { times: [1] } },
+        nodeRPCCalls: {
+          perMethod: { getBlockHeader: { times: [1] } },
+          roundTrips: { roundTrips: 1, totalBlockingTime: 1, roundTripDurations: [1] },
+        },
         timings: {
           sync: 1,
           proving: 1,
@@ -140,7 +166,10 @@ export class UtilitySimulationResult {
 
   static random(): UtilitySimulationResult {
     return new UtilitySimulationResult([Fr.random()], {
-      nodeRPCCalls: { getBlockHeader: { times: [1] } },
+      nodeRPCCalls: {
+        perMethod: { getBlockHeader: { times: [1] } },
+        roundTrips: { roundTrips: 1, totalBlockingTime: 1, roundTripDurations: [1] },
+      },
       timings: {
         sync: 1,
         publicSimulation: 1,
