diff --git a/Cargo.lock b/Cargo.lock index 78dde5610..36f119ecb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -8309,6 +8309,7 @@ dependencies = [ "spin-doctor", "spin-environments", "spin-factor-outbound-networking", + "spin-factors-executor", "spin-http", "spin-loader", "spin-locked-app", @@ -8734,7 +8735,9 @@ dependencies = [ "spin-factor-wasi", "spin-factors", "spin-factors-test", + "spin-telemetry", "tokio", + "tracing", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 8a6bd7801..34757ef16 100644 --- a/Cargo.toml +++ b/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 = [ diff --git a/crates/factors-executor/Cargo.toml b/crates/factors-executor/Cargo.toml index 9dd5f80b0..56675bf0e 100644 --- a/crates/factors-executor/Cargo.toml +++ b/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"] diff --git a/crates/factors-executor/src/lib.rs b/crates/factors-executor/src/lib.rs index 04734fd5b..dc68ab504 100644 --- a/crates/factors-executor/src/lib.rs +++ b/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 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::(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 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( + &self, + state: &mut InstanceState, + 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 { 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, + /// 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 Drop for InstanceState { + 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 InstanceState {