chore: add traces and histograms to avm simulator (#10233)

Add a histogram for tracking the gas/second of avm enqueued call
simulations.

Assert that we are above 2.5 Mgas/second in the public transfer test. 

Also some traces at the enqueued call level.

See graph attached. Interestingly, `transfer_in_public` sits constantly
around 5.5 Mgas/s, but `total_supply` was the worst at around 3 Mgas/s.

<img width="957" alt="Screenshot 2024-11-26 at 21 17 50"
src="https://github.com/user-attachments/assets/2f99546c-77e3-47a4-8faf-622e9ac6b9b0">

fix #10145 
fix #10146

Author: just-mitch

yarn-project/end-to-end/scripts/e2e_test_config.yml

@@ -84,7 +84,8 @@ tests:
   e2e_state_vars: {}
   e2e_static_calls: {}
   e2e_synching: {}
-  e2e_token_contract: {}
+  e2e_token_contract:
+    with_alerts: true
   e2e_p2p_gossip:
     test_path: 'e2e_p2p/gossip_network.test.ts'
     with_alerts: true

yarn-project/end-to-end/src/e2e_token_contract/token_contract_test.ts

@@ -14,7 +14,7 @@ import {
 import { mintTokensToPrivate } from '../fixtures/token_utils.js';
 import { TokenSimulator } from '../simulators/token_simulator.js';
 
-const { E2E_DATA_PATH: dataPath } = process.env;
+const { E2E_DATA_PATH: dataPath, METRICS_PORT: metricsPort } = process.env;
 
 export class TokenContractTest {
   static TOKEN_NAME = 'USDC';
@@ -30,7 +30,9 @@ export class TokenContractTest {
 
   constructor(testName: string) {
     this.logger = createDebugLogger(`aztec:e2e_token_contract:${testName}`);
-    this.snapshotManager = createSnapshotManager(`e2e_token_contract/${testName}`, dataPath);
+    this.snapshotManager = createSnapshotManager(`e2e_token_contract/${testName}`, dataPath, {
+      metricsPort: metricsPort ? parseInt(metricsPort) : undefined,
+    });
   }
 
   /**

yarn-project/end-to-end/src/e2e_token_contract/transfer_in_public.test.ts

@@ -1,8 +1,23 @@
 import { Fr } from '@aztec/aztec.js';
 
 import { U128_UNDERFLOW_ERROR } from '../fixtures/fixtures.js';
+import { AlertChecker, type AlertConfig } from '../quality_of_service/alert_checker.js';
 import { TokenContractTest } from './token_contract_test.js';
 
+const CHECK_ALERTS = process.env.CHECK_ALERTS === 'true';
+
+const qosAlerts: AlertConfig[] = [
+  {
+    // Dummy alert to check that the metric is being emitted.
+    // Separate benchmark tests will use dedicated machines with the published system requirements.
+    alert: 'publishing_mana_per_second',
+    expr: 'rate(aztec_public_executor_simulation_mana_per_second_per_second_sum[5m]) / rate(aztec_public_executor_simulation_mana_per_second_per_second_count[5m]) < 10',
+    for: '5m',
+    annotations: {},
+    labels: {},
+  },
+];
+
 describe('e2e_token_contract transfer public', () => {
   const t = new TokenContractTest('transfer_in_public');
   let { asset, accounts, tokenSim, wallets, badAccount } = t;
@@ -17,6 +32,10 @@ describe('e2e_token_contract transfer public', () => {
 
   afterAll(async () => {
     await t.teardown();
+    if (CHECK_ALERTS) {
+      const alertChecker = new AlertChecker(t.logger);
+      await alertChecker.runAlertCheck(qosAlerts);
+    }
   });
 
   afterEach(async () => {

yarn-project/end-to-end/src/fixtures/snapshot_manager.ts

@@ -345,7 +345,7 @@ async function setupFromFresh(
     aztecNodeConfig.bbWorkingDirectory = bbConfig.bbWorkingDirectory;
   }
 
-  const telemetry = await getEndToEndTestTelemetryClient(opts.metricsPort, /*serviceName*/ 'basenode');
+  const telemetry = await getEndToEndTestTelemetryClient(opts.metricsPort, /*serviceName*/ statePath);
 
   logger.verbose('Creating and synching an aztec node...');
   const aztecNode = await AztecNodeService.createAndSync(aztecNodeConfig, { telemetry });

yarn-project/simulator/src/public/executor_metrics.ts

@@ -3,15 +3,20 @@ import {
   type Histogram,
   Metrics,
   type TelemetryClient,
+  type Tracer,
   type UpDownCounter,
   ValueType,
+  linearBuckets,
 } from '@aztec/telemetry-client';
 
 export class ExecutorMetrics {
+  public readonly tracer: Tracer;
   private fnCount: UpDownCounter;
   private fnDuration: Histogram;
+  private manaPerSecond: Histogram;
 
   constructor(client: TelemetryClient, name = 'PublicExecutor') {
+    this.tracer = client.getTracer(name);
     const meter = client.getMeter(name);
 
     this.fnCount = meter.createUpDownCounter(Metrics.PUBLIC_EXECUTOR_SIMULATION_COUNT, {
@@ -23,13 +28,30 @@ export class ExecutorMetrics {
       unit: 'ms',
       valueType: ValueType.INT,
     });
+
+    this.manaPerSecond = meter.createHistogram(Metrics.PUBLIC_EXECUTOR_SIMULATION_MANA_PER_SECOND, {
+      description: 'Mana used per second',
+      unit: 'mana/s',
+      valueType: ValueType.INT,
+      advice: {
+        explicitBucketBoundaries: linearBuckets(0, 10_000_000, 10),
+      },
+    });
   }
 
-  recordFunctionSimulation(durationMs: number) {
+  recordFunctionSimulation(durationMs: number, manaUsed: number, fnName: string) {
     this.fnCount.add(1, {
       [Attributes.OK]: true,
+      [Attributes.APP_CIRCUIT_NAME]: fnName,
+      [Attributes.MANA_USED]: manaUsed,
     });
     this.fnDuration.record(Math.ceil(durationMs));
+    if (durationMs > 0 && manaUsed > 0) {
+      const manaPerSecond = Math.round((manaUsed * 1000) / durationMs);
+      this.manaPerSecond.record(manaPerSecond, {
+        [Attributes.APP_CIRCUIT_NAME]: fnName,
+      });
+    }
   }
 
   recordFunctionSimulationFailure() {

yarn-project/simulator/src/public/public_processor.ts

@@ -229,6 +229,9 @@ export class PublicProcessor {
     return new PublicDataWrite(leafSlot, updatedBalance);
   }
 
+  @trackSpan('PublicProcessor.processPrivateOnlyTx', (tx: Tx) => ({
+    [Attributes.TX_HASH]: tx.getTxHash().toString(),
+  }))
   private async processPrivateOnlyTx(tx: Tx): Promise<[ProcessedTx]> {
     const gasFees = this.globalVariables.gasFees;
     const transactionFee = tx.data.gasUsed.computeFee(gasFees);

yarn-project/simulator/src/public/public_tx_simulator.ts

@@ -20,7 +20,7 @@ import {
 } from '@aztec/circuits.js';
 import { type DebugLogger, createDebugLogger } from '@aztec/foundation/log';
 import { Timer } from '@aztec/foundation/timer';
-import { type TelemetryClient } from '@aztec/telemetry-client';
+import { Attributes, type TelemetryClient, type Tracer, trackSpan } from '@aztec/telemetry-client';
 
 import { type AvmFinalizedCallResult } from '../avm/avm_contract_call_result.js';
 import { type AvmPersistableStateManager, AvmSimulator } from '../avm/index.js';
@@ -55,15 +55,18 @@ export class PublicTxSimulator {
   constructor(
     private db: MerkleTreeReadOperations,
     private worldStateDB: WorldStateDB,
-    client: TelemetryClient,
+    telemetryClient: TelemetryClient,
     private globalVariables: GlobalVariables,
     private realAvmProvingRequests: boolean = true,
     private doMerkleOperations: boolean = false,
   ) {
     this.log = createDebugLogger(`aztec:public_tx_simulator`);
-    this.metrics = new ExecutorMetrics(client, 'PublicTxSimulator');
+    this.metrics = new ExecutorMetrics(telemetryClient, 'PublicTxSimulator');
   }
 
+  get tracer(): Tracer {
+    return this.metrics.tracer;
+  }
   /**
    * Simulate a transaction's public portion including all of its phases.
    * @param tx - The transaction to simulate.
@@ -244,6 +247,12 @@ export class PublicTxSimulator {
    * @param executionRequest - The execution request (includes args)
    * @returns The result of execution.
    */
+  @trackSpan('PublicTxSimulator.simulateEnqueuedCall', (phase, context, _callRequest, executionRequest) => ({
+    [Attributes.TX_HASH]: context.getTxHash().toString(),
+    [Attributes.TARGET_ADDRESS]: executionRequest.callContext.contractAddress.toString(),
+    [Attributes.SENDER_ADDRESS]: executionRequest.callContext.msgSender.toString(),
+    [Attributes.SIMULATOR_PHASE]: TxExecutionPhase[phase].toString(),
+  }))
   private async simulateEnqueuedCall(
     phase: TxExecutionPhase,
     context: PublicTxContext,
@@ -312,6 +321,12 @@ export class PublicTxSimulator {
    * @param fnName - The name of the function
    * @returns The result of execution.
    */
+  @trackSpan(
+    'PublicTxSimulator.simulateEnqueuedCallInternal',
+    (_stateManager, _executionRequest, _allocatedGas, _transactionFee, fnName) => ({
+      [Attributes.APP_CIRCUIT_NAME]: fnName,
+    }),
+  )
   private async simulateEnqueuedCallInternal(
     stateManager: AvmPersistableStateManager,
     executionRequest: PublicExecutionRequest,
@@ -356,7 +371,7 @@ export class PublicTxSimulator {
     if (result.reverted) {
       this.metrics.recordFunctionSimulationFailure();
     } else {
-      this.metrics.recordFunctionSimulation(timer.ms());
+      this.metrics.recordFunctionSimulation(timer.ms(), allocatedGas.sub(result.gasLeft).l2Gas, fnName);
     }
 
     return result;

yarn-project/telemetry-client/src/attributes.ts

@@ -83,3 +83,8 @@ export const P2P_ID = 'aztec.p2p.id';
 export const POOL_NAME = 'aztec.pool.name';
 
 export const SEQUENCER_STATE = 'aztec.sequencer.state';
+
+export const SIMULATOR_PHASE = 'aztec.simulator.phase';
+export const TARGET_ADDRESS = 'aztec.address.target';
+export const SENDER_ADDRESS = 'aztec.address.sender';
+export const MANA_USED = 'aztec.mana.used';

yarn-project/telemetry-client/src/metrics.ts

@@ -71,6 +71,7 @@ export const PUBLIC_PROCESSOR_DEPLOY_BYTECODE_SIZE = 'aztec.public_processor.dep
 
 export const PUBLIC_EXECUTOR_SIMULATION_COUNT = 'aztec.public_executor.simulation_count';
 export const PUBLIC_EXECUTOR_SIMULATION_DURATION = 'aztec.public_executor.simulation_duration';
+export const PUBLIC_EXECUTOR_SIMULATION_MANA_PER_SECOND = 'aztec.public_executor.simulation_mana_per_second';
 export const PUBLIC_EXECUTION_SIMULATION_BYTECODE_SIZE = 'aztec.public_executor.simulation_bytecode_size';
 
 export const PROVING_ORCHESTRATOR_BASE_ROLLUP_INPUTS_DURATION =

yarn-project/telemetry-client/src/otel.ts

@@ -75,7 +75,16 @@ export class OpenTelemetryClient implements TelemetryClient {
   }
 
   public async stop() {
-    await Promise.all([this.meterProvider.shutdown(), this.loggerProvider.shutdown()]);
+    const flushAndShutdown = async (provider: { forceFlush: () => Promise<void>; shutdown: () => Promise<void> }) => {
+      await provider.forceFlush();
+      await provider.shutdown();
+    };
+
+    await Promise.all([
+      flushAndShutdown(this.meterProvider),
+      flushAndShutdown(this.loggerProvider),
+      this.traceProvider instanceof NodeTracerProvider ? flushAndShutdown(this.traceProvider) : Promise.resolve(),
+    ]);
   }
 
   public static async createAndStart(config: TelemetryClientConfig, log: DebugLogger): Promise<OpenTelemetryClient> {