feat(metrics): adding emitting metrics for component CPU and memory usage

Signed-off-by: Andrew Steurer <94206073+asteurer@users.noreply.github.com>

Author: asteurer

Cargo.lock

@@ -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" }
@@ -112,6 +113,8 @@ 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.
+call-hook = ["spin-factors-executor/call-hook"]
 
 [workspace]
 members = [

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]
+call-hook = ["spin-core/call-hook"]

crates/factors-executor/Cargo.toml

@@ -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,
+            mem_usg_init: 0,
+            component_id: self.app_component.id().into(),
         };
         let mut store = self.store_builder.build(instance_state)?;
+
+        #[cfg(feature = "call-hook")]
+        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().mem_usg_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,
+            mem_usg_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,42 @@ pub struct InstanceState<T, U> {
     core: spin_core::State,
     factors: T,
     executor: U,
+    /// The last time guest code started running in this instance.
+    pub cpu_time_last_entry: Option<Instant>,
+    /// The total CPU time elapsed actively running guest code in this instance.
+    pub cpu_time_elapsed: Duration,
+    /// The component ID.
+    pub component_id: String,
+    /// The memory (in bytes) consumed on initialization.
+    pub mem_usg_init: u64,
+}
+
+impl<T, U> Drop for InstanceState<T, U> {
+    fn drop(&mut self) {
+        // Record the component execution time.
+        #[cfg(feature = "call-hook")]
+        spin_telemetry::metrics::histogram!(
+            spin.component_cpu_time = self.cpu_time_elapsed.as_micros() as 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_init_memory_used = self.mem_usg_init,
+            component_id = self.component_id,
+            unit = "bytes"
+        );
+
+        // Record the component memory consumed during execution.
+        spin_telemetry::metrics::histogram!(
+            spin.component_exec_memory_used = self.core.memory_consumed(),
+            component_id = self.component_id,
+            unit = "bytes"
+        );
+    }
 }
 
 impl<T, U> InstanceState<T, U> {