Add VM execution metrics to exec tile

Collect transaction-, VM, and CPI-level setup, execute, and commit
timings.

Author: riptl

book/api/metrics-generated.md

@@ -1136,6 +1136,14 @@
 | <span class="metrics-name">exec_&#8203;progcache_&#8203;dup_&#8203;inserts</span> | counter | Number of time two tiles raced to insert the same cache entry |
 | <span class="metrics-name">exec_&#8203;progcache_&#8203;invalidations</span> | counter | Number of program cache invalidations |
 | <span class="metrics-name">exec_&#8203;accdb_&#8203;created</span> | counter | Number of account database records created |
+| <span class="metrics-name">exec_&#8203;txn_&#8203;regime</span><br/>{txn_&#8203;regime="<span class="metrics-enum">setup</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in transaction execution regimes. (Transaction setup) |
+| <span class="metrics-name">exec_&#8203;txn_&#8203;regime</span><br/>{txn_&#8203;regime="<span class="metrics-enum">exec</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in transaction execution regimes. (Transaction execution (includes VM setup/execution)) |
+| <span class="metrics-name">exec_&#8203;txn_&#8203;regime</span><br/>{txn_&#8203;regime="<span class="metrics-enum">commit</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in transaction execution regimes. (Transaction result commit) |
+| <span class="metrics-name">exec_&#8203;vm_&#8203;regime</span><br/>{vm_&#8203;regime="<span class="metrics-enum">setup</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes. (VM setup) |
+| <span class="metrics-name">exec_&#8203;vm_&#8203;regime</span><br/>{vm_&#8203;regime="<span class="metrics-enum">commit</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes. (VM commit) |
+| <span class="metrics-name">exec_&#8203;vm_&#8203;regime</span><br/>{vm_&#8203;regime="<span class="metrics-enum">setup_&#8203;cpi</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes. (VM setup (CPI)) |
+| <span class="metrics-name">exec_&#8203;vm_&#8203;regime</span><br/>{vm_&#8203;regime="<span class="metrics-enum">commit_&#8203;cpi</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes. (VM commit (CPI)) |
+| <span class="metrics-name">exec_&#8203;vm_&#8203;regime</span><br/>{vm_&#8203;regime="<span class="metrics-enum">interpreter</span>"} | counter | Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes. (VM interpreter execution) |
 
 </div>
 

src/disco/metrics/generated/fd_metrics_enums.h

@@ -764,4 +764,26 @@
 #define FD_METRICS_ENUM_ROUTE_TABLE_V_MAIN_IDX  1
 #define FD_METRICS_ENUM_ROUTE_TABLE_V_MAIN_NAME "main"
 
+#define FD_METRICS_ENUM_TXN_REGIME_NAME "txn_regime"
+#define FD_METRICS_ENUM_TXN_REGIME_CNT (3UL)
+#define FD_METRICS_ENUM_TXN_REGIME_V_SETUP_IDX  0
+#define FD_METRICS_ENUM_TXN_REGIME_V_SETUP_NAME "setup"
+#define FD_METRICS_ENUM_TXN_REGIME_V_EXEC_IDX  1
+#define FD_METRICS_ENUM_TXN_REGIME_V_EXEC_NAME "exec"
+#define FD_METRICS_ENUM_TXN_REGIME_V_COMMIT_IDX  2
+#define FD_METRICS_ENUM_TXN_REGIME_V_COMMIT_NAME "commit"
+
+#define FD_METRICS_ENUM_VM_REGIME_NAME "vm_regime"
+#define FD_METRICS_ENUM_VM_REGIME_CNT (5UL)
+#define FD_METRICS_ENUM_VM_REGIME_V_SETUP_IDX  0
+#define FD_METRICS_ENUM_VM_REGIME_V_SETUP_NAME "setup"
+#define FD_METRICS_ENUM_VM_REGIME_V_COMMIT_IDX  1
+#define FD_METRICS_ENUM_VM_REGIME_V_COMMIT_NAME "commit"
+#define FD_METRICS_ENUM_VM_REGIME_V_SETUP_CPI_IDX  2
+#define FD_METRICS_ENUM_VM_REGIME_V_SETUP_CPI_NAME "setup_cpi"
+#define FD_METRICS_ENUM_VM_REGIME_V_COMMIT_CPI_IDX  3
+#define FD_METRICS_ENUM_VM_REGIME_V_COMMIT_CPI_NAME "commit_cpi"
+#define FD_METRICS_ENUM_VM_REGIME_V_INTERPRETER_IDX  4
+#define FD_METRICS_ENUM_VM_REGIME_V_INTERPRETER_NAME "interpreter"
+
 #endif /* HEADER_fd_src_disco_metrics_generated_fd_metrics_enums_h */

src/disco/metrics/generated/fd_metrics_exec.c

@@ -10,4 +10,12 @@ const fd_metrics_meta_t FD_METRICS_EXEC[FD_METRICS_EXEC_TOTAL] = {
     DECLARE_METRIC( EXEC_PROGCACHE_DUP_INSERTS, COUNTER ),
     DECLARE_METRIC( EXEC_PROGCACHE_INVALIDATIONS, COUNTER ),
     DECLARE_METRIC( EXEC_ACCDB_CREATED, COUNTER ),
+    DECLARE_METRIC_ENUM( EXEC_TXN_REGIME, COUNTER, TXN_REGIME, SETUP ),
+    DECLARE_METRIC_ENUM( EXEC_TXN_REGIME, COUNTER, TXN_REGIME, EXEC ),
+    DECLARE_METRIC_ENUM( EXEC_TXN_REGIME, COUNTER, TXN_REGIME, COMMIT ),
+    DECLARE_METRIC_ENUM( EXEC_VM_REGIME, COUNTER, VM_REGIME, SETUP ),
+    DECLARE_METRIC_ENUM( EXEC_VM_REGIME, COUNTER, VM_REGIME, COMMIT ),
+    DECLARE_METRIC_ENUM( EXEC_VM_REGIME, COUNTER, VM_REGIME, SETUP_CPI ),
+    DECLARE_METRIC_ENUM( EXEC_VM_REGIME, COUNTER, VM_REGIME, COMMIT_CPI ),
+    DECLARE_METRIC_ENUM( EXEC_VM_REGIME, COUNTER, VM_REGIME, INTERPRETER ),
 };

src/disco/metrics/generated/fd_metrics_exec.h

@@ -54,7 +54,31 @@
 #define FD_METRICS_COUNTER_EXEC_ACCDB_CREATED_DESC "Number of account database records created"
 #define FD_METRICS_COUNTER_EXEC_ACCDB_CREATED_CVT  (FD_METRICS_CONVERTER_NONE)
 
-#define FD_METRICS_EXEC_TOTAL (8UL)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_OFF  (24UL)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_NAME "exec_txn_regime"
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_TYPE (FD_METRICS_TYPE_COUNTER)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_DESC "Mutually exclusive and exhaustive duration of time spent in transaction execution regimes."
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_CVT  (FD_METRICS_CONVERTER_NANOSECONDS)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_CNT  (3UL)
+
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_SETUP_OFF (24UL)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_EXEC_OFF (25UL)
+#define FD_METRICS_COUNTER_EXEC_TXN_REGIME_COMMIT_OFF (26UL)
+
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_OFF  (27UL)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_NAME "exec_vm_regime"
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_TYPE (FD_METRICS_TYPE_COUNTER)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_DESC "Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes."
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_CVT  (FD_METRICS_CONVERTER_NANOSECONDS)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_CNT  (5UL)
+
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_SETUP_OFF (27UL)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_COMMIT_OFF (28UL)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_SETUP_CPI_OFF (29UL)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_COMMIT_CPI_OFF (30UL)
+#define FD_METRICS_COUNTER_EXEC_VM_REGIME_INTERPRETER_OFF (31UL)
+
+#define FD_METRICS_EXEC_TOTAL (16UL)
 extern const fd_metrics_meta_t FD_METRICS_EXEC[FD_METRICS_EXEC_TOTAL];
 
 #endif /* HEADER_fd_src_disco_metrics_generated_fd_metrics_exec_h */

src/disco/metrics/metrics.xml

@@ -1119,6 +1119,20 @@ metric introduced.
     <gauge name="StartSlot" summary="The slot at which the backtest started" />
 </tile>
 
+<enum name="TxnRegime">
+    <int value="0" name="Setup" label="Transaction setup" />
+    <int value="1" name="Exec" label="Transaction execution (includes VM setup/execution)" />
+    <int value="2" name="Commit" label="Transaction result commit" />
+</enum>
+
+<enum name="VmRegime">
+    <int value="0" name="Setup" label="VM setup" />
+    <int value="1" name="Commit" label="VM commit" />
+    <int value="2" name="SetupCpi" label="VM setup (CPI)" />
+    <int value="3" name="CommitCpi" label="VM commit (CPI)" />
+    <int value="4" name="Interpreter" label="VM interpreter execution" />
+</enum>
+
 <tile name="exec">
     <counter name="ProgcacheMisses" summary="Number of program cache misses" />
     <counter name="ProgcacheHits" summary="Number of program cache hits" />
@@ -1128,6 +1142,9 @@ metric introduced.
     <counter name="ProgcacheDupInserts" summary="Number of time two tiles raced to insert the same cache entry" />
     <counter name="ProgcacheInvalidations" summary="Number of program cache invalidations" />
     <counter name="AccdbCreated" summary="Number of account database records created" />
+
+    <counter name="TxnRegime" converter="nanoseconds" enum="TxnRegime" summary="Mutually exclusive and exhaustive duration of time spent in transaction execution regimes." />
+    <counter name="VmRegime" converter="nanoseconds" enum="VmRegime" summary="Mutually exclusive and exhaustive duration of time spent in virtual machine execution regimes." />
 </tile>
 
 <tile name="benchs">

src/discof/exec/fd_exec_tile.c

@@ -72,6 +72,17 @@ typedef struct fd_exec_tile_ctx {
 
   fd_runtime_t runtime[1];
 
+  struct {
+    /* Ticks spent preparing a txn (database reads, account copies) */
+    ulong txn_setup_cum_ticks;
+
+    /* Ticks spent executing a txn (includes any VM time) */
+    ulong txn_exec_cum_ticks;
+
+    /* Ticks spent committing a txn (database writes) */
+    ulong txn_commit_cum_ticks;
+  } metrics;
+
 } fd_exec_tile_ctx_t;
 
 FD_FN_CONST static inline ulong
@@ -99,6 +110,20 @@ metrics_write( fd_exec_tile_ctx_t * ctx ) {
   FD_MCNT_SET( EXEC, PROGCACHE_INVALIDATIONS, progcache->metrics->invalidate_cnt );
   FD_MCNT_SET( EXEC, PROGCACHE_DUP_INSERTS,   progcache->metrics->dup_insert_cnt );
 
+  FD_MCNT_SET( EXEC, TXN_REGIME_SETUP,  ctx->metrics.txn_setup_cum_ticks   );
+  FD_MCNT_SET( EXEC, TXN_REGIME_EXEC,   ctx->metrics.txn_exec_cum_ticks    );
+  FD_MCNT_SET( EXEC, TXN_REGIME_COMMIT, ctx->metrics.txn_commit_cum_ticks  );
+
+  fd_runtime_t const * runtime = ctx->runtime;
+  ulong cpi_ticks  = runtime->metrics.cpi_setup_cum_ticks +
+                     runtime->metrics.cpi_commit_cum_ticks;
+  ulong exec_ticks = runtime->metrics.vm_exec_cum_ticks - cpi_ticks;
+  FD_MCNT_SET( EXEC, VM_REGIME_SETUP,       runtime->metrics.vm_setup_cum_ticks   );
+  FD_MCNT_SET( EXEC, VM_REGIME_COMMIT,      runtime->metrics.vm_commit_cum_ticks  );
+  FD_MCNT_SET( EXEC, VM_REGIME_SETUP_CPI,   runtime->metrics.cpi_setup_cum_ticks  );
+  FD_MCNT_SET( EXEC, VM_REGIME_COMMIT_CPI,  runtime->metrics.cpi_commit_cum_ticks );
+  FD_MCNT_SET( EXEC, VM_REGIME_INTERPRETER, exec_ticks                            );
+
   fd_accdb_user_t * accdb = ctx->accdb;
   FD_MCNT_SET( EXEC, ACCDB_CREATED, accdb->base.created_cnt );
 }
@@ -181,6 +206,24 @@ returnable_frag( fd_exec_tile_ctx_t * ctx,
         ctx->slot = fd_bank_slot_get( ctx->bank );
         publish_txn_finalized_msg( ctx, stem );
 
+        /* Update metrics */
+        ulong setup_dt  = (ulong)ctx->txn_out.details.exec_start_timestamp   - (ulong)ctx->txn_out.details.prep_start_timestamp;
+        ulong exec_dt   = (ulong)ctx->txn_out.details.commit_start_timestamp - (ulong)ctx->txn_out.details.exec_start_timestamp;
+        ulong commit_dt = (ulong)fd_tickcount()                              - (ulong)ctx->txn_out.details.commit_start_timestamp;
+        if( FD_UNLIKELY( ctx->txn_out.details.prep_start_timestamp==LONG_MAX ) ) {
+          setup_dt = 0UL;
+        }
+        if( FD_UNLIKELY( ctx->txn_out.details.exec_start_timestamp==LONG_MAX ) ) {
+          setup_dt = 0UL;
+          exec_dt  = 0UL;
+        }
+        if( FD_UNLIKELY( ctx->txn_out.details.commit_start_timestamp==LONG_MAX ) ) {
+          commit_dt = 0UL;
+        }
+        ctx->metrics.txn_setup_cum_ticks  += setup_dt;
+        ctx->metrics.txn_exec_cum_ticks   += exec_dt;
+        ctx->metrics.txn_commit_cum_ticks += commit_dt;
+
         break;
       }
       case FD_EXEC_TT_TXN_SIGVERIFY: {
@@ -361,6 +404,9 @@ unprivileged_init( fd_topo_t *      topo,
   ctx->runtime->log.enable_vm_tracing    = 0;
   ctx->runtime->log.tracing_mem          = &ctx->tracing_mem[0][0];
   ctx->runtime->log.capture_ctx          = ctx->capture_ctx;
+
+  memset( &ctx->metrics,          0, sizeof(ctx->metrics)          );
+  memset( &ctx->runtime->metrics, 0, sizeof(ctx->runtime->metrics) );
 }
 
 static ulong

src/flamenco/runtime/fd_runtime.h

@@ -136,6 +136,26 @@ struct fd_runtime {
     ulong                     starting_dlen[ MAX_TX_ACCOUNT_LOCKS ];     /* Starting data length for each account */
     ulong                     refcnt[ MAX_TX_ACCOUNT_LOCKS ];            /* Reference count for each account */
   } accounts;
+
+  struct {
+
+    /* Ticks spent spent preparing a txn-level VM (zeroing memory,
+       copying account data, etc) */
+    ulong vm_setup_cum_ticks;
+
+    /* Ticks spent committing txn-level VM results (copying account
+       data, etc) */
+    ulong vm_commit_cum_ticks;
+
+    /* Ticks spent in top-levl VM interpreter (includes CPI setup/commit
+       ticks) */
+    ulong vm_exec_cum_ticks;
+
+    /* Ticks spent preparing/committing a cross-program invocation) */
+    ulong cpi_setup_cum_ticks;
+    ulong cpi_commit_cum_ticks;
+
+  } metrics;
 };
 typedef struct fd_runtime fd_runtime_t;
 

src/flamenco/runtime/program/fd_bpf_loader_program.c

@@ -376,6 +376,7 @@ int
 fd_bpf_execute( fd_exec_instr_ctx_t *      instr_ctx,
                 fd_progcache_rec_t const * cache_entry,
                 uchar                      is_deprecated ) {
+  long const regime0 = fd_tickcount();
 
   int err = FD_EXECUTOR_INSTR_SUCCESS;
 
@@ -479,9 +480,20 @@ fd_bpf_execute( fd_exec_instr_ctx_t *      instr_ctx,
     if( FD_UNLIKELY( !vm->trace ) ) FD_LOG_ERR(( "unable to create trace; make sure you've compiled with sufficient spad size " ));
   }
 
+  long const regime1 = fd_tickcount();
+
   int exec_err = fd_vm_exec( vm );
   instr_ctx->txn_out->details.compute_budget.compute_meter = vm->cu;
 
+  long const regime2 = fd_tickcount();
+
+  if( instr_ctx->instr->stack_height==1 ) {
+    instr_ctx->runtime->metrics.vm_setup_cum_ticks  += (ulong)( regime1-regime0 );
+    instr_ctx->runtime->metrics.vm_exec_cum_ticks   += (ulong)( regime2-regime1 );
+  } else {
+    instr_ctx->runtime->metrics.cpi_setup_cum_ticks += (ulong)( regime1-regime0 );
+  }
+
   if( FD_UNLIKELY( vm->trace ) ) {
     err = fd_vm_trace_printf( vm->trace, vm->syscalls );
     if( FD_UNLIKELY( err ) ) {
@@ -625,11 +637,15 @@ fd_bpf_execute( fd_exec_instr_ctx_t *      instr_ctx,
 
   err = fd_bpf_loader_input_deserialize_parameters(
     instr_ctx, pre_lens, input, input_sz, stricter_abi_and_runtime_constraints, direct_mapping, is_deprecated );
-  if( FD_UNLIKELY( err ) ) {
-    return err;
+
+  long const regime3 = fd_tickcount();
+  if( instr_ctx->instr->stack_height==1 ) {
+    instr_ctx->runtime->metrics.cpi_commit_cum_ticks += (ulong)( regime3-regime2 );
+  } else {
+    instr_ctx->runtime->metrics.vm_commit_cum_ticks  += (ulong)( regime3-regime2 );
   }
 
-  return FD_EXECUTOR_INSTR_SUCCESS;
+  return err;
 }
 
 /* https://github.com/anza-xyz/agave/blob/v2.3.1/programs/bpf_loader/src/lib.rs#L1358-L1539 */

src/flamenco/vm/syscall/fd_vm_syscall_cpi_common.c

@@ -675,6 +675,7 @@ VM_SYSCALL_CPI_ENTRYPOINT( void *  _vm,
                            ulong   signers_seeds_va,
                            ulong   signers_seeds_cnt,
                            ulong * _ret ) {
+  long const regime0 = fd_tickcount();
 
   fd_vm_t * vm = (fd_vm_t *)_vm;
 
@@ -907,10 +908,15 @@ VM_SYSCALL_CPI_ENTRYPOINT( void *  _vm,
      so that the callee cannot use compute units that the caller has already used. */
   vm->instr_ctx->txn_out->details.compute_budget.compute_meter = vm->cu;
 
+  long const regime1 = fd_tickcount();
+
   /* Execute the CPI instruction in the runtime */
   int err_exec = fd_execute_instr( vm->instr_ctx->runtime, vm->instr_ctx->bank, vm->instr_ctx->txn_in, vm->instr_ctx->txn_out, instruction_to_execute );
   ulong instr_exec_res = (ulong)err_exec;
 
+  long const regime2 = fd_tickcount();
+  vm->instr_ctx->runtime->metrics.cpi_setup_cum_ticks += (ulong)( regime1-regime0 );
+
   /* Set the CU meter to the instruction context's transaction context's compute meter,
      so that the caller can't use compute units that the callee has already used. */
   vm->cu = vm->instr_ctx->txn_out->details.compute_budget.compute_meter;
@@ -958,6 +964,9 @@ VM_SYSCALL_CPI_ENTRYPOINT( void *  _vm,
     }
   }
 
+  long const regime3 = fd_tickcount();
+  vm->instr_ctx->runtime->metrics.cpi_commit_cum_ticks += (ulong)( regime3-regime2 );
+
   return FD_VM_SUCCESS;
 }