perf(471): Add duration metrics for wasm abi calls

crates/core/src/db/db_metrics/mod.rs

@@ -1,4 +1,4 @@
-use crate::{execution_context::TransactionType, util::typed_prometheus::metrics_group};
+use crate::{execution_context::TransactionType, host::AbiCall, util::typed_prometheus::metrics_group};
 use once_cell::sync::Lazy;
 use prometheus::{Histogram, HistogramVec, IntCounterVec};
 use spacetimedb_lib::Address;
@@ -85,6 +85,11 @@ metrics_group!(
         #[help = "The time spent executing a transaction (nanoseconds), excluding time spent waiting to acquire database locks"]
         #[labels(txn_type: TransactionType, db: Address, reducer: str)]
         pub rdb_txn_cpu_time_ns: HistogramVec,
+
+        #[name = spacetime_wasm_abi_call_duration_ns]
+        #[help = "The total duration of a spacetime wasm abi call (nanoseconds); includes row serialization and copying into wasm memory"]
+        #[labels(txn_type: TransactionType, db: Address, reducer: str, call: AbiCall)]
+        pub wasm_abi_call_duration_ns: HistogramVec,
     }
 );
 

crates/core/src/host/instance_env.rs

@@ -116,10 +116,9 @@ impl InstanceEnv {
         log::trace!("MOD({}): {}", self.dbic.address.to_abbreviated_hex(), record.message);
     }
 
-    pub fn insert(&self, table_id: TableId, buffer: &[u8]) -> Result<ProductValue, NodesError> {
+    pub fn insert(&self, ctx: &ExecutionContext, table_id: TableId, buffer: &[u8]) -> Result<ProductValue, NodesError> {
         let stdb = &*self.dbic.relational_db;
         let tx = &mut *self.get_tx()?;
-        let ctx = ExecutionContext::internal(stdb.address());
         let ret = stdb
             .insert_bytes_as_row(tx, table_id, buffer)
             .inspect_err_(|e| match e {
@@ -130,7 +129,7 @@ impl InstanceEnv {
                     value: _,
                 }) => {}
                 _ => {
-                    let res = stdb.table_name_from_id(&ctx, tx, table_id);
+                    let res = stdb.table_name_from_id(ctx, tx, table_id);
                     if let Ok(Some(table_name)) = res {
                         log::debug!("insert(table: {table_name}, table_id: {table_id}): {e}")
                     } else {

crates/core/src/host/mod.rs

@@ -3,6 +3,8 @@ use std::time::Duration;
 use anyhow::Context;
 use bytes::Bytes;
 use bytestring::ByteString;
+use derive_more::Display;
+use enum_map::Enum;
 use spacetimedb_lib::de::serde::SeedWrapper;
 use spacetimedb_lib::de::DeserializeSeed;
 use spacetimedb_lib::{bsatn, Hash, Identity};
@@ -166,3 +168,20 @@ impl EnergyMonitor for NullEnergyMonitor {
     ) {
     }
 }
+
+/// Tags for each call that a `WasmInstanceEnv` can make.
+#[derive(Debug, Display, Enum)]
+pub enum AbiCall {
+    CancelReducer,
+    ConsoleLog,
+    CreateIndex,
+    DeleteByColEq,
+    GetTableId,
+    Insert,
+    IterByColEq,
+    IterDrop,
+    IterNext,
+    IterStart,
+    IterStartFiltered,
+    ScheduleReducer,
+}

crates/core/src/host/wasm_common/instrumentation.rs

@@ -23,16 +23,20 @@
 
 use std::time::{Duration, Instant};
 
-use enum_map::{enum_map, Enum, EnumMap};
+use enum_map::{enum_map, EnumMap};
+
+use crate::host::AbiCall;
 
 #[allow(unused)]
 pub mod noop {
+    use crate::host::AbiCall;
+
     use super::*;
 
     pub struct CallSpanStart;
 
     impl CallSpanStart {
-        pub fn new(_call: Call) -> Self {
+        pub fn new(_call: AbiCall) -> Self {
             Self
         }
 
@@ -48,15 +52,17 @@ pub mod noop {
 
 #[allow(unused)]
 pub mod op {
+    use crate::host::AbiCall;
+
     use super::*;
 
     pub struct CallSpanStart {
-        call: Call,
+        call: AbiCall,
         start: Instant,
     }
 
     impl CallSpanStart {
-        pub fn new(call: Call) -> Self {
+        pub fn new(call: AbiCall) -> Self {
             let start = Instant::now();
             Self { call, start }
         }
@@ -70,7 +76,7 @@ pub mod op {
 
     #[derive(Debug)]
     pub struct CallSpan {
-        pub(super) call: Call,
+        pub(super) call: AbiCall,
         pub(super) duration: Duration,
     }
 
@@ -79,27 +85,10 @@ pub mod op {
     }
 }
 
-/// Tags for each call that a `WasmInstanceEnv` can make.
-#[derive(Debug, Enum)]
-pub enum Call {
-    CancelReducer,
-    ConsoleLog,
-    CreateIndex,
-    DeleteByColEq,
-    GetTableId,
-    Insert,
-    IterByColEq,
-    IterDrop,
-    IterNext,
-    IterStart,
-    IterStartFiltered,
-    ScheduleReducer,
-}
-
 #[derive(Debug)]
-/// Associates each `Call` tag with a cumulative total `Duration` spent within that call.
+/// Associates each `AbiCall` tag with a cumulative total `Duration` spent within that call.
 pub struct CallTimes {
-    times: EnumMap<Call, Duration>,
+    times: EnumMap<AbiCall, Duration>,
 }
 
 impl CallTimes {
@@ -110,7 +99,7 @@ impl CallTimes {
     }
 
     /// Track a particular `CallSpan` by adding its duration to the
-    /// associated `Call`'s timing information.
+    /// associated `AbiCall`'s timing information.
     pub fn span(&mut self, span: op::CallSpan) {
         self.times[span.call] += span.duration;
     }