Expose CPU and memory usage on per-component execution spans

Cargo.toml

@@ -56,6 +56,7 @@ watchexec-filterer-globset = "8.0"
 spin-app = { path = "crates/app" }
 spin-build = { path = "crates/build" }
 spin-common = { path = "crates/common" }
+spin-factors-executor = { path = "crates/factors-executor" }
 spin-doctor = { path = "crates/doctor" }
 spin-environments = { path = "crates/environments" }
 spin-factor-outbound-networking = { path = "crates/factor-outbound-networking" }
@@ -106,12 +107,14 @@ vergen = { version = "^8.2.1", default-features = false, features = [
 ] }
 
 [features]
-default = ["llm"]
+default = ["llm", "cpu-time-metrics"]
 all-tests = ["extern-dependencies-tests"]
 extern-dependencies-tests = []
 llm = ["spin-runtime-factors/llm"]
 llm-metal = ["llm", "spin-runtime-factors/llm-metal"]
 llm-cublas = ["llm", "spin-runtime-factors/llm-cublas"]
+# This enables the collection and emission CPU time elapsed per component execution.
+cpu-time-metrics = ["spin-factors-executor/cpu-time-metrics"]
 
 [workspace]
 members = [

crates/factors-executor/Cargo.toml

@@ -13,6 +13,8 @@ anyhow = { workspace = true }
 spin-app = { path = "../app" }
 spin-core = { path = "../core" }
 spin-factors = { path = "../factors" }
+spin-telemetry = { path = "../telemetry" }
+tracing = { workspace = true }
 
 [dev-dependencies]
 spin-factor-wasi = { path = "../factor-wasi" }
@@ -21,3 +23,6 @@ tokio = { workspace = true, features = ["macros", "rt"] }
 
 [lints]
 workspace = true
+
+[features]
+cpu-time-metrics = ["spin-core/call-hook"]

crates/factors-executor/src/lib.rs

@@ -1,8 +1,9 @@
+use std::time::{Duration, Instant};
 use std::{collections::HashMap, sync::Arc};
 
 use anyhow::Context;
 use spin_app::{App, AppComponent};
-use spin_core::{async_trait, Component};
+use spin_core::{async_trait, wasmtime::CallHook, Component};
 use spin_factors::{
  AsInstanceState, ConfiguredApp, Factor, HasInstanceBuilder, RuntimeFactors,
  RuntimeFactorsInstanceState,
@@ -255,9 +256,24 @@ impl<T: RuntimeFactors, U: Send> FactorsInstanceBuilder<'_, T, U> {
  core: Default::default(),
  factors: self.factors.build_instance_state(self.factor_builders)?,
  executor: executor_instance_state,
+ cpu_time_elapsed: Duration::from_millis(0),
+ cpu_time_last_entry: None,
+ memory_used_on_init: 0,
+ component_id: self.app_component.id().into(),
  };
  let mut store = self.store_builder.build(instance_state)?;
+
+ #[cfg(feature = "cpu-time-metrics")]
+ store.as_mut().call_hook(|mut store, hook| {
+ CpuTimeCallHook.handle_call_event::<T, U>(store.data_mut(), hook)
+ });
+
  let instance = self.instance_pre.instantiate_async(&mut store).await?;
+
+ // Track memory usage after instantiation in the instance state.
+ // Note: This only applies if the component has initial memory reservations.
+ store.data_mut().memory_used_on_init = store.data().core_state().memory_consumed();
+
  Ok((instance, store))
  }
 
@@ -269,11 +285,41 @@ impl<T: RuntimeFactors, U: Send> FactorsInstanceBuilder<'_, T, U> {
  core: Default::default(),
  factors: self.factors.build_instance_state(self.factor_builders)?,
  executor: executor_instance_state,
+ cpu_time_elapsed: Duration::from_millis(0),
+ cpu_time_last_entry: None,
+ memory_used_on_init: 0,
+ component_id: self.app_component.id().into(),
  };
  self.store_builder.build(instance_state)
  }
 }
 
+// Tracks CPU time used by a Wasm guest.
+#[allow(unused)]
+struct CpuTimeCallHook;
+
+#[allow(unused)]
+impl CpuTimeCallHook {
+ fn handle_call_event<T: RuntimeFactors, U>(
+ &self,
+ state: &mut InstanceState<T::InstanceState, U>,
+ ch: CallHook,
+ ) -> anyhow::Result<()> {
+ match ch {
+ CallHook::CallingWasm | CallHook::ReturningFromHost => {
+ debug_assert!(state.cpu_time_last_entry.is_none());
+ state.cpu_time_last_entry = Some(Instant::now());
+ }
+ CallHook::ReturningFromWasm | CallHook::CallingHost => {
+ let elapsed = state.cpu_time_last_entry.take().unwrap().elapsed();
+ state.cpu_time_elapsed += elapsed;
+ }
+ }
+
+ Ok(())
+ }
+}
+
 /// InstanceState is the [`spin_core::Store`] `data` for an instance.
 ///
 /// It is generic over the [`RuntimeFactors::InstanceState`] and any ad-hoc
@@ -282,6 +328,43 @@ pub struct InstanceState<T, U> {
  core: spin_core::State,
  factors: T,
  executor: U,
+ /// The component ID.
+ component_id: String,
+
+ /// The last time guest code started running in this instance.
+ cpu_time_last_entry: Option<Instant>,
+ /// The total CPU time elapsed actively running guest code in this instance.
+ cpu_time_elapsed: Duration,
+ /// The memory (in bytes) consumed on initialization.
+ memory_used_on_init: u64,
+}
+
+impl<T, U> Drop for InstanceState<T, U> {
+ fn drop(&mut self) {
+ // Record the component execution time.
+ #[cfg(feature = "cpu-time-metrics")]
+ spin_telemetry::metrics::histogram!(
+ spin.component_cpu_time = self.cpu_time_elapsed.as_secs_f64(),
+ component_id = self.component_id,
+ // According to the OpenTelemetry spec, instruments measuring durations should use "s" as the unit.
+ // See https://opentelemetry.io/docs/specs/semconv/general/metrics/#units
+ unit = "s"
+ );
+
+ // Record the component memory consumed on initialization.
+ spin_telemetry::metrics::histogram!(
+ spin.component_memory_used_on_init = self.memory_used_on_init,
+ component_id = self.component_id,
+ unit = "By"
+ );
+
+ // Record the component memory consumed during execution.
+ spin_telemetry::metrics::histogram!(
+ spin.component_memory_used = self.core.memory_consumed(),
+ component_id = self.component_id,
+ unit = "By"
+ );
+ }
 }
 
 impl<T, U> InstanceState<T, U> {