From 51166c9bc2529d46275bff24480cad95cbaeffae Mon Sep 17 00:00:00 2001 From: Jeffrey Dallatezza Date: Wed, 15 Jul 2026 11:55:32 -0700 Subject: [PATCH 1/4] Add new view timing metrics that are separated from reducers --- crates/core/src/host/module_host.rs | 16 ++- crates/core/src/host/scheduler.rs | 3 +- .../src/host/wasm_common/module_host_actor.rs | 110 ++++++++++++++---- crates/core/src/sql/execute.rs | 4 +- crates/datastore/src/db_metrics/mod.rs | 20 ++++ 5 files changed, 128 insertions(+), 25 deletions(-) diff --git a/crates/core/src/host/module_host.rs b/crates/core/src/host/module_host.rs index 8a1bbc6b414..35f88434330 100644 --- a/crates/core/src/host/module_host.rs +++ b/crates/core/src/host/module_host.rs @@ -1534,6 +1534,9 @@ pub struct ViewCallResult { pub tx: MutTxId, pub execution_budget_used: FunctionBudget, pub total_duration: Duration, + // Includes the time spent calling the user-defined view function, but not the time spent materializing the view + // after that function returns. + pub call_duration: Duration, pub abi_duration: Duration, } @@ -1543,6 +1546,7 @@ impl fmt::Debug for ViewCallResult { .field("outcome", &self.outcome) .field("execution_budget_used", &self.execution_budget_used) .field("total_duration", &self.total_duration) + .field("call_duration", &self.call_duration) .field("abi_duration", &self.abi_duration) .finish() } @@ -1554,6 +1558,7 @@ impl ViewCallResult { outcome: ViewOutcome::Success, execution_budget_used: FunctionBudget::ZERO, total_duration: Duration::ZERO, + call_duration: Duration::ZERO, abi_duration: Duration::ZERO, tx, } @@ -2908,11 +2913,12 @@ impl ModuleHost { /// /// The returned transaction contains both the original writes and any backing-table /// updates produced by re-materializing the affected views. + /// This returns the number of views that were evaluated, and whether any of them trapped. pub fn call_views_with_tx( tx: MutTxId, instance: &mut RefInstance<'_, I>, caller: Identity, - ) -> (ViewCallResult, bool) { + ) -> (ViewCallResult, u32, bool) { Self::call_views_with_tx_at(tx, instance, caller, Timestamp::now()) } @@ -2925,14 +2931,16 @@ impl ModuleHost { instance: &mut RefInstance<'_, I>, caller: Identity, timestamp: Timestamp, - ) -> (ViewCallResult, bool) { + ) -> (ViewCallResult, u32, bool) { let mut tx = tx; let module_def = &instance.common.info().module_def; let mut outcome = ViewOutcome::Success; let mut energy_used = FunctionBudget::ZERO; let mut total_duration = Duration::ZERO; + let mut call_duration = Duration::ZERO; let mut abi_duration = Duration::ZERO; let mut trapped = false; + let mut num_views_evaluated = 0; for view_call in tx.views_for_refresh().cloned().collect::>() { let resolved = match resolve_view_for_refresh(&tx, module_def, &view_call) { Ok(resolved) => resolved, @@ -2978,6 +2986,7 @@ impl ModuleHost { view_def.product_type_ref, timestamp, ); + num_views_evaluated += 1; // Increment execution stats tx = result.tx; @@ -2985,6 +2994,7 @@ impl ModuleHost { energy_used += result.execution_budget_used; total_duration += result.total_duration; abi_duration += result.abi_duration; + call_duration += result.call_duration; trapped |= trap; // Terminate early if execution failed @@ -2999,7 +3009,9 @@ impl ModuleHost { execution_budget_used: energy_used, total_duration, abi_duration, + call_duration, }, + num_views_evaluated, trapped, ) } diff --git a/crates/core/src/host/scheduler.rs b/crates/core/src/host/scheduler.rs index 295574606e2..c5ec94796d5 100644 --- a/crates/core/src/host/scheduler.rs +++ b/crates/core/src/host/scheduler.rs @@ -690,7 +690,8 @@ fn refresh_views_then_commit_and_broadcast( inst: &mut impl WasmInstance, ) { let timestamp = Timestamp::now(); - let (view_result, trapped) = inst_common.call_views_with_tx(tx, module_info.database_identity, inst, timestamp); + let (view_result, _n_evaluated, trapped) = + inst_common.call_views_with_tx(tx, module_info.database_identity, inst, timestamp); let mut status = match view_result.outcome { crate::host::module_host::ViewOutcome::Success => EventStatus::Committed(DatabaseUpdate::default()), crate::host::module_host::ViewOutcome::Failed(err) => EventStatus::FailedInternal(err), diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index 97951829d16..7df53672c1c 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -55,6 +55,7 @@ use spacetimedb_schema::def::{ModuleDef, ViewDef}; use spacetimedb_schema::identifier::Identifier; use spacetimedb_schema::reducer_name::ReducerName; use spacetimedb_subscription::SubscriptionPlan; +use std::collections::HashMap; use std::sync::Arc; use tracing::span::EnteredSpan; @@ -721,7 +722,7 @@ impl InstanceCommon { } } crate::db::update::UpdateResult::EvaluateSubscribedViews => { - let (out, trapped) = self.evaluate_subscribed_views(tx, inst)?; + let (out, _, trapped) = self.evaluate_subscribed_views(tx, inst)?; tx = out.tx; if trapped || out.outcome != ViewOutcome::Success { let msg = match trapped { @@ -763,7 +764,7 @@ impl InstanceCommon { &mut self, tx: MutTxId, inst: &mut I, - ) -> Result<(ViewCallResult, bool), anyhow::Error> { + ) -> Result<(ViewCallResult, u32, bool), anyhow::Error> { let view_calls = collect_subscribed_view_calls(&tx, &self.info.module_def, self.info.owner_identity)?; Ok(self.execute_view_calls(tx, view_calls, inst)) } @@ -1064,16 +1065,15 @@ impl InstanceCommon { }; // Only re-evaluate and update views if the reducer's execution was successful - let (out, trapped) = if !trapped && matches!(status, EventStatus::Committed(_)) { + let (out, n_views_evaluated, trapped) = if !trapped && matches!(status, EventStatus::Committed(_)) { self.call_views_with_tx(tx, caller_identity, inst, timestamp) } else { - (ViewCallResult::default(tx), trapped) + (ViewCallResult::default(tx), 0, trapped) }; // Account for view execution in reducer reporting metrics - vm_metrics.report_execution_budget_used(out.execution_budget_used); - vm_metrics.report_total_duration(out.total_duration); - vm_metrics.report_abi_duration(out.abi_duration); + + vm_metrics.report_view_refreshed(n_views_evaluated); let status = match out.outcome { ViewOutcome::BudgetExceeded => EventStatus::OutOfEnergy, @@ -1099,6 +1099,7 @@ impl InstanceCommon { status, reducer_return_value, execution_budget_used, + // Note: this is not counting view work. host_execution_duration: total_duration, request_id, timer, @@ -1304,6 +1305,7 @@ impl InstanceCommon { params: CallViewParams, inst: &mut I, ) -> (ViewCallResult, bool) { + let compute_start = std::time::Instant::now(); let CallViewParams { view_name, view_id, @@ -1404,12 +1406,23 @@ impl InstanceCommon { } }; + let total_time = compute_start.elapsed(); + // Report execution metrics on each view call. + self.vm_metrics + //.get_for_view_id(view_id, &self.info.database_identity, &view_name) + .get_for_view_id2(view_id, &self.info.database_identity, &view_name) + .report(&ViewExecutionStats { + call_duration: result.stats.total_duration(), + total_duration: total_time, + }); + let res = ViewCallResult { outcome, tx, execution_budget_used: result.stats.execution_budget_used(), - total_duration: result.stats.total_duration(), + total_duration: total_time, abi_duration: result.stats.abi_duration(), + call_duration: result.stats.total_duration(), }; (res, trapped) @@ -1429,13 +1442,14 @@ impl InstanceCommon { } /// A [`MutTxId`] knows which views must be updated (re-evaluated). /// This method re-evaluates them and updates their backing tables. + /// Returns an overall result, the number of views evaluated, and whether any call trapped. pub(crate) fn call_views_with_tx( &mut self, tx: MutTxId, caller: Identity, inst: &mut I, timestamp: Timestamp, - ) -> (ViewCallResult, bool) { + ) -> (ViewCallResult, u32, bool) { let mut instance = RefInstance { common: self, instance: inst, @@ -1450,11 +1464,13 @@ impl InstanceCommon { tx: MutTxId, view_calls: Vec, inst: &mut I, - ) -> (ViewCallResult, bool) { + ) -> (ViewCallResult, u32, bool) { let mut out = ViewCallResult::default(tx); let mut trapped = false; + let mut num_views_evaluated = 0; for params in view_calls { + num_views_evaluated += 1; let (result, call_trapped) = self.call_view_with_tx(out.tx, params, inst); out.tx = result.tx; @@ -1471,7 +1487,7 @@ impl InstanceCommon { } } - (out, trapped) + (out, num_views_evaluated, trapped) } /// Empty the system tables tracking clients without running any lifecycle reducers. @@ -1569,8 +1585,10 @@ struct AllVmMetrics { // TODO(perf, centril): Define a `VecMapWithFallback` // that falls back to `HashMap` when exceeding `N` entries. // This could be useful elsewhere for e.g., TableId => X maps and similar. - counters: Vec, + reducer_counters: Vec, num_reducers: u32, + + view_metrics: HashMap, } impl AllVmMetrics { @@ -1582,21 +1600,22 @@ impl AllVmMetrics { let num_reducers = reducers.len() as u32; let reducers = reducers.map(|(_, def)| def.name()); - // These are the views: - let views = def.views().map(|def| def.name()); - // Pre-fetch the metrics for both: - let counters = reducers - .chain(views) + let reducer_counters = reducers .map(|name| VmMetrics::new(&info.database_identity, name)) .collect(); - Self { counters, num_reducers } + // View metrics will be lazily fetched, as they are not always called. + Self { + reducer_counters, + num_reducers, + view_metrics: HashMap::new(), + } } #[inline] fn get_for_index(&self, index: u32) -> Option { - self.counters.get(index as usize).cloned() + self.reducer_counters.get(index as usize).cloned() } /// Returns the vm metrics counters for `id`, @@ -1607,6 +1626,13 @@ impl AllVmMetrics { .expect("all counters for reducers should've been pre-fetched") } + fn get_for_view_id2(&mut self, id: ViewId, identity: &Identity, name: &str) -> ViewMetrics { + self.view_metrics + .entry(id) + .or_insert_with(|| ViewMetrics::new(identity, name)) + .clone() + } + /// Returns the vm metrics counters for `id`, /// or panics if `id` was not pre-fetched in [`AllVmMetrics::new`]. #[inline] @@ -1623,6 +1649,41 @@ impl AllVmMetrics { } } +#[derive(Clone)] +struct ViewMetrics { + // Counts the time calling the user-defined function. + call_duration_usec: IntCounter, + // Includes the time spent calling the user-defined function and materializing the results. + total_duration_usec: IntCounter, + // Number of times the view was called. + total_calls: IntCounter, +} + +struct ViewExecutionStats { + call_duration: Duration, + total_duration: Duration, +} + +impl ViewMetrics { + fn new(identity: &Identity, name: &str) -> Self { + let call_duration_usec = DB_METRICS.view_call_duration_usec.with_label_values(identity, name); + let total_duration_usec = DB_METRICS.view_total_duration_usec.with_label_values(identity, name); + let total_calls = DB_METRICS.view_calls.with_label_values(identity, name); + + Self { + call_duration_usec, + total_duration_usec, + total_calls, + } + } + + fn report(&self, stats: &ViewExecutionStats) { + self.call_duration_usec.inc_by(stats.call_duration.as_micros() as u64); + self.total_duration_usec.inc_by(stats.total_duration.as_micros() as u64); + self.total_calls.inc(); + } +} + /// VM-related metrics for reducer execution. #[derive(Clone)] struct VmMetrics { @@ -1634,6 +1695,8 @@ struct VmMetrics { reducer_duration_usec: IntCounter, /// The total time spent in reducer ABI calls. reducer_abi_time_usec: IntCounter, + /// The number of view refreshes triggered by this reducer. + views_refreshed: IntCounter, } impl VmMetrics { @@ -1651,12 +1714,15 @@ impl VmMetrics { let reducer_abi_time_usec = DB_METRICS .reducer_abi_time_usec .with_label_values(database_identity, reducer_name); - + let views_refreshed = DB_METRICS + .view_calls_triggered + .with_label_values(database_identity, reducer_name); Self { reducer_plus_query_duration, reducer_fuel_used, reducer_duration_usec, reducer_abi_time_usec, + views_refreshed, } } @@ -1677,6 +1743,10 @@ impl VmMetrics { self.reducer_abi_time_usec.inc_by(duration.as_micros() as u64); } + fn report_view_refreshed(&self, num_views_evaluated: u32) { + self.views_refreshed.inc_by(num_views_evaluated as u64); + } + /// Reports some VM metrics. fn report(&self, stats: &ExecutionStats) { let execution_budget_used = stats.energy.used(); diff --git a/crates/core/src/sql/execute.rs b/crates/core/src/sql/execute.rs index 7fe2fe229f8..ddd57d780c5 100644 --- a/crates/core/src/sql/execute.rs +++ b/crates/core/src/sql/execute.rs @@ -154,9 +154,9 @@ fn run_inner( tx.metrics.merge(metrics); // Update views - let (result, trapped) = match instance { + let (result, _num_views_evaluated, trapped) = match instance { Some(instance) => ModuleHost::call_views_with_tx(tx, instance, auth.caller()), - None => (ViewCallResult::default(tx), false), + None => (ViewCallResult::default(tx), 0, false), }; // Rollback transaction and report metrics if view execution failed diff --git a/crates/datastore/src/db_metrics/mod.rs b/crates/datastore/src/db_metrics/mod.rs index 3a3bd35325e..a2219f5548b 100644 --- a/crates/datastore/src/db_metrics/mod.rs +++ b/crates/datastore/src/db_metrics/mod.rs @@ -116,6 +116,26 @@ metrics_group!( #[labels(db: Identity, reducer: str)] pub reducer_duration_usec: IntCounterVec, + #[name = view_call_time_usec] + #[help = "The duration of view function calls, not counting materialization"] + #[labels(db: Identity, view: str)] + pub view_call_duration_usec: IntCounterVec, + + #[name = view_total_time_usec] + #[help = "The total duration of view computation"] + #[labels(db: Identity, view: str)] + pub view_total_duration_usec: IntCounterVec, + + #[name = view_calls] + #[help = "The total number of view function calls"] + #[labels(db: Identity, view: str)] + pub view_calls: IntCounterVec, + + #[name = view_calls_triggered] + #[help = "The total number of view calls triggered by a reducer"] + #[labels(db: Identity, reducer: str)] + pub view_calls_triggered: IntCounterVec, + #[name = reducer_abi_time_usec] #[help = "The total time spent in reducer ABI calls"] #[labels(db: Identity, reducer: str)] From da83eb9d5f3f9c8c83b9b27e76125b5a7691b45d Mon Sep 17 00:00:00 2001 From: Jeffrey Dallatezza Date: Wed, 15 Jul 2026 12:26:32 -0700 Subject: [PATCH 2/4] comment --- crates/core/src/host/wasm_common/module_host_actor.rs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index 7df53672c1c..495d991a839 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -1626,6 +1626,7 @@ impl AllVmMetrics { .expect("all counters for reducers should've been pre-fetched") } + // Returns the view metrics for `id`. fn get_for_view_id2(&mut self, id: ViewId, identity: &Identity, name: &str) -> ViewMetrics { self.view_metrics .entry(id) @@ -1635,6 +1636,10 @@ impl AllVmMetrics { /// Returns the vm metrics counters for `id`, /// or panics if `id` was not pre-fetched in [`AllVmMetrics::new`]. + /// + /// TODO: delete these. This version is using reducer stats, which is very confusing. + /// I'm leaving this in place for now because I need to figure out if this matters for + /// billing or the website dashboard. #[inline] fn get_for_view_id(&self, id: ViewId, identity: &Identity, name: &str) -> VmMetrics { // Cosunters for the first view starts after counters for the last reducer. From 9038d756ab711e3201fbff0e2cd734c264ef0256 Mon Sep 17 00:00:00 2001 From: Jeffrey Dallatezza Date: Wed, 15 Jul 2026 13:12:45 -0700 Subject: [PATCH 3/4] Apply suggestions from code review Co-authored-by: Phoebe Goldman Signed-off-by: Jeffrey Dallatezza --- crates/core/src/host/wasm_common/module_host_actor.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index 495d991a839..d81bca75386 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -1443,6 +1443,7 @@ impl InstanceCommon { /// A [`MutTxId`] knows which views must be updated (re-evaluated). /// This method re-evaluates them and updates their backing tables. /// Returns an overall result, the number of views evaluated, and whether any call trapped. + /// The caller should use the number of views evaluated to increment the metric `view_calls_triggered`. pub(crate) fn call_views_with_tx( &mut self, tx: MutTxId, @@ -1639,7 +1640,7 @@ impl AllVmMetrics { /// /// TODO: delete these. This version is using reducer stats, which is very confusing. /// I'm leaving this in place for now because I need to figure out if this matters for - /// billing or the website dashboard. + /// billing or the website dashboard. (jsdt 2026-07-15) #[inline] fn get_for_view_id(&self, id: ViewId, identity: &Identity, name: &str) -> VmMetrics { // Cosunters for the first view starts after counters for the last reducer. From 200f86118a47e230bdec20d37f68ce87d5b8aca2 Mon Sep 17 00:00:00 2001 From: Jeffrey Dallatezza Date: Wed, 15 Jul 2026 14:28:33 -0700 Subject: [PATCH 4/4] rename metric to view_calls_triggered_by_reducer --- crates/core/src/host/wasm_common/module_host_actor.rs | 2 +- crates/datastore/src/db_metrics/mod.rs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index 495d991a839..c6162ad0aef 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -1720,7 +1720,7 @@ impl VmMetrics { .reducer_abi_time_usec .with_label_values(database_identity, reducer_name); let views_refreshed = DB_METRICS - .view_calls_triggered + .view_calls_triggered_by_reducer .with_label_values(database_identity, reducer_name); Self { reducer_plus_query_duration, diff --git a/crates/datastore/src/db_metrics/mod.rs b/crates/datastore/src/db_metrics/mod.rs index a2219f5548b..b8366034bac 100644 --- a/crates/datastore/src/db_metrics/mod.rs +++ b/crates/datastore/src/db_metrics/mod.rs @@ -131,10 +131,10 @@ metrics_group!( #[labels(db: Identity, view: str)] pub view_calls: IntCounterVec, - #[name = view_calls_triggered] + #[name = view_calls_triggered_by_reducer] #[help = "The total number of view calls triggered by a reducer"] #[labels(db: Identity, reducer: str)] - pub view_calls_triggered: IntCounterVec, + pub view_calls_triggered_by_reducer: IntCounterVec, #[name = reducer_abi_time_usec] #[help = "The total time spent in reducer ABI calls"]