Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 14 additions & 2 deletions crates/core/src/host/module_host.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
}

Expand All @@ -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()
}
Expand All @@ -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,
}
Expand Down Expand Up @@ -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<I: WasmInstance>(
tx: MutTxId,
instance: &mut RefInstance<'_, I>,
caller: Identity,
) -> (ViewCallResult, bool) {
) -> (ViewCallResult, u32, bool) {
Self::call_views_with_tx_at(tx, instance, caller, Timestamp::now())
}

Expand All @@ -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::<Vec<_>>() {
let resolved = match resolve_view_for_refresh(&tx, module_def, &view_call) {
Ok(resolved) => resolved,
Expand Down Expand Up @@ -2978,13 +2986,15 @@ impl ModuleHost {
view_def.product_type_ref,
timestamp,
);
num_views_evaluated += 1;

// Increment execution stats
tx = result.tx;
outcome = result.outcome;
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
Expand All @@ -2999,7 +3009,9 @@ impl ModuleHost {
execution_budget_used: energy_used,
total_duration,
abi_duration,
call_duration,
},
num_views_evaluated,
trapped,
)
}
Expand Down
3 changes: 2 additions & 1 deletion crates/core/src/host/scheduler.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Comment thread
gefjon marked this conversation as resolved.
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),
Expand Down
116 changes: 96 additions & 20 deletions crates/core/src/host/wasm_common/module_host_actor.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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))
}
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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)
Expand All @@ -1429,13 +1442,15 @@ 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.
Comment thread
jsdt marked this conversation as resolved.
/// The caller should use the number of views evaluated to increment the metric `view_calls_triggered`.
pub(crate) fn call_views_with_tx<I: WasmInstance>(
&mut self,
tx: MutTxId,
caller: Identity,
inst: &mut I,
timestamp: Timestamp,
) -> (ViewCallResult, bool) {
) -> (ViewCallResult, u32, bool) {
let mut instance = RefInstance {
common: self,
instance: inst,
Expand All @@ -1450,11 +1465,13 @@ impl InstanceCommon {
tx: MutTxId,
view_calls: Vec<CallViewParams>,
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;
Expand All @@ -1471,7 +1488,7 @@ impl InstanceCommon {
}
}

(out, trapped)
(out, num_views_evaluated, trapped)
}

/// Empty the system tables tracking clients without running any lifecycle reducers.
Expand Down Expand Up @@ -1569,8 +1586,10 @@ struct AllVmMetrics {
// TODO(perf, centril): Define a `VecMapWithFallback<N>`
// that falls back to `HashMap` when exceeding `N` entries.
// This could be useful elsewhere for e.g., TableId => X maps and similar.
counters: Vec<VmMetrics>,
reducer_counters: Vec<VmMetrics>,
num_reducers: u32,

view_metrics: HashMap<ViewId, ViewMetrics>,
}

impl AllVmMetrics {
Expand All @@ -1582,21 +1601,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<VmMetrics> {
self.counters.get(index as usize).cloned()
self.reducer_counters.get(index as usize).cloned()
}

/// Returns the vm metrics counters for `id`,
Expand All @@ -1607,8 +1627,20 @@ 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)
.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`].
///
/// 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. (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.
Expand All @@ -1623,6 +1655,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 {
Expand All @@ -1634,6 +1701,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 {
Expand All @@ -1651,12 +1720,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_by_reducer
.with_label_values(database_identity, reducer_name);
Self {
reducer_plus_query_duration,
reducer_fuel_used,
reducer_duration_usec,
reducer_abi_time_usec,
views_refreshed,
}
}

Expand All @@ -1677,6 +1749,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();
Expand Down
4 changes: 2 additions & 2 deletions crates/core/src/sql/execute.rs
Original file line number Diff line number Diff line change
Expand Up @@ -154,9 +154,9 @@ fn run_inner<I: WasmInstance>(
tx.metrics.merge(metrics);

// Update views
let (result, trapped) = match instance {
let (result, _num_views_evaluated, trapped) = match instance {
Comment thread
gefjon marked this conversation as resolved.
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
Expand Down
Loading
Loading