chore: track avm proving time

yarn-project/bb-prover/src/avm_proving.test.ts

@@ -248,12 +248,14 @@ const proveAndVerifyAvmTestContract = async (
     startGas,
     context,
     simulator.getBytecode(),
+    functionName,
   );
   // TODO(dbanks12): public inputs should not be empty.... Need to construct them from AvmContext?
   const uncompressedBytecode = simulator.getBytecode()!;
   const publicInputs = getPublicInputs(pxResult);
 
   const avmCircuitInputs = new AvmCircuitInputs(
+    functionName,
     uncompressedBytecode,
     context.environment.calldata,
     publicInputs,

yarn-project/bb-prover/src/prover/bb_native_proof_creator.ts

@@ -42,6 +42,7 @@ import { type NoirCompiledCircuit } from '@aztec/types/noir';
 import { serializeWitness } from '@noir-lang/noirc_abi';
 import { type WitnessMap } from '@noir-lang/types';
 import * as fs from 'fs/promises';
+import { join } from 'path';
 
 import {
   BB_RESULT,
@@ -175,7 +176,7 @@ export class BBNativeProofCreator implements ProofCreator {
       throw new Error(errorMessage);
     }
 
-    this.log.info(`Successfully verified ${circuitType} proof in ${result.duration} ms`);
+    this.log.info(`Successfully verified ${circuitType} proof in ${Math.ceil(result.duration)} ms`);
   }
 
   private async verifyProofFromKey(
@@ -304,13 +305,14 @@ export class BBNativeProofCreator implements ProofCreator {
   }> {
     const compressedBincodedWitness = serializeWitness(partialWitness);
 
-    const inputsWitnessFile = `${directory}/witness.gz`;
+    const inputsWitnessFile = join(directory, 'witness.gz');
 
     await fs.writeFile(inputsWitnessFile, compressedBincodedWitness);
 
     this.log.debug(`Written ${inputsWitnessFile}`);
 
-    this.log.info(`Proving ${circuitType} circuit...`);
+    const dbgCircuitName = appCircuitName ? `(${appCircuitName})` : '';
+    this.log.info(`Proving ${circuitType}${dbgCircuitName} circuit...`);
 
     const timer = new Timer();
 
@@ -324,13 +326,11 @@ export class BBNativeProofCreator implements ProofCreator {
     );
 
     if (provingResult.status === BB_RESULT.FAILURE) {
-      this.log.error(`Failed to generate proof for ${circuitType}: ${provingResult.reason}`);
+      this.log.error(`Failed to generate proof for ${circuitType}${dbgCircuitName}: ${provingResult.reason}`);
       throw new Error(provingResult.reason);
     }
 
-    this.log.info(
-      `Generated ${circuitType === 'App' ? appCircuitName : circuitType} circuit proof in ${timer.ms()} ms`,
-    );
+    this.log.info(`Generated ${circuitType}${dbgCircuitName} circuit proof in ${Math.ceil(timer.ms())} ms`);
 
     if (circuitType === 'App') {
       const vkData = await extractVkData(directory);

yarn-project/bb-prover/src/prover/bb_prover.ts

@@ -439,35 +439,30 @@ export class BBNativeRollupProver implements ServerCircuitProver {
       const rawProof = await fs.readFile(`${provingResult.proofPath!}/${PROOF_FILENAME}`);
 
       const proof = new Proof(rawProof, vkData.numPublicInputs);
-      logger.info(
-        `Generated proof for ${circuitType} in ${Math.ceil(provingResult.duration)} ms, size: ${
-          proof.buffer.length
-        } bytes`,
-        {
-          circuitName: mapProtocolArtifactNameToCircuitName(circuitType),
-          // does not include reading the proof from disk
-          duration: provingResult.duration,
-          proofSize: proof.buffer.length,
-          eventName: 'circuit-proving',
-          // circuitOutput is the partial witness that became the input to the proof
-          inputSize: output.toBuffer().length,
-          circuitSize: vkData.circuitSize,
-          numPublicInputs: vkData.numPublicInputs,
-        } satisfies CircuitProvingStats,
-      );
+      logger.info(`Generated proof for ${circuitType} in ${Math.ceil(provingResult.duration)} ms`, {
+        circuitName: mapProtocolArtifactNameToCircuitName(circuitType),
+        // does not include reading the proof from disk
+        duration: provingResult.duration,
+        proofSize: proof.buffer.length,
+        eventName: 'circuit-proving',
+        // circuitOutput is the partial witness that became the input to the proof
+        inputSize: output.toBuffer().length,
+        circuitSize: vkData.circuitSize,
+        numPublicInputs: vkData.numPublicInputs,
+      } satisfies CircuitProvingStats);
 
       return { circuitOutput: output, proof };
     };
     return await runInDirectory(this.config.bbWorkingDirectory, operation);
   }
 
   private async generateAvmProofWithBB(input: AvmCircuitInputs, workingDirectory: string): Promise<BBSuccess> {
-    logger.debug(`Proving avm-circuit...`);
+    logger.info(`Proving avm-circuit for ${input.functionName}...`);
 
     const provingResult = await generateAvmProof(this.config.bbBinaryPath, workingDirectory, input, logger.verbose);
 
     if (provingResult.status === BB_RESULT.FAILURE) {
-      logger.error(`Failed to generate proof for avm-circuit: ${provingResult.reason}`);
+      logger.error(`Failed to generate AVM proof for ${input.functionName}: ${provingResult.reason}`);
       throw new Error(provingResult.reason);
     }
 
@@ -490,18 +485,17 @@ export class BBNativeRollupProver implements ServerCircuitProver {
 
       const circuitType = 'avm-circuit' as const;
       logger.info(
-        `Generated proof for ${circuitType} in ${Math.ceil(provingResult.duration)} ms, size: ${
-          proof.buffer.length
-        } bytes`,
+        `Generated proof for ${circuitType}(${input.functionName}) in ${Math.ceil(provingResult.duration)} ms`,
         {
           circuitName: circuitType,
+          appCircuitName: input.functionName,
           // does not include reading the proof from disk
           duration: provingResult.duration,
           proofSize: proof.buffer.length,
           eventName: 'circuit-proving',
           inputSize: input.toBuffer().length,
-          circuitSize: verificationKey.circuitSize,
-          numPublicInputs: verificationKey.numPublicInputs,
+          circuitSize: verificationKey.circuitSize, // FIX: wrong in VK
+          numPublicInputs: verificationKey.numPublicInputs, // FIX: wrong in VK
         } satisfies CircuitProvingStats,
       );
 

yarn-project/circuit-types/src/tx/processed_tx.ts

@@ -54,6 +54,7 @@ export const AVM_REQUEST = 'AVM' as const;
 
 export type AvmProvingRequest = {
   type: typeof AVM_REQUEST;
+  functionName: string; // informational only
   bytecode: Buffer;
   calldata: Fr[];
   avmHints: AvmExecutionHints;

yarn-project/circuits.js/src/structs/avm/avm.ts

@@ -367,6 +367,7 @@ export class AvmExecutionHints {
 
 export class AvmCircuitInputs {
   constructor(
+    public readonly functionName: string, // only informational
     public readonly bytecode: Buffer,
     public readonly calldata: Fr[],
     public readonly publicInputs: PublicCircuitPublicInputs,
@@ -378,7 +379,10 @@ export class AvmCircuitInputs {
    * @returns - The inputs serialized to a buffer.
    */
   toBuffer() {
+    const functionNameBuffer = Buffer.from(this.functionName);
     return serializeToBuffer(
+      functionNameBuffer.length,
+      functionNameBuffer,
       this.bytecode.length,
       this.bytecode,
       this.calldata.length,
@@ -402,7 +406,11 @@ export class AvmCircuitInputs {
    */
   isEmpty(): boolean {
     return (
-      this.bytecode.length == 0 && this.calldata.length == 0 && this.publicInputs.isEmpty() && this.avmHints.isEmpty()
+      this.functionName.length == 0 &&
+      this.bytecode.length == 0 &&
+      this.calldata.length == 0 &&
+      this.publicInputs.isEmpty() &&
+      this.avmHints.isEmpty()
     );
   }
 
@@ -421,7 +429,7 @@ export class AvmCircuitInputs {
    * @returns An array of fields.
    */
   static getFields(fields: FieldsOf<AvmCircuitInputs>) {
-    return [fields.bytecode, fields.calldata, fields.publicInputs, fields.avmHints] as const;
+    return [fields.functionName, fields.bytecode, fields.calldata, fields.publicInputs, fields.avmHints] as const;
   }
 
   /**
@@ -432,8 +440,9 @@ export class AvmCircuitInputs {
   static fromBuffer(buff: Buffer | BufferReader): AvmCircuitInputs {
     const reader = BufferReader.asReader(buff);
     return new AvmCircuitInputs(
-      reader.readBuffer(),
-      reader.readVector(Fr),
+      /*functionName=*/ reader.readBuffer().toString(),
+      /*bytecode=*/ reader.readBuffer(),
+      /*calldata=*/ reader.readVector(Fr),
       PublicCircuitPublicInputs.fromBuffer(reader),
       AvmExecutionHints.fromBuffer(reader),
     );

yarn-project/circuits.js/src/tests/factories.ts

@@ -1336,6 +1336,7 @@ export function makeAvmExecutionHints(
  */
 export function makeAvmCircuitInputs(seed = 0, overrides: Partial<FieldsOf<AvmCircuitInputs>> = {}): AvmCircuitInputs {
   return AvmCircuitInputs.from({
+    functionName: `function${seed}`,
     bytecode: makeBytes((seed % 100) + 100, seed),
     calldata: makeArray((seed % 100) + 10, i => new Fr(i), seed + 0x1000),
     publicInputs: makePublicCircuitPublicInputs(seed + 0x2000),

yarn-project/prover-client/src/orchestrator/orchestrator.ts

@@ -772,6 +772,7 @@ export class ProvingOrchestrator {
       // Nothing downstream depends on the AVM proof yet. So having this mode lets us incrementally build the AVM circuit.
       const doAvmProving = async (signal: AbortSignal) => {
         const inputs: AvmCircuitInputs = new AvmCircuitInputs(
+          publicFunction.vmRequest!.functionName,
           publicFunction.vmRequest!.bytecode,
           publicFunction.vmRequest!.calldata,
           publicFunction.vmRequest!.kernelRequest.inputs.publicCall.callStackItem.publicInputs,

yarn-project/scripts/src/benchmarks/aggregate.ts

@@ -134,14 +134,25 @@ function processCircuitSimulation(entry: CircuitSimulationStats, results: Benchm
  */
 function processCircuitProving(entry: CircuitProvingStats, results: BenchmarkCollectedResults) {
   if (entry.circuitName === 'app-circuit') {
-    const bucket = entry.appCircuitName;
-    if (!bucket) {
+    if (!entry.appCircuitName) {
       return;
     }
+    const bucket = entry.appCircuitName;
     append(results, 'app_circuit_proving_time_in_ms', bucket, entry.duration);
     append(results, 'app_circuit_proof_size_in_bytes', bucket, entry.proofSize);
     append(results, 'app_circuit_size_in_gates', bucket, entry.circuitSize);
     append(results, 'app_circuit_num_public_inputs', bucket, entry.numPublicInputs);
+  } else if (entry.circuitName === 'avm-circuit') {
+    if (!entry.appCircuitName) {
+      return;
+    }
+    const bucket = `${entry.appCircuitName} (avm)`;
+    append(results, 'app_circuit_proving_time_in_ms', bucket, entry.duration);
+    append(results, 'app_circuit_proof_size_in_bytes', bucket, entry.proofSize);
+    append(results, 'app_circuit_input_size_in_bytes', bucket, entry.inputSize);
+    // These are not yet correctly passed in bb_prover.ts.
+    // append(results, 'app_circuit_size_in_gates', bucket, entry.circuitSize);
+    // append(results, 'app_circuit_num_public_inputs', bucket, entry.numPublicInputs);
   } else {
     const bucket = entry.circuitName;
     append(results, 'protocol_circuit_proving_time_in_ms', bucket, entry.duration);

yarn-project/simulator/src/avm/opcodes/external_calls.ts

@@ -94,13 +94,19 @@ abstract class ExternalCall extends Instruction {
     const oldStyleExecution = createPublicExecution(startSideEffectCounter, nestedContext.environment, calldata);
     const simulator = new AvmSimulator(nestedContext);
     const nestedCallResults: AvmContractCallResults = await simulator.execute();
+    const functionName =
+      (await nestedContext.persistableState.hostStorage.contractsDb.getDebugFunctionName(
+        nestedContext.environment.address,
+        nestedContext.environment.temporaryFunctionSelector,
+      )) ?? `${nestedContext.environment.address}:${nestedContext.environment.temporaryFunctionSelector}`;
     const pxResults = convertAvmResultsToPxResult(
       nestedCallResults,
       startSideEffectCounter,
       oldStyleExecution,
       Gas.from(allocatedGas),
       nestedContext,
       simulator.getBytecode(),
+      functionName,
     );
     // store the old PublicExecutionResult object to maintain a recursive data structure for the old kernel
     context.persistableState.transitionalExecutionResult.nestedExecutions.push(pxResults);

yarn-project/simulator/src/mocks/fixtures.ts

@@ -144,6 +144,7 @@ export class PublicExecutionResultBuilder {
       transactionFee: Fr.ZERO,
       calldata: [],
       avmHints: AvmExecutionHints.empty(),
+      functionName: 'unknown',
       ...overrides,
     };
   }

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

@@ -77,6 +77,7 @@ export const PhaseIsRevertible: Record<PublicKernelType, boolean> = {
 };
 
 export type PublicProvingInformation = {
+  functionName: string; // informational only
   calldata: Fr[];
   bytecode: Buffer;
   inputs: PublicKernelCircuitPrivateInputs;
@@ -89,6 +90,7 @@ export function makeAvmProvingRequest(
 ): AvmProvingRequest {
   return {
     type: AVM_REQUEST,
+    functionName: info.functionName,
     bytecode: info.bytecode,
     calldata: info.calldata,
     avmHints: info.avmHints,
@@ -282,15 +284,17 @@ export abstract class AbstractPhaseManager {
         const functionSelector = result.execution.functionSelector.toString();
         if (result.reverted && !result.revertReason) {
           throw new Error(
-            `Simulation of ${result.execution.contractAddress.toString()}:${functionSelector} reverted with no reason.`,
+            `Simulation of ${result.execution.contractAddress.toString()}:${functionSelector}(${
+              result.functionName
+            }) reverted with no reason.`,
           );
         }
 
         if (result.reverted && !PhaseIsRevertible[this.phase]) {
           this.log.debug(
-            `Simulation error on ${result.execution.contractAddress.toString()}:${functionSelector} with reason: ${
-              result.revertReason
-            }`,
+            `Simulation error on ${result.execution.contractAddress.toString()}:${functionSelector}(${
+              result.functionName
+            }) with reason: ${result.revertReason}`,
           );
           throw result.revertReason;
         }
@@ -302,14 +306,17 @@ export abstract class AbstractPhaseManager {
 
         // Simulate the public kernel circuit.
         this.log.debug(
-          `Running public kernel circuit for ${result.execution.contractAddress.toString()}:${functionSelector}`,
+          `Running public kernel circuit for ${result.execution.contractAddress.toString()}:${functionSelector}(${
+            result.functionName
+          })`,
         );
         const callData = await this.getPublicCallData(result, isExecutionRequest);
         const [privateInputs, publicInputs] = await this.runKernelCircuit(kernelPublicOutput, callData);
         kernelPublicOutput = publicInputs;
 
         // Capture the inputs for later proving in the AVM and kernel.
         const publicProvingInformation: PublicProvingInformation = {
+          functionName: result.functionName,
           calldata: result.calldata,
           bytecode: result.bytecode!,
           inputs: privateInputs,
@@ -322,17 +329,19 @@ export abstract class AbstractPhaseManager {
         // but the kernel carries the reverted flag forward. But if the simulator reverts, so should the kernel.
         if (result.reverted && kernelPublicOutput.revertCode.isOK()) {
           throw new Error(
-            `Public kernel circuit did not revert on ${result.execution.contractAddress.toString()}:${functionSelector}, but simulator did.`,
+            `Public kernel circuit did not revert on ${result.execution.contractAddress.toString()}:${functionSelector}(${
+              result.functionName
+            }), but simulator did.`,
           );
         }
 
         // We know the phase is revertible due to the above check.
         // So safely return the revert reason and the kernel output (which has had its revertible side effects dropped)
         if (result.reverted) {
           this.log.debug(
-            `Reverting on ${result.execution.contractAddress.toString()}:${functionSelector} with reason: ${
-              result.revertReason
-            }`,
+            `Reverting on ${result.execution.contractAddress.toString()}:${functionSelector}(${
+              result.functionName
+            }) with reason: ${result.revertReason}`,
           );
           // TODO(@spalladino): Check gasUsed is correct. The AVM should take care of setting gasLeft to zero upon a revert.
           return {

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

@@ -77,6 +77,8 @@ export interface PublicExecutionResult {
   calldata: Fr[];
   /** Hints for proving AVM execution. */
   avmHints: AvmExecutionHints;
+  /** The name of the function that was executed. Only used for logging. */
+  functionName: string;
 }
 
 /**

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

@@ -43,7 +43,7 @@ export class PublicExecutor {
     const address = execution.contractAddress;
     const selector = execution.functionSelector;
     const startGas = availableGas;
-    const fnName = await this.contractsDb.getDebugFunctionName(address, selector);
+    const fnName = (await this.contractsDb.getDebugFunctionName(address, selector)) ?? `${address}:${selector}`;
 
     PublicExecutor.log.verbose(`[AVM] Executing public external function ${fnName}.`);
     const timer = new Timer();
@@ -83,7 +83,7 @@ export class PublicExecutor {
       }.`,
       {
         eventName: 'avm-simulation',
-        appCircuitName: fnName ?? 'unknown',
+        appCircuitName: fnName,
         duration: timer.ms(),
         bytecodeSize: bytecode!.length,
       } satisfies AvmSimulationStats,
@@ -96,6 +96,7 @@ export class PublicExecutor {
       startGas,
       avmContext,
       bytecode,
+      fnName,
     );
 
     // TODO(https://github.com/AztecProtocol/aztec-packages/issues/5818): is this really needed?