diff --git a/crates/nexum-runtime-metrics/src/lib.rs b/crates/nexum-runtime-metrics/src/lib.rs index f052ff5..e3bb431 100644 --- a/crates/nexum-runtime-metrics/src/lib.rs +++ b/crates/nexum-runtime-metrics/src/lib.rs @@ -65,7 +65,7 @@ pub const METRICS: &[Metric] = &[ Metric { name: "nexum_runtime_dispatch_latency_seconds", kind: Kind::Histogram, - help: "Wall-clock seconds to dispatch one trigger.", + help: "Wall-clock seconds to dispatch one trigger, by module and outcome.", }, Metric { name: "nexum_runtime_log_fields_dropped_total", diff --git a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs index 09c9e1b..3c15e1f 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs @@ -312,19 +312,18 @@ impl>> Supervisor { "nexum_runtime_dispatch_dropped_total", "module" => module.name.to_string(), "trigger_kind" => trigger_kind, - "reason" => "rate_limited", + "reason" => <&str>::from(DispatchOutcome::RateLimited), ) .increment(1); return DispatchOutcome::RateLimited; } - if let Err(e) = module.live.store.set_fuel(module.seed.spec.fuel) { - error!( - module = %module.name, - chain_id, - trigger_kind, - error = %e, - "set_fuel failed - skipping" - ); + if !refuel( + &mut module.live.store, + module.seed.spec.fuel, + &module.name, + chain_id, + trigger_kind, + ) { return DispatchOutcome::FuelSetFailed; } let start = Instant::now(); @@ -335,16 +334,16 @@ impl>> Supervisor { .live .bindings .call_on_trigger(&mut module.live.store, trigger); - let outcome = with_dispatch_deadline(deadline, call) - .await - .unwrap_or_else(|exceeded| Err(wasmtime::Error::from(exceeded))); + let bounded = with_dispatch_deadline(deadline, call).await; + let deadline_hit = bounded.is_err(); + let result = bounded.unwrap_or_else(|exceeded| Err(wasmtime::Error::from(exceeded))); // One post-call sample: the trap instant is start plus elapsed, not // the pre-dispatch `now`. This is the same clock the lifecycle // reads, so under `start_paused` the latency histogram records the // virtual elapsed time: do not assert on it from a paused test. let elapsed = start.elapsed(); let latency_ms = elapsed.as_millis() as u64; - match outcome { + let outcome = match result { Ok(Ok(())) => { debug!( module = %module.name, @@ -354,12 +353,6 @@ impl>> Supervisor { latency_ms, "dispatch ok" ); - metrics::histogram!( - "nexum_runtime_dispatch_latency_seconds", - "module" => module.name.to_string(), - "trigger_kind" => trigger_kind, - ) - .record(elapsed.as_secs_f64()); module.health.dispatch_succeeded(); DispatchOutcome::Ok } @@ -388,6 +381,14 @@ impl>> Supervisor { let died_at = start + elapsed; let seed = crate::runtime::restart_policy::jitter_seed(module.name.as_str()); let verdict = module.health.record_trap(died_at, poison_policy, seed); + // One label for one event: the histogram's outcome and this + // counter's kind come from the same variant, so a deadline + // cannot read as a bug on one metric and a limit on the other. + let outcome = if deadline_hit { + DispatchOutcome::Deadline + } else { + DispatchOutcome::Trapped + }; error!( module = %module.name, chain_id, @@ -402,7 +403,7 @@ impl>> Supervisor { metrics::counter!( "nexum_runtime_module_errors_total", "module" => module.name.clone(), - "error_kind" => "trap", + "error_kind" => <&str>::from(outcome), ) .increment(1); // Leave a retrievable panic record on the dead run; the full @@ -416,12 +417,52 @@ impl>> Supervisor { if let Some(recent) = verdict.poisoned { report_poison(&module.name, recent, poison_policy.window, trap.to_string()); } - DispatchOutcome::Trapped + outcome } - } + }; + // Every outcome that entered the guest contributes a sample: a + // success-only histogram reads p95 low exactly when dispatch is + // failing. + metrics::histogram!( + "nexum_runtime_dispatch_latency_seconds", + "module" => module.name.to_string(), + "trigger_kind" => trigger_kind, + "outcome" => <&str>::from(outcome), + ) + .record(elapsed.as_secs_f64()); + outcome } } +/// Grants the dispatch its fuel budget; `false` means the trigger never +/// reached the guest and was counted as a drop. +pub(super) fn refuel( + store: &mut wasmtime::Store, + fuel: u64, + module: &ModuleId, + chain_id: u64, + trigger_kind: &'static str, +) -> bool { + let Err(e) = store.set_fuel(fuel) else { + return true; + }; + error!( + module = %module, + chain_id, + trigger_kind, + error = %e, + "set_fuel failed - skipping" + ); + metrics::counter!( + "nexum_runtime_dispatch_dropped_total", + "module" => module.clone(), + "trigger_kind" => trigger_kind, + "reason" => <&str>::from(DispatchOutcome::FuelSetFailed), + ) + .increment(1); + false +} + /// The poison-transition trio: quarantine warn plus gauge, with the trap /// that crossed the threshold. fn report_poison(name: &ModuleId, recent_failures: u32, window: Duration, last_error: String) { @@ -459,13 +500,19 @@ pub(super) async fn with_dispatch_deadline( .map_err(|_elapsed| DeadlineExceeded(deadline)) } -#[derive(Debug)] +/// The `outcome` label on the latency histogram; the two pre-guest drops carry +/// theirs as the `reason` on `nexum_runtime_dispatch_dropped_total` instead. +#[derive(Debug, Clone, Copy, strum::IntoStaticStr)] +#[strum(serialize_all = "snake_case")] pub(super) enum DispatchOutcome { Ok, /// Guest returned a typed `fault` via WIT, not a trap; the module stays alive. Fault, /// Marked dead, maybe quarantined per the poison policy. + #[strum(serialize = "trap")] Trapped, + /// Cut off at the wall-clock deadline; handled like a trap. + Deadline, /// `set_fuel` failed before the call; the module stays alive, the trigger skips. FuelSetFailed, /// Dropped before the guest runs; liveness untouched. diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs index d6050db..22b6c6a 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs @@ -18,11 +18,7 @@ fn a_boot_refusal_increments_the_counter_under_its_parse_class() { // Raw TOML: the textual absence of [dependencies] is the fixture. let manifest = "[component]\nname = \"example\"\n"; let (refusal, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(scenario().module(manifest.to_owned()).expect_refusal()) + block_on_current_thread(scenario().module(manifest.to_owned()).expect_refusal()) }); refusal.variant::(|e| { matches!(e, BootRefusal::Manifest(ParseError::MissingCapabilities)) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs index 67621e8..a41dc8a 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs @@ -244,21 +244,17 @@ fn a_guest_request_for_an_unconfigured_chain_counts_under_the_sentinel() { // `scenario()` boots over an empty pool while `test_chain_configs()` // still declares chain 1. let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module(workspace_manifest( - "modules/fixtures/slow-host/component.toml", - )) - .boot() - .await - .expect("slow-host boots over the empty pool"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots over the empty pool"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1, "the fixture swallows the request error"); let hits = samples_named(&samples, "nexum_runtime_chain_request_total"); @@ -288,22 +284,17 @@ fn a_guest_request_for_a_configured_chain_keeps_its_chain_id() { let node = FakeNode::new(); node.on_method(nexum_world::ChainMethod::EthBlockNumber, "\"0x1\""); let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = - BootScenario::over(mock_components_from(&node, MockStateStore::new())) - .wasm(wasm) - .module(workspace_manifest( - "modules/fixtures/slow-host/component.toml", - )) - .boot() - .await - .expect("slow-host boots over the mocked pool"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = BootScenario::over(mock_components_from(&node, MockStateStore::new())) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots over the mocked pool"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1); let hits = samples_named(&samples, "nexum_runtime_chain_request_total"); diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs index 69dfc51..07daf3b 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs @@ -2,6 +2,7 @@ use super::*; use crate::engine_config::DispatchLimitsSection; +use crate::test_utils::{Sample, capture_metrics, samples_named}; fn deadline_secs(secs: u64) -> DispatchLimitsSection { DispatchLimitsSection { @@ -10,6 +11,16 @@ fn deadline_secs(secs: u64) -> DispatchLimitsSection { } } +/// The `outcome` label of every latency sample recorded. +fn latency_outcomes(samples: &[Sample]) -> Vec<&str> { + samples_named(samples, "nexum_runtime_dispatch_latency_seconds") + .into_iter() + .flat_map(|sample| sample.labels.iter()) + .filter(|(key, _)| key == "outcome") + .map(|(_, value)| value.as_str()) + .collect() +} + #[test] fn module_limits_default_to_policy_ceilings_when_unset() { let cfg = PolicyCeilings::default(); @@ -259,29 +270,24 @@ async fn dispatch_deadline_cuts_off_a_blocked_host_call_and_recovers() { #[test] fn a_delivered_block_sets_the_last_delivered_gauge() { use crate::test_utils::metrics_util::debugging::DebugValue; - use crate::test_utils::{capture_metrics, samples_named}; let Some(wasm) = example_wasm_or_skip() else { return; }; let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module( - TestManifest::new("module-a") - .cap("logging") - .block_trigger(1), - ) - .boot() - .await - .expect("boot"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module( + TestManifest::new("module-a") + .cap("logging") + .block_trigger(1), + ) + .boot() + .await + .expect("boot"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1); let hits = samples_named(&samples, "nexum_runtime_chain_last_delivered_height"); @@ -298,39 +304,34 @@ fn a_delivered_block_sets_the_last_delivered_gauge() { #[test] fn an_older_delivery_does_not_lower_the_last_delivered_gauge() { use crate::test_utils::metrics_util::debugging::DebugValue; - use crate::test_utils::{capture_metrics, samples_named}; let Some(wasm) = example_wasm_or_skip() else { return; }; let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module( - TestManifest::new("module-a") - .cap("logging") - .block_trigger(1), - ) - .boot() - .await - .expect("boot"); - let newer = booted.dispatch_block_on(1).await; - let older = booted - .supervisor - .dispatch_block(nexum::host::types::Block { - chain_id: 1, - number: 18_000_000, - hash: vec![0xcd; 32], - timestamp: 1_700_000_000_000, - }) - .await; - newer + older - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module( + TestManifest::new("module-a") + .cap("logging") + .block_trigger(1), + ) + .boot() + .await + .expect("boot"); + let newer = booted.dispatch_block_on(1).await; + let older = booted + .supervisor + .dispatch_block(nexum::host::types::Block { + chain_id: 1, + number: 18_000_000, + hash: vec![0xcd; 32], + timestamp: 1_700_000_000_000, + }) + .await; + newer + older + }) }); assert_eq!(dispatched, 2, "both blocks reached the module"); let hits = samples_named(&samples, "nexum_runtime_chain_last_delivered_height"); @@ -543,3 +544,139 @@ async fn multi_chain_poisoned_module_does_not_affect_other_chains() { assert_eq!(booted.supervisor.alive_count(), 1, "only example is alive"); assert_eq!(booted.supervisor.poisoned_count(), 1); } + +/// fuel-bomb traps on chain 1; the example succeeds on chain 100. +#[test] +fn a_trap_and_a_success_each_record_a_labelled_latency_sample() { + let Some(bomb_wasm) = module_wasm_or_skip("fuel-bomb") else { + return; + }; + let Some(example_wasm) = example_wasm_or_skip() else { + return; + }; + let ((), samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = scenario() + .module( + Entry::new(workspace_manifest( + "modules/fixtures/fuel-bomb/component.toml", + )) + .wasm(bomb_wasm), + ) + .module( + Entry::new( + TestManifest::new("example") + .cap("logging") + .block_trigger(100), + ) + .wasm(example_wasm), + ) + .boot() + .await + .expect("boot"); + booted.dispatch_block_on(1).await; + assert_eq!(booted.dispatch_block_on(100).await, 1, "the example ran"); + }) + }); + let outcomes = latency_outcomes(&samples); + assert!(outcomes.contains(&"trap"), "{samples:?}"); + assert!(outcomes.contains(&"ok"), "{samples:?}"); +} + +/// slow-host parks its one host call an hour past the 1 s deadline, so +/// the dispatch ends fatally like a trap and carries its own label. +#[test] +fn a_deadline_hit_records_a_latency_sample_labelled_deadline() { + let Some(wasm) = module_wasm_or_skip("slow-host") else { + return; + }; + let node = crate::test_utils::FakeNode::new(); + node.on_method(nexum_world::ChainMethod::EthBlockNumber, "\"0x1\""); + node.delay_next_request(Duration::from_secs(3600)); + let (dispatched, samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = BootScenario::over(crate::test_utils::mock_components_from( + &node, + crate::test_utils::MockStateStore::new(), + )) + .limits(limits_with(|limits| limits.dispatch = deadline_secs(1))) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots"); + // The park is an hour past the 1 s deadline; pausing here waits + // out neither. + tokio::time::pause(); + booted.dispatch_block_on(1).await + }) + }); + assert_eq!(dispatched, 0, "the deadline cut the blocked host call off"); + assert!( + latency_outcomes(&samples).contains(&"deadline"), + "{samples:?}", + ); + let errors = samples_named(&samples, "nexum_runtime_module_errors_total"); + assert!( + errors.iter().any(|s| s.has_label("error_kind", "deadline")), + "{samples:?}", + ); + assert!( + !errors.iter().any(|s| s.has_label("error_kind", "trap")), + "a deadline is a limit, not a trap: {samples:?}", + ); +} + +/// A zero state quota faults the fixture's first store write, which the +/// guest returns as a typed WIT fault rather than trapping. +#[test] +fn a_fault_records_a_latency_sample_labelled_fault() { + let Some(wasm) = module_wasm_or_skip("flaky-bomb") else { + return; + }; + let ((dispatched, alive), samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = scenario() + .policy(PolicySection { + ceilings: PolicyCeilings { + max_state_bytes: 0, + ..PolicyCeilings::default() + }, + ..PolicySection::default() + }) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/flaky-bomb/component.toml", + )) + .boot() + .await + .expect("flaky-bomb boots"); + let dispatched = booted.dispatch_block_on(1).await; + (dispatched, booted.supervisor.alive_count()) + }) + }); + assert_eq!(dispatched, 0, "the quota refused the store write"); + assert_eq!(alive, 1, "a fault leaves the module alive"); + assert!(latency_outcomes(&samples).contains(&"fault"), "{samples:?}"); +} + +/// An engine without fuel metering is the only way `set_fuel` fails. +#[test] +fn a_failed_fuel_set_is_counted_as_a_drop() { + let engine = wasmtime::Engine::default(); + let mut store = wasmtime::Store::new(&engine, ()); + let module = nexum_primitives::module_id::ModuleId::parse("m").expect("a plain name parses"); + let (granted, samples) = capture_metrics(|| refuel(&mut store, 1_000, &module, 1, "block")); + assert!(!granted, "an engine without fuel cannot be refuelled"); + let hits = samples_named(&samples, "nexum_runtime_dispatch_dropped_total"); + assert_eq!(hits.len(), 1, "one drop counted: {samples:?}"); + assert!( + hits[0].has_label("reason", "fuel_set_failed") + && hits[0].has_label("module", "m") + && hits[0].has_label("trigger_kind", "block"), + "{:?}", + hits[0].labels, + ); +} diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs index a076258..ed986e8 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs @@ -20,7 +20,7 @@ use super::artifact::{DigestPolicy, read_verified_component}; use super::cursors::{ chainlog_cursor_key, commit_chain_log_cursor, commit_chain_log_frontier, read_chain_log_cursor, }; -use super::dispatch::with_dispatch_deadline; +use super::dispatch::{refuel, with_dispatch_deadline}; use super::prepass::{ NamespaceLedger, claim_namespace, enforce_total_reservation, unconfigured_chain, }; @@ -37,8 +37,9 @@ use crate::manifest::{self, CapabilityRegistry, ParseError, ResourceSection}; use crate::supervisor::load::LoadRefusal; use crate::supervisor::prepass::BootRefusal; use crate::test_utils::{ - BootScenario, Entry, LocalTypes, ManifestInput, Refusal, TestManifest, example_wasm_or_skip, - limits_with, mock_components, module_wasm_or_skip, test_wasmtime_engine, workspace_root, + BootScenario, Entry, LocalTypes, ManifestInput, Refusal, TestManifest, block_on_current_thread, + example_wasm_or_skip, limits_with, mock_components, module_wasm_or_skip, test_wasmtime_engine, + workspace_root, }; use nexum_primitives::digest::{ContentDigest, DigestMismatch}; use nexum_runtime_chain::ProviderPool; diff --git a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs index c3f6572..634dc2d 100644 --- a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs +++ b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs @@ -16,10 +16,10 @@ pub(crate) use nexum_runtime_testing::{ #[cfg(test)] pub(crate) use nexum_runtime_testing::{ - FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, capture_metrics, - example_wasm_or_skip, linked_block, metrics_util, mock_components, mock_components_from, - mocked_pool, module_wasm_or_skip, rpc_err, rpc_head, rpc_ok, samples_named, test_hash, - workspace_root, + FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, Sample, block_on_current_thread, + capture_metrics, example_wasm_or_skip, linked_block, metrics_util, mock_components, + mock_components_from, mocked_pool, module_wasm_or_skip, rpc_err, rpc_head, rpc_ok, + samples_named, test_hash, workspace_root, }; #[cfg(test)] diff --git a/crates/nexum-runtime-testing/Cargo.toml b/crates/nexum-runtime-testing/Cargo.toml index 225ebcf..2fdedcb 100644 --- a/crates/nexum-runtime-testing/Cargo.toml +++ b/crates/nexum-runtime-testing/Cargo.toml @@ -30,7 +30,7 @@ nexum-world = { path = "../nexum-world" } parking_lot.workspace = true serde.workspace = true serde_json = { workspace = true, features = ["std"] } -tokio = { workspace = true, features = ["sync", "time"] } +tokio = { workspace = true, features = ["rt", "sync", "time"] } toml.workspace = true tower.workspace = true wasmtime-wasi.workspace = true diff --git a/crates/nexum-runtime-testing/src/lib.rs b/crates/nexum-runtime-testing/src/lib.rs index 166c8e9..5abc9c0 100644 --- a/crates/nexum-runtime-testing/src/lib.rs +++ b/crates/nexum-runtime-testing/src/lib.rs @@ -22,7 +22,7 @@ pub use alloy_transport::mock::MockResponse; pub use builders::Prebuilt; pub use clock::ManualClock; pub use manifest::{ManifestInput, TestManifest, manifest}; -pub use metrics_capture::{Sample, capture_metrics, samples_named}; +pub use metrics_capture::{Sample, block_on_current_thread, capture_metrics, samples_named}; pub use rpc::{ CapturedRpc, FakeNode, MockRpc, linked_block, mocked_pool, rpc_err, rpc_head, rpc_ok, test_hash, }; diff --git a/crates/nexum-runtime-testing/src/metrics_capture.rs b/crates/nexum-runtime-testing/src/metrics_capture.rs index 189a92e..2d9868c 100644 --- a/crates/nexum-runtime-testing/src/metrics_capture.rs +++ b/crates/nexum-runtime-testing/src/metrics_capture.rs @@ -56,6 +56,19 @@ pub fn samples_named<'a>(samples: &'a [Sample], name: &str) -> Vec<&'a Sample> { samples.iter().filter(|s| s.name == name).collect() } +/// Drive `f` to completion on the calling thread. +/// +/// [`capture_metrics`] installs a thread-local recorder, so work spawned onto +/// another runtime's worker records into a different one and the capture comes +/// back empty. +pub fn block_on_current_thread(f: F) -> F::Output { + tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("current-thread runtime") + .block_on(f) +} + #[cfg(test)] mod tests { use super::*; diff --git a/crates/nexum-runtime/src/addons.rs b/crates/nexum-runtime/src/addons.rs index c2a2280..c694712 100644 --- a/crates/nexum-runtime/src/addons.rs +++ b/crates/nexum-runtime/src/addons.rs @@ -125,7 +125,8 @@ mod tests { use crate::test_utils::Refusal; /// The `NexumDispatchLatency` alert reads `_bucket` series by `le`, so - /// the latency metric must render as a Prometheus histogram. + /// the latency metric must render as a Prometheus histogram. Bounds are + /// matched on the bare name, so call-site labels cannot cost them. #[test] fn the_latency_histogram_renders_bucket_series() { const NAME: &str = "nexum_runtime_dispatch_latency_seconds"; @@ -134,7 +135,8 @@ mod tests { .build_recorder(); let handle = recorder.handle(); metrics::with_local_recorder(&recorder, || { - metrics::histogram!(NAME, "module" => "m", "trigger_kind" => "block").record(0.5); + metrics::histogram!(NAME, "module" => "m", "trigger_kind" => "block", "outcome" => "trap") + .record(0.5); }); let rendered = handle.render(); assert!( diff --git a/docs/production.md b/docs/production.md index 5392f6a..453c694 100644 --- a/docs/production.md +++ b/docs/production.md @@ -188,9 +188,9 @@ With `enabled = false` the recorder is still installed, so call sites stay live, | Metric | Type | Labels | Meaning | |---|---|---|---| | `nexum_runtime_boot_refusals_total` | counter | `error_kind` | Boot refusals by error kind. | -| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind` | Wall-clock seconds to dispatch one trigger. | -| `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. A block is not replayed; an event is, from its cursor. | -| `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap; other values are fault labels. | +| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind`, `outcome` | Wall-clock seconds to dispatch one trigger, sampled on every dispatch that reached the guest. `outcome` is one of `ok`, `fault`, `trap` and `deadline`, so a p95 read over the bare metric covers the failing dispatches too; sum `outcome` away to read one module's whole distribution, as `NexumDispatchLatency` below does. A trigger dropped before the guest runs records no latency and is counted in `nexum_runtime_dispatch_dropped_total` instead. `outcome` is bounded at those four values, so it multiplies the series count by at most four: each `module`, `trigger_kind` and `outcome` triple carries the eleven buckets plus `+Inf`, `_sum` and `_count`. | +| `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. `reason = "fuel_set_failed"` is the per-dispatch fuel budget failing to apply: the module stays alive and the trigger is skipped. A block is not replayed; an event is, from its cursor. | +| `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap and `"deadline"` is a dispatch cut off at `[limits.dispatch] deadline_secs`; other values are fault labels. The trap and deadline values are the same strings the latency histogram uses for `outcome`, so the two metrics agree about one event. | | `nexum_runtime_module_restarts_total` | counter | `module` | Module restart attempts. | | `nexum_runtime_module_poisoned` | gauge | `module` | `1` once a module crosses `[limits.poison]` (default 5 failures in 600 s) or its event source reports an unrecoverable condition. Stays `1` until the process restarts. | | `nexum_runtime_module_unverified` | gauge | `module` | `1` for a module loaded with neither a `[[modules]].digest` nor a `[component].digest`, so nothing checked its bytes. Set once at boot and never cleared; a pinned module emits no series, so `sum` is the fleet's unverified count. Reaching this state at all needs `require_component_digest = false`, or a single-wasm command-line override. | @@ -237,6 +237,9 @@ groups: annotations: summary: "Nexum module {{ $labels.module }} is running unverified; pin its digest in engine.toml" + # A deadline is a limit doing its job, so it is deliberately not here. + # Alert on error_kind="deadline" separately if a module should never + # reach one. - alert: NexumModuleTraps expr: rate(nexum_runtime_module_errors_total{error_kind="trap"}[5m]) > 0 for: 5m