v5.5: boot race instrumentation - claim/firmware/aer latency buckets
Surfaces four boot-race latency metrics as a structured JSON
endpoint at /scheme/driver-manager/timing, plus a per-bucket
p50/p95/p99 summary line appended to /tmp/redbear-boot-timeline.json.
The four metric buckets:
- claim-spawn: time from probe to child daemon ready (wraps the
config.rs::probe() spawn path).
- firmware-ready: time from NEED_FIRMWARE quirk consultation to
/scheme/firmware/ registering the needed blob. Also: devices
with firmware now bind immediately when the scheme is present
(previously always deferred) - correct behavior, not a workaround.
- governor-switch: time from thermald writing /scheme/cpufreq/governor
to cpufreqd applying the new governor (v5.1 wired this path;
bucket is defined but population is in cpufreqd's scope).
- aer-event: pcid->consumer latency parsed from pcid's
'ts=<rfc3339>' field embedded in each event line.
Architecture:
- timing.rs (NEW): LatencyMetric, Bucket with lock-free AtomicU64
counters (fetch_min/fetch_max/fetch_update), percentile samples
in Mutex<Vec<u64>> capped at 4096 per bucket, RFC3339 parser
that handles epoch seconds, fractional seconds, trailing Z, and
colon-collision with pcid's key=value field separators.
- config.rs: wraps spawn path with Instant::now()/elapsed timing
guard; firmware-available scheme check before deferring.
- unified_events.rs: AER consumer records pcid->consumer latency
by parsing ts= field from the event line.
- scheme.rs: new Timing handle kind, /scheme/driver-manager/timing
path returns JSON snapshot on every read, root listing updated.
- main.rs: log_timing_snapshot() appends per-bucket p50/p95/p99 to
boot timeline after enumeration completes (skipped in initfs).
Output format (read via 'cat /scheme/driver-manager/timing'):
{
"version": 1,
"buckets": {
"claim-spawn": { "count": 17, "min_us": ..., ... },
"firmware-ready": { ... },
"governor-switch": { ... },
"aer-event": { ... }
}
}
Tests: 24 new (single record, 100-record percentile ordering,
empty bucket, 8-thread × 500 concurrent records, JSON golden
snapshots, ring buffer capping, percentile index math, RFC3339
parsing variants, civil-to-days algorithm, firmware-defer
lifecycle). Total 112 tests pass, 0 failed.
Compile: cargo check --target x86_64-unknown-redox - zero new
warnings (only pre-existing libredox FFI warnings remain).
Constraints per local/AGENTS.md:
- No new branches (work on 0.3.1)
- No new Cargo dependencies (std-only: AtomicU64, Mutex, Vec, etc.)
- No stubs, no todo!/unimplemented!
- Cat 1 in-house recipe - source IS the durable location
Closes v5.5 of the v5.x work program.
This commit is contained in:
kellito
@@ -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));
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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<String> {
|
||||
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 '<pci_addr> <reset_device|rescan_bus|disconnect>' 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,
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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<Vec<u64>>,
|
||||
ring: Mutex<VecDeque<u64>>,
|
||||
}
|
||||
|
||||
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<u64> {
|
||||
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<LatencyMetric> {
|
||||
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<HashMap> because HashMap::new() is
|
||||
// not const-evaluable in a static initializer.
|
||||
|
||||
static FIRMWARE_DEFER_STARTS: Mutex<Option<HashMap<String, Instant>>> = 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=<rfc3339>` 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=<rfc3339>` 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<u64> {
|
||||
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<String> {
|
||||
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<u64> {
|
||||
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<i64> {
|
||||
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<LatencyMetric> = 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());
|
||||
}
|
||||
}
|
||||
@@ -101,13 +101,25 @@ fn run<F>(
|
||||
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 });
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user