Add EVM profiler

packages/client/bin/cli.ts

@@ -344,6 +344,16 @@ const args: ClientOpts = yargs(hideBin(process.argv))
       'To run client in single node configuration without need to discover the sync height from peer. Particularly useful in test configurations. This flag is automically activated in the "dev" mode',
     boolean: true,
   })
+  .option('vmProfileBlocks', {
+    describe: 'Report the VM profile after running each block',
+    boolean: true,
+    default: false,
+  })
+  .option('vmProfileTxs', {
+    describe: 'Report the VM profile after running each block',
+    boolean: true,
+    default: false,
+  })
   .option('loadBlocksFromRlp', {
     describe: 'path to a file of RLP encoded blocks',
     string: true,
@@ -816,6 +826,8 @@ async function run() {
     mine,
     minerCoinbase: args.minerCoinbase,
     isSingleNode,
+    vmProfileBlocks: args.vmProfileBlocks,
+    vmProfileTxs: args.vmProfileTxs,
     minPeers: args.minPeers,
     multiaddrs,
     port: args.port,

packages/client/src/config.ts

@@ -11,7 +11,7 @@ import type { Logger } from './logging'
 import type { EventBusType, MultiaddrLike } from './types'
 import type { BlockHeader } from '@ethereumjs/block'
 import type { Address } from '@ethereumjs/util'
-import type { VM } from '@ethereumjs/vm'
+import type { VM, VMProfilerOpts } from '@ethereumjs/vm'
 import type { Multiaddr } from 'multiaddr'
 
 export enum DataDirectory {
@@ -251,6 +251,16 @@ export interface ConfigOptions {
    */
   isSingleNode?: boolean
 
+  /**
+   * Whether to profile VM blocks
+   */
+  vmProfileBlocks?: boolean
+
+  /**
+   * Whether to profile VM txs
+   */
+  vmProfileTxs?: boolean
+
   /**
    * Unlocked accounts of form [address, privateKey]
    * Currently only the first account is used to seal mined PoA blocks
@@ -376,6 +386,7 @@ export class Config {
   public readonly isSingleNode: boolean
   public readonly accounts: [address: Address, privKey: Uint8Array][]
   public readonly minerCoinbase?: Address
+  public readonly vmProfilerOpts?: VMProfilerOpts
 
   public readonly safeReorgDistance: number
   public readonly skeletonFillCanonicalBackStep: number
@@ -434,6 +445,14 @@ export class Config {
     this.debugCode = options.debugCode ?? Config.DEBUGCODE_DEFAULT
     this.mine = options.mine ?? false
     this.isSingleNode = options.isSingleNode ?? false
+
+    if (options.vmProfileBlocks !== undefined || options.vmProfileTxs !== undefined) {
+      this.vmProfilerOpts = {
+        reportProfilerAfterBlock: options.vmProfileBlocks !== false,
+        reportProfilerAfterTx: options.vmProfileTxs !== false,
+      }
+    }
+
     this.accounts = options.accounts ?? []
     this.minerCoinbase = options.minerCoinbase
 

packages/client/src/execution/vmexecution.ts

@@ -76,6 +76,7 @@ export class VMExecution extends Execution {
         common: this.config.execCommon,
         blockchain: this.chain.blockchain,
         stateManager,
+        profilerOpts: this.config.vmProfilerOpts,
       })
     } else {
       this.vm = this.config.vm

packages/client/src/types.ts

@@ -157,5 +157,7 @@ export interface ClientOpts {
   txLookupLimit?: number
   startBlock?: number
   isSingleNode?: boolean
+  vmProfileBlocks?: boolean
+  vmProfileTxs?: boolean
   loadBlocksFromRlp?: string
 }

packages/evm/src/evm.ts

@@ -20,13 +20,15 @@
 import { ERROR, EvmError } from './exceptions.js'
 import { Interpreter } from './interpreter.js'
 import { Journal } from './journal.js'
+import { EVMPerformanceLogger } from './logger.js'
 import { Message } from './message.js'
 import { getOpcodesForHF } from './opcodes/index.js'
-import { getActivePrecompiles } from './precompiles/index.js'
+import { getActivePrecompiles, getPrecompileName } from './precompiles/index.js'
 import { TransientStorage } from './transientStorage.js'
 import { DefaultBlockchain } from './types.js'
 
 import type { InterpreterOpts } from './interpreter.js'
+import type { Timer } from './logger.js'
 import type { MessageWithTo } from './message.js'
 import type { AsyncDynamicGasHandler, SyncDynamicGasHandler } from './opcodes/gas.js'
 import type { OpHandler, OpcodeList } from './opcodes/index.js'
@@ -108,6 +110,8 @@
 
   protected readonly _optsCached: EVMOpts
 
+  protected performanceLogger: EVMPerformanceLogger
+
   public get precompiles() {
     return this._precompiles
   }
@@ -191,6 +195,8 @@
       return new Promise((resolve) => this.events.emit(topic as keyof EVMEvents, data, resolve))
     }
 
+    this.performanceLogger = new EVMPerformanceLogger()
+
     // Skip DEBUG calls unless 'ethjs' included in environmental DEBUG variables
     // Additional window check is to prevent vite browser bundling (and potentially other) to break
     this.DEBUG =
@@ -265,11 +271,23 @@
 
     let result: ExecResult
     if (message.isCompiled) {
+      let timer: Timer
+      let target: string
+      if (this._optsCached.profiler?.enabled === true) {
+        target = bytesToUnprefixedHex(message.codeAddress.bytes)
+        // TODO: map target precompile not to address, but to a name
+        target = getPrecompileName(target) ?? target.slice(20)
+        timer = this.performanceLogger.startTimer(target)
+      }
       result = await this.runPrecompile(
         message.code as PrecompileFunc,
         message.data,
         message.gasLimit
       )
+
+      if (this._optsCached.profiler?.enabled === true) {
+        this.performanceLogger.stopTimer(timer!, Number(result.executionGasUsed), 'precompiles')
+      }
       result.gasRefund = message.gasRefund
     } else {
       if (this.DEBUG) {
@@ -557,7 +575,9 @@
       this.blockchain,
       env,
       message.gasLimit,
-      this.journal
+      this.journal,
+      this.performanceLogger,
+      this._optsCached.profiler
     )
     if (message.selfdestruct) {
       interpreter._result.selfdestruct = message.selfdestruct
@@ -885,6 +905,14 @@
     ;(opts.stateManager as any).common = common
     return new EVM(opts)
   }
+
+  public getPerformanceLogs() {
+    return this.performanceLogger.getLogs()
+  }
+
+  public clearPerformanceLogs() {
+    this.performanceLogger.clear()
+  }
 }
 
 export function OOGResult(gasLimit: bigint): ExecResult {

packages/evm/src/interpreter.ts

@@ -18,8 +18,9 @@
 
 import type { EVM } from './evm.js'
 import type { Journal } from './journal.js'
+import type { EVMPerformanceLogger, Timer } from './logger.js'
 import type { AsyncOpHandler, OpHandler, Opcode } from './opcodes/index.js'
-import type { Block, Blockchain, EVMResult, Log } from './types.js'
+import type { Block, Blockchain, EVMProfilerOpts, EVMResult, Log } from './types.js'
 import type { Common, EVMStateManagerInterface } from '@ethereumjs/common'
 import type { Address } from '@ethereumjs/util'
 const { debug: createDebugLogger } = debugDefault
@@ -133,14 +134,19 @@
   // Opcode debuggers (e.g. { 'push': [debug Object], 'sstore': [debug Object], ...})
   private opDebuggers: { [key: string]: (debug: string) => void } = {}
 
+  private profilerOpts?: EVMProfilerOpts
+  private performanceLogger: EVMPerformanceLogger
+
   // TODO remove gasLeft as constructor argument
   constructor(
     evm: EVM,
     stateManager: EVMStateManagerInterface,
     blockchain: Blockchain,
     env: Env,
     gasLeft: bigint,
-    journal: Journal
+    journal: Journal,
+    performanceLogs: EVMPerformanceLogger,
+    profilerOpts?: EVMProfilerOpts
   ) {
     this._evm = evm
     this._stateManager = stateManager
@@ -171,6 +177,8 @@
       returnValue: undefined,
       selfdestruct: new Set(),
     }
+    this.profilerOpts = profilerOpts
+    this.performanceLogger = performanceLogs
   }
 
   async run(code: Uint8Array, opts: InterpreterOpts = {}): Promise<InterpreterResult> {
@@ -259,41 +267,54 @@
   async runStep(): Promise<void> {
     const opInfo = this.lookupOpInfo(this._runState.opCode)
 
-    let gas = BigInt(opInfo.fee)
-    // clone the gas limit; call opcodes can add stipend,
-    // which makes it seem like the gas left increases
-    const gasLimitClone = this.getGasLeft()
-
-    if (opInfo.dynamicGas) {
-      const dynamicGasHandler = (this._evm as any)._dynamicGasHandlers.get(this._runState.opCode)!
-      // This function updates the gas in-place.
-      // It needs the base fee, for correct gas limit calculation for the CALL opcodes
-      gas = await dynamicGasHandler(this._runState, gas, this.common)
-    }
+    let timer: Timer
 
-    if (this._evm.events.listenerCount('step') > 0 || this._evm.DEBUG) {
-      // Only run this stepHook function if there is an event listener (e.g. test runner)
-      // or if the vm is running in debug mode (to display opcode debug logs)
-      await this._runStepHook(gas, gasLimitClone)
+    if (this.profilerOpts?.enabled === true) {
+      timer = this.performanceLogger.startTimer(opInfo.name)
     }
 
-    // Check for invalid opcode
-    if (opInfo.name === 'INVALID') {
-      throw new EvmError(ERROR.INVALID_OPCODE)
-    }
+    let gas = BigInt(opInfo.fee)
 
-    // Reduce opcode's base fee
-    this.useGas(gas, `${opInfo.name} fee`)
-    // Advance program counter
-    this._runState.programCounter++
+    try {
+      // clone the gas limit; call opcodes can add stipend,
+      // which makes it seem like the gas left increases
+      const gasLimitClone = this.getGasLeft()
 
-    // Execute opcode handler
-    const opFn = this.getOpHandler(opInfo)
+      if (opInfo.dynamicGas) {
+        const dynamicGasHandler = (this._evm as any)._dynamicGasHandlers.get(this._runState.opCode)!
+        // This function updates the gas in-place.
+        // It needs the base fee, for correct gas limit calculation for the CALL opcodes
+        gas = await dynamicGasHandler(this._runState, gas, this.common)
+      }
 
-    if (opInfo.isAsync) {
-      await (opFn as AsyncOpHandler).apply(null, [this._runState, this.common])
-    } else {
-      opFn.apply(null, [this._runState, this.common])
+      if (this._evm.events.listenerCount('step') > 0 || this._evm.DEBUG) {
+        // Only run this stepHook function if there is an event listener (e.g. test runner)
+        // or if the vm is running in debug mode (to display opcode debug logs)
+        await this._runStepHook(gas, gasLimitClone)
+      }
+
+      // Check for invalid opcode
+      if (opInfo.name === 'INVALID') {
+        throw new EvmError(ERROR.INVALID_OPCODE)
+      }
+
+      // Reduce opcode's base fee
+      this.useGas(gas, `${opInfo.name} fee`)
+      // Advance program counter
+      this._runState.programCounter++
+
+      // Execute opcode handler
+      const opFn = this.getOpHandler(opInfo)
+
+      if (opInfo.isAsync) {
+        await (opFn as AsyncOpHandler).apply(null, [this._runState, this.common])
+      } else {
+        opFn.apply(null, [this._runState, this.common])
+      }
+    } finally {
+      if (this.profilerOpts?.enabled === true) {
+        this.performanceLogger.stopTimer(timer!, Number(gas), 'opcodes')
+      }
     }
   }
 
@@ -872,7 +893,14 @@
       return BigInt(0)
     }
 
+    let timer: Timer
+    if (this.profilerOpts?.enabled === true) {
+      timer = this.performanceLogger.pauseTimer()
+    }
     const results = await this._evm.runCall({ message: msg })
+    if (this.profilerOpts?.enabled === true) {
+      this.performanceLogger.unpauseTimer(timer!)
+    }
 
     if (results.execResult.logs) {
       this._result.logs = this._result.logs.concat(results.execResult.logs)
@@ -971,7 +999,14 @@
       message.createdAddresses = createdAddresses
     }
 
+    let timer: Timer
+    if (this.profilerOpts?.enabled === true) {
+      timer = this.performanceLogger.pauseTimer()
+    }
     const results = await this._evm.runCall({ message })
+    if (this.profilerOpts?.enabled === true) {
+      this.performanceLogger.unpauseTimer(timer!)
+    }
 
     if (results.execResult.logs) {
       this._result.logs = this._result.logs.concat(results.execResult.logs)