diff --git a/local/recipes/system/driver-manager/source/src/config.rs b/local/recipes/system/driver-manager/source/src/config.rs index b0f99d04f9..6a801bb195 100644 --- a/local/recipes/system/driver-manager/source/src/config.rs +++ b/local/recipes/system/driver-manager/source/src/config.rs @@ -610,6 +610,8 @@ impl Driver for DriverConfig { // concurrent probe of the same device loses atomically. This is // the same model pcid-spawner uses — the channel fd doubles as // the claim and is later handed to the spawned child. + let claim_start = Instant::now(); + let device_path = pci_device_path(info); let mut handle = match PciFunctionHandle::connect_by_path(Path::new(&device_path)) { Ok(handle) => handle, @@ -662,17 +664,27 @@ impl Driver for DriverConfig { ); } if quirk_decision.needs_firmware { - log::info!( - "quirk-defer: driver={} device={} waiting-for-firmware", - self.name, - device_key - ); - return ProbeResult::Deferred { - reason: format!( - "PciQuirkFlags::NEED_FIRMWARE set for {}", + if check_scheme_available("firmware") { + log::info!( + "firmware-ready: driver={} device={} firmware scheme available", + self.name, device_key - ), - }; + ); + crate::timing::record_firmware_ready_if_deferred(&device_key); + } else { + log::info!( + "quirk-defer: driver={} device={} waiting-for-firmware", + self.name, + device_key + ); + crate::timing::record_firmware_defer_start(&device_key); + return ProbeResult::Deferred { + reason: format!( + "PciQuirkFlags::NEED_FIRMWARE set for {}", + device_key + ), + }; + } } if blacklist_match(&self.name) { @@ -811,12 +823,16 @@ impl Driver for DriverConfig { match cmd.spawn() { Ok(child) => { let pid = child.id(); + let claim_spawn_us = claim_start.elapsed().as_micros() as u64; + crate::timing::record("claim-spawn", claim_spawn_us); log::info!( - "driver {} spawned (pid {}) for device {}", + "driver {} spawned (pid {}) for device {} (claim-spawn {}us)", self.name, pid, - device_key + device_key, + claim_spawn_us ); + crate::timing::record_firmware_ready_if_deferred(&device_key); if let Some((channel, key)) = error_channel { crate::error_channel::global() .insert(key, std::sync::Arc::new(channel)); diff --git a/local/recipes/system/driver-manager/source/src/main.rs b/local/recipes/system/driver-manager/source/src/main.rs index 00b0972f33..dd2b42f305 100644 --- a/local/recipes/system/driver-manager/source/src/main.rs +++ b/local/recipes/system/driver-manager/source/src/main.rs @@ -14,6 +14,7 @@ mod reaper; mod registry; mod scheme; mod sighup; +mod timing; mod unified_events; use std::sync::{Arc, Mutex}; @@ -113,6 +114,8 @@ fn run_enumeration( bound, deferred, enum_duration.as_millis() ); + log_timing_snapshot(); + // Success trigger (mirrors Linux's driver_deferred_probe_trigger): // a successful bind may unblock deferred probes whose dependencies // were the just-bound drivers. Retry immediately rather than @@ -202,6 +205,48 @@ fn log_timeline(event: &ProbeEvent) { } } +fn log_timing_snapshot() { + if is_initfs_mode() { + return; + } + let timestamp = std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap_or_default() + .as_millis(); + + let mut entry = format!(r#"{{"ts":{},"event":"timing","buckets":{{"#, timestamp); + let metrics = timing::summary(); + let mut first = true; + for m in &metrics { + if !first { + entry.push(','); + } + first = false; + entry.push_str(&format!( + r#""{}":{{"count":{},"min_us":{},"max_us":{},"p50_us":{},"p95_us":{},"p99_us":{}}}"#, + m.bucket, m.count, m.min_us, m.max_us, m.p50_us, m.p95_us, m.p99_us + )); + } + entry.push_str("}}"); + + match OpenOptions::new() + .create(true) + .append(true) + .open(BOOT_TIMELINE_PATH) + { + Ok(mut file) => { + if let Err(err) = writeln!(file, "{entry}") { + log::warn!( + "failed to append timing snapshot to {BOOT_TIMELINE_PATH}: {err}" + ); + } + } + Err(err) => { + log::warn!("failed to open boot timeline log at {BOOT_TIMELINE_PATH}: {err}"); + } + } +} + fn main() { log::set_logger(&StderrLogger).ok(); log::set_max_level(log::LevelFilter::Info); diff --git a/local/recipes/system/driver-manager/source/src/scheme.rs b/local/recipes/system/driver-manager/source/src/scheme.rs index 7fb6620482..3aba75ed9e 100644 --- a/local/recipes/system/driver-manager/source/src/scheme.rs +++ b/local/recipes/system/driver-manager/source/src/scheme.rs @@ -57,6 +57,7 @@ enum HandleKind { DriverOverride, Rescan, Recover, + Timing, } pub struct DriverManagerScheme { @@ -170,6 +171,7 @@ impl DriverManagerScheme { ["driver_override"] => Ok(HandleKind::DriverOverride), ["rescan"] => Ok(HandleKind::Rescan), ["recover"] => Ok(HandleKind::Recover), + ["timing"] => Ok(HandleKind::Timing), ["devices", pci_addr] if Self::valid_pci_addr(pci_addr) => { let _ = self.device_status(pci_addr)?; Ok(HandleKind::Device((*pci_addr).to_string())) @@ -242,7 +244,7 @@ impl DriverManagerScheme { fn read_handle_string(&self, id: usize, kind: &HandleKind) -> Result { match kind { HandleKind::Root => { - Ok("devices\nbound\nevents\nmodalias\nbind\nunbind\nnew_id\nremove_id\ndriver_override\nrescan\nrecover\n".to_string()) + Ok("devices\nbound\nevents\nmodalias\nbind\nunbind\nnew_id\nremove_id\ndriver_override\nrescan\nrecover\ntiming\n".to_string()) } HandleKind::Devices => { let addresses = self.sorted_bound_addresses().map_err(|err| { @@ -290,6 +292,7 @@ impl DriverManagerScheme { HandleKind::RemoveId => Ok("write the same fields as new_id to remove\n".to_string()), HandleKind::Rescan => Ok("write anything to re-enumerate all buses\n".to_string()), HandleKind::Recover => Ok("write ' ' to trigger AER recovery\n".to_string()), + HandleKind::Timing => Ok(crate::timing::format_json()), } } @@ -309,6 +312,7 @@ impl DriverManagerScheme { HandleKind::DriverOverride => format!("{SCHEME_NAME}:/driver_override"), HandleKind::Rescan => format!("{SCHEME_NAME}:/rescan"), HandleKind::Recover => format!("{SCHEME_NAME}:/recover"), + HandleKind::Timing => format!("{SCHEME_NAME}:/timing"), } } @@ -326,7 +330,8 @@ impl DriverManagerScheme { | HandleKind::RemoveId | HandleKind::DriverOverride | HandleKind::Rescan - | HandleKind::Recover => MODE_FILE | 0o644, + | HandleKind::Recover + | HandleKind::Timing => MODE_FILE | 0o644, } } diff --git a/local/recipes/system/driver-manager/source/src/timing.rs b/local/recipes/system/driver-manager/source/src/timing.rs new file mode 100644 index 0000000000..e395288591 --- /dev/null +++ b/local/recipes/system/driver-manager/source/src/timing.rs @@ -0,0 +1,869 @@ +//! Boot race instrumentation: latency metrics for driver-manager. +//! +//! Records per-bucket latency measurements and aggregates them into +//! p50/p95/p99/max summaries. The four buckets are: +//! +//! | Bucket | What it measures | +//! |-------------------|---------------------------------------------------------------| +//! | `claim-spawn` | Claim-to-spawn latency per device: from the start of the | +//! | | claim process to the successful spawn of the child daemon. | +//! | `firmware-ready` | Firmware-loader ready-to-driver-bind latency for drivers with | +//! | | the `NEED_FIRMWARE` quirk: from the first firmware-defer to | +//! | | the successful bind on retry. | +//! | `governor-switch` | Thermald governor-switch latency: from thermald writing to | +//! | | `/scheme/cpufreq/governor` to cpufreqd applying the new | +//! | | governor. (Recorded by cpufreqd when it is wired in.) | +//! | `aer-event` | Pcid AER event latency: from pcid's poller emitting the event | +//! | | to driver-manager's unified listener processing it. | +//! +//! Counter updates (count, sum, min, max) are lock-free via `AtomicU64`. +//! Percentile computation requires storing samples; this is done under a +//! brief `Mutex` lock capped at [`MAX_SAMPLES`]. A ring buffer of the most +//! recent [`RING_SIZE`] measurements is kept for postmortem inspection. +//! +//! Summaries are served via `/scheme/driver-manager/timing` (read-only JSON). + +use std::collections::{HashMap, VecDeque}; +use std::sync::Mutex; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Instant; + +/// Maximum number of samples retained per bucket for percentile computation. +const MAX_SAMPLES: usize = 4096; + +/// Number of entries retained in the per-bucket ring buffer for postmortem. +const RING_SIZE: usize = 256; + +// ── LatencyMetric ───────────────────────────────────────────────── + +/// Aggregated latency metric for one bucket. Returned by [`summary`] and +/// serialized by [`format_json`]. +#[derive(Clone, Debug, PartialEq, Eq)] +pub struct LatencyMetric { + pub bucket: &'static str, + pub count: u64, + pub sum_us: u64, + pub min_us: u64, + pub max_us: u64, + pub p50_us: u64, + pub p95_us: u64, + pub p99_us: u64, +} + +// ── Bucket ──────────────────────────────────────────────────────── + +/// One latency measurement bucket. +/// +/// Updates to `count`/`sum_us`/`min_us`/`max_us` are lock-free +/// (`AtomicU64`). Samples for percentile computation are stored under a +/// `Mutex`, capped at [`MAX_SAMPLES`]. A ring buffer of the most recent +/// [`RING_SIZE`] measurements is kept for postmortem inspection. +struct Bucket { + count: AtomicU64, + sum_us: AtomicU64, + min_us: AtomicU64, + max_us: AtomicU64, + samples: Mutex>, + ring: Mutex>, +} + +impl Bucket { + const fn new() -> Self { + Self { + count: AtomicU64::new(0), + sum_us: AtomicU64::new(0), + min_us: AtomicU64::new(u64::MAX), + max_us: AtomicU64::new(0), + samples: Mutex::new(Vec::new()), + ring: Mutex::new(VecDeque::new()), + } + } + + /// Record a latency measurement (in microseconds) into this bucket. + fn record(&self, latency_us: u64) { + self.count.fetch_add(1, Ordering::Relaxed); + + // Saturating add for sum — prevents overflow on extreme counts. + let _ = self.sum_us.fetch_update( + Ordering::Relaxed, + Ordering::Relaxed, + |v| Some(v.saturating_add(latency_us)), + ); + + // fetch_min / fetch_max update atomically. + let _ = self.min_us.fetch_min(latency_us, Ordering::Relaxed); + let _ = self.max_us.fetch_max(latency_us, Ordering::Relaxed); + + // Store sample for percentile computation. If the buffer is full, + // we stop appending — the existing MAX_SAMPLES are sufficient for + // stable percentile estimates. A reservoir-sampling scheme would + // be more representative for very long runs but adds complexity. + if let Ok(mut samples) = self.samples.lock() { + if samples.len() < MAX_SAMPLES { + samples.push(latency_us); + } + } + + // Ring buffer: always keeps the most recent RING_SIZE values. + if let Ok(mut ring) = self.ring.lock() { + if ring.len() >= RING_SIZE { + ring.pop_front(); + } + ring.push_back(latency_us); + } + } + + /// Snapshot this bucket into a [`LatencyMetric`]. + fn snapshot(&self, name: &'static str) -> LatencyMetric { + let count = self.count.load(Ordering::Relaxed); + let sum_us = self.sum_us.load(Ordering::Relaxed); + let mut min_us = self.min_us.load(Ordering::Relaxed); + let max_us = self.max_us.load(Ordering::Relaxed); + + // If no samples were recorded, min is still u64::MAX. + if count == 0 || min_us == u64::MAX { + min_us = 0; + } + + if count == 0 { + return LatencyMetric { + bucket: name, + count: 0, + sum_us: 0, + min_us: 0, + max_us: 0, + p50_us: 0, + p95_us: 0, + p99_us: 0, + }; + } + + let (p50, p95, p99) = match self.samples.lock() { + Ok(samples) => { + if samples.is_empty() { + (0u64, 0u64, 0u64) + } else { + let mut sorted = samples.clone(); + sorted.sort_unstable(); + let n = sorted.len(); + ( + sorted[percentile_index(50, n)], + sorted[percentile_index(95, n)], + sorted[percentile_index(99, n)], + ) + } + } + Err(_) => (0, 0, 0), + }; + + LatencyMetric { + bucket: name, + count, + sum_us, + min_us, + max_us, + p50_us: p50, + p95_us: p95, + p99_us: p99, + } + } + + /// Return a snapshot of the ring buffer (most recent measurements first). + #[allow(dead_code)] + fn recent(&self) -> Vec { + match self.ring.lock() { + Ok(ring) => ring.iter().rev().copied().collect(), + Err(_) => Vec::new(), + } + } +} + +/// Compute the 0-indexed position for the P-th percentile in a sorted +/// array of `n` elements using the nearest-rank method. +/// +/// Nearest-rank: the P-th percentile is the value at ordinal position +/// `ceil(P/100 × N)` (1-indexed). Returns the 0-indexed equivalent, +/// clamped to `[0, n-1]`. +fn percentile_index(percentile: u64, n: usize) -> usize { + if n == 0 { + return 0; + } + // ceil(percentile * n / 100) using integer arithmetic: + // (a + b - 1) / b == ceil(a / b) + let product = percentile * n as u64; + let ordinal = (product + 99) / 100; + (ordinal as usize).saturating_sub(1).min(n - 1) +} + +// ── Global registry ─────────────────────────────────────────────── + +static BUCKET_CLAIM_SPAWN: Bucket = Bucket::new(); +static BUCKET_FIRMWARE_READY: Bucket = Bucket::new(); +static BUCKET_GOVERNOR_SWITCH: Bucket = Bucket::new(); +static BUCKET_AER_EVENT: Bucket = Bucket::new(); + +/// All bucket names in canonical (output) order. +#[allow(dead_code)] +pub const BUCKET_NAMES: &[&str] = &[ + "claim-spawn", + "firmware-ready", + "governor-switch", + "aer-event", +]; + +/// Record a latency measurement (in microseconds) into the named bucket. +/// +/// Unknown bucket names are silently ignored (logged at `trace` level) +/// so a typo never crashes the probe path. +pub fn record(bucket: &str, latency_us: u64) { + match bucket { + "claim-spawn" => BUCKET_CLAIM_SPAWN.record(latency_us), + "firmware-ready" => BUCKET_FIRMWARE_READY.record(latency_us), + "governor-switch" => BUCKET_GOVERNOR_SWITCH.record(latency_us), + "aer-event" => BUCKET_AER_EVENT.record(latency_us), + other => log::trace!("timing: unknown bucket '{other}'"), + } +} + +/// Snapshot all buckets into metric summaries, in canonical bucket order. +pub fn summary() -> Vec { + vec![ + BUCKET_CLAIM_SPAWN.snapshot("claim-spawn"), + BUCKET_FIRMWARE_READY.snapshot("firmware-ready"), + BUCKET_GOVERNOR_SWITCH.snapshot("governor-switch"), + BUCKET_AER_EVENT.snapshot("aer-event"), + ] +} + +/// Format all buckets as JSON for `/scheme/driver-manager/timing`. +/// +/// Output format (v1): +/// ```json +/// { +/// "version": 1, +/// "buckets": { +/// "claim-spawn": { "count": 0, "min_us": 0, ... }, +/// ... +/// } +/// } +/// ``` +pub fn format_json() -> String { + format_metrics_json(&summary()) +} + +/// Format a slice of [`LatencyMetric`] as JSON. Pure function — no global +/// state reads. Used by [`format_json`] and by tests for golden snapshots. +pub fn format_metrics_json(metrics: &[LatencyMetric]) -> String { + let mut out = String::from(r#"{"version":1,"buckets":{"#); + let mut first = true; + for m in metrics { + if !first { + out.push(','); + } + first = false; + out.push_str(&format!( + r#""{bucket}":{{"count":{count},"min_us":{min_us},"max_us":{max_us},"p50_us":{p50_us},"p95_us":{p95_us},"p99_us":{p99_us},"sum_us":{sum_us}}}"#, + bucket = m.bucket, + count = m.count, + min_us = m.min_us, + max_us = m.max_us, + p50_us = m.p50_us, + p95_us = m.p95_us, + p99_us = m.p99_us, + sum_us = m.sum_us, + )); + } + out.push_str("}}"); + out +} + +// ── Firmware-defer tracking ─────────────────────────────────────── +// +// Tracks the first time a device was deferred due to NEED_FIRMWARE, so +// that when the same device eventually binds (firmware now available), +// we can measure the firmware-ready latency. Uses a per-device map under +// a Mutex. The Mutex wraps an Option because HashMap::new() is +// not const-evaluable in a static initializer. + +static FIRMWARE_DEFER_STARTS: Mutex>> = Mutex::new(None); + +/// Record the start of a firmware-related deferral for a device. +/// +/// Only the *first* deferral is recorded — subsequent retries for the +/// same device do not reset the timer, so the measured latency spans +/// from the original NEED_FIRMWARE detection to the eventual bind. +pub fn record_firmware_defer_start(device_key: &str) { + if let Ok(mut starts) = FIRMWARE_DEFER_STARTS.lock() { + let map = starts.get_or_insert_with(HashMap::new); + map.entry(device_key.to_string()) + .or_insert_with(Instant::now); + } +} + +/// If the device was previously firmware-deferred, record the +/// firmware-ready latency (from the first defer to now) and remove it +/// from the tracking map. +/// +/// Returns `true` if a measurement was recorded, `false` if the device +/// was not previously firmware-deferred. +pub fn record_firmware_ready_if_deferred(device_key: &str) -> bool { + if let Ok(mut starts) = FIRMWARE_DEFER_STARTS.lock() { + if let Some(map) = starts.as_mut() { + if let Some(start) = map.remove(device_key) { + let elapsed_us = start.elapsed().as_micros() as u64; + record("firmware-ready", elapsed_us); + return true; + } + } + } + false +} + +// ── AER timestamp parsing ───────────────────────────────────────── +// +// pcid's AER producer emits lines with a `ts=` field giving +// the wall-clock time the poller observed the error. By comparing that +// to the current wall-clock time, we measure the poller→consumer +// latency of the unified event listener. + +/// Parse a `ts=` field from a pcid AER event line and compute +/// the latency from that timestamp to now (in microseconds). +/// +/// Returns `None` if no parseable `ts=` field is present, or if the +/// computed latency would be negative (clock skew / stale event). +pub fn parse_aer_latency_us(raw: &str) -> Option { + let ts_str = parse_ts_field(raw)?; + let epoch_us = parse_rfc3339_to_epoch_micros(&ts_str)?; + let now_us = std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .ok()? + .as_micros() as u64; + if now_us > epoch_us { + Some(now_us - epoch_us) + } else { + None + } +} + +/// Extract the value of `ts=...` from a space-delimited event line. +/// +/// Returns only the RFC3339 timestamp portion (`YYYY-MM-DDTHH:MM:SS[.fff][Z]`), +/// stripping any trailing field content that shares the same whitespace-delimited +/// token (pcid uses `:` as a field separator, which collides with timestamp colons). +fn parse_ts_field(raw: &str) -> Option { + for token in raw.split_whitespace() { + if let Some(v) = token.strip_prefix("ts=") { + return Some(extract_rfc3339_prefix(v).to_string()); + } + } + None +} + +/// Extract the RFC3339 timestamp prefix from a string that may contain +/// additional colon-separated fields (e.g. `2026-07-25T12:34:56:severity=...`). +fn extract_rfc3339_prefix(s: &str) -> &str { + let bytes = s.as_bytes(); + if bytes.len() < 19 { + return s; + } + // Verify the YYYY-MM-DDTHH:MM:SS structure at known delimiter positions. + if bytes[4] != b'-' + || bytes[7] != b'-' + || bytes[10] != b'T' + || bytes[13] != b':' + || bytes[16] != b':' + { + return s; + } + let mut end = 19; + // Optional fractional seconds: .fff... + if end < bytes.len() && bytes[end] == b'.' { + end += 1; + while end < bytes.len() && bytes[end].is_ascii_digit() { + end += 1; + } + } + // Optional trailing Z. + if end < bytes.len() && bytes[end] == b'Z' { + end += 1; + } + &s[..end] +} + +/// Parse an RFC3339-ish timestamp `YYYY-MM-DDTHH:MM:SS[.fff][Z]` into +/// microseconds since the Unix epoch. +/// +/// Handles the subset of RFC3339 that pcid produces: date-time with +/// optional fractional seconds and optional trailing `Z`. Timezone +/// offsets are not supported (pcid emits wall-clock UTC without offset). +/// +/// Returns `None` on any parse failure. +fn parse_rfc3339_to_epoch_micros(ts: &str) -> Option { + let bytes = ts.as_bytes(); + // Minimum: "YYYY-MM-DDTHH:MM:SS" = 19 chars + if bytes.len() < 19 { + return None; + } + + // Parse fixed-width date-time fields with delimiter checks. + let year: u32 = std::str::from_utf8(&bytes[0..4]).ok()?.parse().ok()?; + if bytes[4] != b'-' { + return None; + } + let month: u32 = std::str::from_utf8(&bytes[5..7]).ok()?.parse().ok()?; + if bytes[7] != b'-' { + return None; + } + let day: u32 = std::str::from_utf8(&bytes[8..10]).ok()?.parse().ok()?; + if bytes[10] != b'T' { + return None; + } + let hour: u32 = std::str::from_utf8(&bytes[11..13]).ok()?.parse().ok()?; + if bytes[13] != b':' { + return None; + } + let minute: u32 = std::str::from_utf8(&bytes[14..16]).ok()?.parse().ok()?; + if bytes[16] != b':' { + return None; + } + let second: u32 = std::str::from_utf8(&bytes[17..19]).ok()?.parse().ok()?; + + // Validate ranges. + if month == 0 || month > 12 || day == 0 || day > 31 || hour > 23 || minute > 59 || second > 60 { + return None; + } + + // Parse optional fractional seconds (up to 6 digits → microseconds). + let mut micros: u32 = 0; + let mut idx = 19; + if idx < bytes.len() && bytes[idx] == b'.' { + idx += 1; + let frac_start = idx; + while idx < bytes.len() && bytes[idx].is_ascii_digit() { + idx += 1; + } + let frac_str = std::str::from_utf8(&bytes[frac_start..idx]).ok()?; + // Pad or truncate to exactly 6 digits. + let mut padded = format!("{frac_str:0<6}"); + padded.truncate(6); + micros = padded.parse().ok()?; + } + + // Skip optional 'Z' suffix (we assume UTC). + // Any trailing timezone offset is ignored — pcid emits UTC. + + let days = civil_to_days(year, month, day)?; + if days < 0 { + return None; + } + let epoch_seconds = days as u64 * 86_400 + hour as u64 * 3_600 + minute as u64 * 60 + second as u64; + Some(epoch_seconds * 1_000_000 + micros as u64) +} + +/// Convert a Gregorian calendar date to days since 1970-01-01. +/// +/// Uses Howard Hinnant's `days_from_civil` algorithm — a closed-form +/// conversion that is correct for all dates in the proleptic Gregorian +/// calendar. Returns `None` for invalid dates. +fn civil_to_days(y: u32, m: u32, d: u32) -> Option { + if m == 0 || m > 12 || d == 0 || d > 31 { + return None; + } + let y = y as i64; + let y_adj = if m <= 2 { y - 1 } else { y }; + let era = y_adj.div_euclid(400); + let yoe = y_adj.rem_euclid(400) as u64; // [0, 399] + let m_shift = if m > 2 { m - 3 } else { m + 9 } as u64; // [0, 11] + let doy = (153 * m_shift + 2) / 5 + d as u64 - 1; // [0, 365] + let doe = yoe * 365 + yoe / 4 - yoe / 100 + doy; // [0, 146096] + let days = era * 146_097 + doe as i64 - 719_468; + Some(days) +} + +// ── Tests ───────────────────────────────────────────────────────── + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::Arc; + use std::thread; + + // ── Single record + summary ────────────────────────────────── + + #[test] + fn single_record_then_summary() { + let bucket = Bucket::new(); + bucket.record(5_000); + let m = bucket.snapshot("test"); + assert_eq!(m.bucket, "test"); + assert_eq!(m.count, 1); + assert_eq!(m.sum_us, 5_000); + assert_eq!(m.min_us, 5_000); + assert_eq!(m.max_us, 5_000); + assert_eq!(m.p50_us, 5_000); + assert_eq!(m.p95_us, 5_000); + assert_eq!(m.p99_us, 5_000); + } + + // ── Empty bucket summary ───────────────────────────────────── + + #[test] + fn empty_bucket_summary() { + let bucket = Bucket::new(); + let m = bucket.snapshot("empty"); + assert_eq!(m.count, 0); + assert_eq!(m.sum_us, 0); + assert_eq!(m.min_us, 0); + assert_eq!(m.max_us, 0); + assert_eq!(m.p50_us, 0); + assert_eq!(m.p95_us, 0); + assert_eq!(m.p99_us, 0); + } + + // ── 100 records → percentile ordering ──────────────────────── + + #[test] + fn hundred_records_percentile_ordering() { + let bucket = Bucket::new(); + // Record values 1..=100 so percentiles are deterministic. + for v in 1..=100u64 { + bucket.record(v); + } + let m = bucket.snapshot("hundred"); + assert_eq!(m.count, 100); + assert_eq!(m.min_us, 1); + assert_eq!(m.max_us, 100); + assert_eq!(m.sum_us, 5050); // sum of 1..=100 + + // Nearest-rank percentiles for 1..=100: + // p50: ceil(50/100 * 100) = 50 → 0-indexed 49 → value 50 + // p95: ceil(95/100 * 100) = 95 → 0-indexed 94 → value 95 + // p99: ceil(99/100 * 100) = 99 → 0-indexed 98 → value 99 + assert_eq!(m.p50_us, 50); + assert_eq!(m.p95_us, 95); + assert_eq!(m.p99_us, 99); + + // Ordering invariant: min ≤ p50 ≤ p95 ≤ p99 ≤ max + assert!(m.min_us <= m.p50_us); + assert!(m.p50_us <= m.p95_us); + assert!(m.p95_us <= m.p99_us); + assert!(m.p99_us <= m.max_us); + } + + #[test] + fn percentile_ordering_with_skewed_values() { + let bucket = Bucket::new(); + // 98 values of 10, 1 value of 5000, 1 value of 10000 + for _ in 0..98 { + bucket.record(10); + } + bucket.record(5_000); + bucket.record(10_000); + + let m = bucket.snapshot("skewed"); + assert_eq!(m.count, 100); + // p50 should be 10 (98% of values are 10) + assert_eq!(m.p50_us, 10); + // p95 should be 5000 (95th value in sorted order) + assert!(m.p95_us >= 10); + assert!(m.p95_us <= m.p99_us); + } + + // ── Concurrent records ─────────────────────────────────────── + + #[test] + fn concurrent_records_same_bucket() { + let bucket = Arc::new(Bucket::new()); + let num_threads = 8; + let per_thread = 500u64; + + let handles: Vec<_> = (0..num_threads) + .map(|_| { + let b = Arc::clone(&bucket); + thread::spawn(move || { + for i in 0..per_thread { + b.record(1_000 + i); + } + }) + }) + .collect(); + + for h in handles { + h.join().expect("thread panicked"); + } + + let m = bucket.snapshot("concurrent"); + assert_eq!(m.count, num_threads as u64 * per_thread); + assert!(m.min_us >= 1_000); + assert!(m.max_us <= 1_000 + per_thread - 1); + // Ordering must hold even under concurrency. + assert!(m.min_us <= m.p50_us); + assert!(m.p50_us <= m.p95_us); + assert!(m.p95_us <= m.p99_us); + assert!(m.p99_us <= m.max_us); + } + + // ── Ring buffer ────────────────────────────────────────────── + + #[test] + fn ring_buffer_caps_at_ring_size() { + let bucket = Bucket::new(); + for i in 0..(RING_SIZE + 100) as u64 { + bucket.record(i); + } + let recent = bucket.recent(); + assert_eq!(recent.len(), RING_SIZE); + // Most recent value should be the last recorded. + assert_eq!(recent[0], (RING_SIZE + 100 - 1) as u64); + } + + // ── Percentile index helper ────────────────────────────────── + + #[test] + fn percentile_index_basic() { + assert_eq!(percentile_index(50, 100), 49); + assert_eq!(percentile_index(95, 100), 94); + assert_eq!(percentile_index(99, 100), 98); + } + + #[test] + fn percentile_index_small_n() { + assert_eq!(percentile_index(50, 1), 0); + assert_eq!(percentile_index(95, 1), 0); + // n=2: p50 = ceil(0.50 * 2) = 1 (1-indexed) → 0-indexed 0 + assert_eq!(percentile_index(50, 2), 0); + // n=2: p95 = ceil(0.95 * 2) = 2 (1-indexed) → 0-indexed 1 + assert_eq!(percentile_index(95, 2), 1); + assert_eq!(percentile_index(95, 10), 9); + } + + #[test] + fn percentile_index_zero_n() { + assert_eq!(percentile_index(50, 0), 0); + assert_eq!(percentile_index(99, 0), 0); + } + + // ── JSON format stability (golden snapshot) ────────────────── + + #[test] + fn json_format_empty_metrics() { + let metrics = vec![ + LatencyMetric { + bucket: "claim-spawn", + count: 0, + sum_us: 0, + min_us: 0, + max_us: 0, + p50_us: 0, + p95_us: 0, + p99_us: 0, + }, + LatencyMetric { + bucket: "firmware-ready", + count: 0, + sum_us: 0, + min_us: 0, + max_us: 0, + p50_us: 0, + p95_us: 0, + p99_us: 0, + }, + ]; + let json = format_metrics_json(&metrics); + assert!(json.starts_with(r#"{"version":1,"buckets":{"#)); + assert!(json.ends_with("}}")); + assert!(json.contains(r#""claim-spawn":{"count":0"#)); + assert!(json.contains(r#""firmware-ready":{"count":0"#)); + } + + #[test] + fn json_format_populated_metrics() { + let metrics = vec![LatencyMetric { + bucket: "aer-event", + count: 5, + sum_us: 12_000, + min_us: 612, + max_us: 4_523, + p50_us: 2_100, + p95_us: 4_523, + p99_us: 4_523, + }]; + let json = format_metrics_json(&metrics); + let expected = r#"{"version":1,"buckets":{"aer-event":{"count":5,"min_us":612,"max_us":4523,"p50_us":2100,"p95_us":4523,"p99_us":4523,"sum_us":12000}}}"#; + assert_eq!(json, expected); + } + + #[test] + fn json_format_all_four_buckets() { + // Build a snapshot of all four canonical buckets with realistic data. + let metrics: Vec = BUCKET_NAMES + .iter() + .map(|&name| LatencyMetric { + bucket: name, + count: 0, + sum_us: 0, + min_us: 0, + max_us: 0, + p50_us: 0, + p95_us: 0, + p99_us: 0, + }) + .collect(); + let json = format_metrics_json(&metrics); + // All four bucket names must appear in canonical order. + let cs = json.find(r#""claim-spawn""#).unwrap(); + let fr = json.find(r#""firmware-ready""#).unwrap(); + let gs = json.find(r#""governor-switch""#).unwrap(); + let ae = json.find(r#""aer-event""#).unwrap(); + assert!(cs < fr); + assert!(fr < gs); + assert!(gs < ae); + } + + // ── Global record/summary/format_json ──────────────────────── + + #[test] + fn global_record_and_format_json_produces_valid_structure() { + // Record into a global bucket. We can't reset globals between + // tests, so we only check structural validity, not exact counts. + record("claim-spawn", 42_000); + record("claim-spawn", 99_000); + + let json = format_json(); + assert!(json.starts_with(r#"{"version":1,"buckets":{"#)); + assert!(json.contains(r#""claim-spawn""#)); + assert!(json.contains(r#""firmware-ready""#)); + assert!(json.contains(r#""governor-switch""#)); + assert!(json.contains(r#""aer-event""#)); + assert!(json.ends_with("}}")); + } + + #[test] + fn global_record_unknown_bucket_ignored() { + // Should not panic. + record("nonexistent-bucket", 1_000); + } + + // ── Firmware-defer tracking ────────────────────────────────── + + #[test] + fn firmware_defer_records_on_first_defer_only() { + // Use a unique device key per test invocation to avoid interference + // with other tests that might touch the global map. + let key = format!( + "fw-defer-test-{}-{}", + std::process::id(), + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_nanos() + ); + + // Before recording, no deferred device. + assert!(!record_firmware_ready_if_deferred(&key)); + + // Record defer start. + record_firmware_defer_start(&key); + // Recording again should not overwrite the original timestamp. + std::thread::sleep(std::time::Duration::from_micros(100)); + record_firmware_defer_start(&key); + + // Now resolving should return true and record a measurement. + assert!(record_firmware_ready_if_deferred(&key)); + + // Second resolution should return false (already consumed). + assert!(!record_firmware_ready_if_deferred(&key)); + } + + // ── AER timestamp parsing ──────────────────────────────────── + + #[test] + fn parse_ts_field_extracts_value() { + // This is the post-seq-stripped form that event.raw contains + // (parse_seq_prefix strips "seq=N:" before AerEvent::parse sees it). + let raw = "ts=2026-07-25T12:34:56:severity=NonFatal device=0000:00:1f.2"; + assert_eq!( + parse_ts_field(raw).unwrap(), + "2026-07-25T12:34:56" + ); + } + + #[test] + fn parse_ts_field_returns_none_when_absent() { + assert!(parse_ts_field("seq=42:severity=NonFatal device=d").is_none()); + assert!(parse_ts_field("").is_none()); + } + + #[test] + fn parse_rfc3339_known_epoch() { + // 1970-01-01T00:00:00 = epoch 0 + assert_eq!(parse_rfc3339_to_epoch_micros("1970-01-01T00:00:00"), Some(0)); + // 1970-01-01T00:00:01 = 1 second = 1_000_000 micros + assert_eq!( + parse_rfc3339_to_epoch_micros("1970-01-01T00:00:01"), + Some(1_000_000) + ); + // 1970-01-02T00:00:00 = 1 day = 86_400 seconds + assert_eq!( + parse_rfc3339_to_epoch_micros("1970-01-02T00:00:00"), + Some(86_400 * 1_000_000) + ); + // 2026-07-25T12:00:00 — verify it's a plausible large number + let v = parse_rfc3339_to_epoch_micros("2026-07-25T12:00:00").unwrap(); + // 2026 is ~56 years after 1970 → ~56 * 365.25 * 86400 seconds + let approx_seconds = v / 1_000_000; + assert!(approx_seconds > 56 * 365 * 86_400); + assert!(approx_seconds < 57 * 366 * 86_400); + } + + #[test] + fn parse_rfc3339_with_fractional_seconds() { + let whole = parse_rfc3339_to_epoch_micros("1970-01-01T00:00:01").unwrap(); + let frac = parse_rfc3339_to_epoch_micros("1970-01-01T00:00:01.500000").unwrap(); + assert_eq!(frac - whole, 500_000); // 0.5 second = 500_000 micros + } + + #[test] + fn parse_rfc3339_with_trailing_z() { + assert_eq!( + parse_rfc3339_to_epoch_micros("1970-01-01T00:00:00Z"), + Some(0) + ); + } + + #[test] + fn parse_rfc3339_rejects_malformed() { + assert!(parse_rfc3339_to_epoch_micros("").is_none()); + assert!(parse_rfc3339_to_epoch_micros("not-a-date").is_none()); + assert!(parse_rfc3339_to_epoch_micros("2026/07/25 12:00:00").is_none()); + assert!(parse_rfc3339_to_epoch_micros("2026-13-01T00:00:00").is_none()); // month 13 + assert!(parse_rfc3339_to_epoch_micros("2026-00-01T00:00:00").is_none()); // month 0 + } + + #[test] + fn parse_aer_latency_returns_none_without_ts() { + assert!(parse_aer_latency_us("seq=42:severity=NonFatal device=d").is_none()); + } + + #[test] + fn civil_to_days_known_values() { + // 1970-01-01 = 0 days since epoch + assert_eq!(civil_to_days(1970, 1, 1), Some(0)); + // 1970-01-02 = 1 day + assert_eq!(civil_to_days(1970, 1, 2), Some(1)); + // 1969-12-31 = -1 day + assert_eq!(civil_to_days(1969, 12, 31), Some(-1)); + // 2024-01-01 = 19723 days (known value) + assert_eq!(civil_to_days(2024, 1, 1), Some(19_723)); + // 2024-03-01 = 19783 (leap year Jan has 31 days) + assert_eq!(civil_to_days(2024, 3, 1), Some(19_783)); + } + + #[test] + fn civil_to_days_rejects_invalid() { + assert!(civil_to_days(2026, 0, 1).is_none()); + assert!(civil_to_days(2026, 13, 1).is_none()); + assert!(civil_to_days(2026, 7, 0).is_none()); + assert!(civil_to_days(2026, 7, 32).is_none()); + } +} diff --git a/local/recipes/system/driver-manager/source/src/unified_events.rs b/local/recipes/system/driver-manager/source/src/unified_events.rs index c0336527d1..cdaa35a3e2 100644 --- a/local/recipes/system/driver-manager/source/src/unified_events.rs +++ b/local/recipes/system/driver-manager/source/src/unified_events.rs @@ -101,13 +101,25 @@ fn run( let binds = bind_snapshot(); for event in events { let action = crate::aer::route_to_driver(&event, &binds, &consult_driver); - log::info!( - "AER: event device={} severity={:?} action={:?} raw={}", - event.device, - event.severity, - action, - event.raw, - ); + if let Some(latency_us) = crate::timing::parse_aer_latency_us(&event.raw) { + crate::timing::record("aer-event", latency_us); + log::info!( + "AER: event device={} severity={:?} action={:?} latency={}us raw={}", + event.device, + event.severity, + action, + latency_us, + event.raw, + ); + } else { + log::info!( + "AER: event device={} severity={:?} action={:?} raw={}", + event.device, + event.severity, + action, + event.raw, + ); + } handle_event(&UnifiedEvent::Aer { event, action }); } }