//! End-to-End Latency Measurement Framework for HFT Order Processing //! //! This test suite measures complete order processing latency with RDTSC timing: //! - Order submission → validation → risk checks → execution → confirmation //! - P50, P95, P99 latency distributions //! - Per-stage breakdowns and bottleneck identification //! - Comparison against HFT targets (<50μs total, <10μs ML, <5μs metrics) //! //! **Wave 68 Agent 10**: Production latency measurement and optimization validation use std::time::Duration; use trading_engine::timing::{calibrate_tsc, HardwareTimestamp}; /// E2E latency measurement point in the order processing pipeline #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum LatencyCheckpoint { OrderSubmission, // Entry point ValidationStart, // Pre-validation start ValidationComplete, // All validations passed RiskCheckStart, // Risk manager invocation RiskCheckComplete, // Risk approval received ExecutionStart, // Order routing begins BrokerSent, // Order sent to exchange ExchangeResponse, // Exchange acknowledgment ConfirmationSent, // Final confirmation to client } /// Comprehensive E2E latency measurement #[derive(Debug, Clone)] pub struct E2ELatencyTrace { /// Order ID for correlation pub order_id: String, /// Checkpoints with RDTSC timestamps pub checkpoints: Vec<(LatencyCheckpoint, HardwareTimestamp)>, /// Total E2E latency (nanoseconds) pub total_latency_ns: u64, /// Per-stage breakdowns pub validation_latency_ns: u64, pub risk_check_latency_ns: u64, pub execution_latency_ns: u64, pub exchange_latency_ns: u64, pub confirmation_latency_ns: u64, /// Additional overhead measurements pub ml_inference_latency_ns: Option, pub metrics_collection_overhead_ns: u64, } impl E2ELatencyTrace { /// Create new latency trace for an order pub fn new(order_id: String) -> Self { Self { order_id, checkpoints: Vec::with_capacity(10), total_latency_ns: 0, validation_latency_ns: 0, risk_check_latency_ns: 0, execution_latency_ns: 0, exchange_latency_ns: 0, confirmation_latency_ns: 0, ml_inference_latency_ns: None, metrics_collection_overhead_ns: 0, } } /// Record a checkpoint with RDTSC timing pub fn record_checkpoint(&mut self, checkpoint: LatencyCheckpoint) { let timestamp = HardwareTimestamp::now(); self.checkpoints.push((checkpoint, timestamp)); } /// Calculate all stage latencies from checkpoints pub fn calculate_latencies(&mut self) -> Result<(), &'static str> { if self.checkpoints.len() < 2 { return Err("Insufficient checkpoints for latency calculation"); } // Find checkpoint positions let find_checkpoint = |cp: LatencyCheckpoint| -> Option { self.checkpoints.iter().position(|(c, _)| *c == cp) }; // Calculate validation latency if let (Some(val_start), Some(val_end)) = ( find_checkpoint(LatencyCheckpoint::ValidationStart), find_checkpoint(LatencyCheckpoint::ValidationComplete), ) { self.validation_latency_ns = self.checkpoints[val_end] .1 .latency_ns(&self.checkpoints[val_start].1); } // Calculate risk check latency if let (Some(risk_start), Some(risk_end)) = ( find_checkpoint(LatencyCheckpoint::RiskCheckStart), find_checkpoint(LatencyCheckpoint::RiskCheckComplete), ) { self.risk_check_latency_ns = self.checkpoints[risk_end] .1 .latency_ns(&self.checkpoints[risk_start].1); } // Calculate execution latency if let (Some(exec_start), Some(broker_sent)) = ( find_checkpoint(LatencyCheckpoint::ExecutionStart), find_checkpoint(LatencyCheckpoint::BrokerSent), ) { self.execution_latency_ns = self.checkpoints[broker_sent] .1 .latency_ns(&self.checkpoints[exec_start].1); } // Calculate exchange response latency if let (Some(broker_sent), Some(exchange_resp)) = ( find_checkpoint(LatencyCheckpoint::BrokerSent), find_checkpoint(LatencyCheckpoint::ExchangeResponse), ) { self.exchange_latency_ns = self.checkpoints[exchange_resp] .1 .latency_ns(&self.checkpoints[broker_sent].1); } // Calculate confirmation latency if let (Some(exchange_resp), Some(confirmation)) = ( find_checkpoint(LatencyCheckpoint::ExchangeResponse), find_checkpoint(LatencyCheckpoint::ConfirmationSent), ) { self.confirmation_latency_ns = self.checkpoints[confirmation] .1 .latency_ns(&self.checkpoints[exchange_resp].1); } // Calculate total E2E latency if let (Some(first), Some(last)) = (self.checkpoints.first(), self.checkpoints.last()) { self.total_latency_ns = last.1.latency_ns(&first.1); } Ok(()) } /// Get validation latency in microseconds pub fn validation_us(&self) -> f64 { self.validation_latency_ns as f64 / 1000.0 } /// Get risk check latency in microseconds pub fn risk_check_us(&self) -> f64 { self.risk_check_latency_ns as f64 / 1000.0 } /// Get execution latency in microseconds pub fn execution_us(&self) -> f64 { self.execution_latency_ns as f64 / 1000.0 } /// Get exchange latency in microseconds pub fn exchange_us(&self) -> f64 { self.exchange_latency_ns as f64 / 1000.0 } /// Get total E2E latency in microseconds pub fn total_us(&self) -> f64 { self.total_latency_ns as f64 / 1000.0 } /// Check if latency meets HFT targets pub fn meets_hft_targets(&self) -> LatencyTargetResult { LatencyTargetResult { total_target_met: self.total_latency_ns < 50_000, // <50μs validation_target_met: self.validation_latency_ns < 5_000, // <5μs risk_check_target_met: self.risk_check_latency_ns < 15_000, // <15μs execution_target_met: self.execution_latency_ns < 10_000, // <10μs ml_inference_target_met: self .ml_inference_latency_ns .map(|lat| lat < 10_000) .unwrap_or(true), // <10μs if present metrics_overhead_target_met: self.metrics_collection_overhead_ns < 5_000, // <5μs } } } /// Result of comparing against HFT latency targets #[derive(Debug, Clone)] pub struct LatencyTargetResult { pub total_target_met: bool, pub validation_target_met: bool, pub risk_check_target_met: bool, pub execution_target_met: bool, pub ml_inference_target_met: bool, pub metrics_overhead_target_met: bool, } impl LatencyTargetResult { /// Check if all targets are met pub fn all_targets_met(&self) -> bool { self.total_target_met && self.validation_target_met && self.risk_check_target_met && self.execution_target_met && self.ml_inference_target_met && self.metrics_overhead_target_met } } /// Latency distribution statistics #[derive(Debug, Clone)] pub struct LatencyDistribution { pub samples: Vec, pub p50_ns: u64, pub p95_ns: u64, pub p99_ns: u64, pub min_ns: u64, pub max_ns: u64, pub mean_ns: f64, pub stddev_ns: f64, } impl LatencyDistribution { /// Calculate distribution from latency samples pub fn from_samples(mut samples: Vec) -> Self { if samples.is_empty() { return Self::empty(); } samples.sort_unstable(); let p50_ns = Self::percentile(&samples, 0.50); let p95_ns = Self::percentile(&samples, 0.95); let p99_ns = Self::percentile(&samples, 0.99); let min_ns = *samples.first().unwrap(); let max_ns = *samples.last().unwrap(); let mean_ns = samples.iter().sum::() as f64 / samples.len() as f64; let variance = samples .iter() .map(|&x| { let diff = x as f64 - mean_ns; diff * diff }) .sum::() / samples.len() as f64; let stddev_ns = variance.sqrt(); Self { samples, p50_ns, p95_ns, p99_ns, min_ns, max_ns, mean_ns, stddev_ns, } } fn percentile(sorted_samples: &[u64], percentile: f64) -> u64 { let index = ((sorted_samples.len() as f64 - 1.0) * percentile) as usize; sorted_samples[index] } fn empty() -> Self { Self { samples: Vec::new(), p50_ns: 0, p95_ns: 0, p99_ns: 0, min_ns: 0, max_ns: 0, mean_ns: 0.0, stddev_ns: 0.0, } } /// Get P50 in microseconds pub fn p50_us(&self) -> f64 { self.p50_ns as f64 / 1000.0 } /// Get P95 in microseconds pub fn p95_us(&self) -> f64 { self.p95_ns as f64 / 1000.0 } /// Get P99 in microseconds pub fn p99_us(&self) -> f64 { self.p99_ns as f64 / 1000.0 } } /// Complete E2E latency analysis results #[derive(Debug, Clone)] pub struct E2ELatencyAnalysis { pub total_orders: usize, pub total_latency_dist: LatencyDistribution, pub validation_latency_dist: LatencyDistribution, pub risk_check_latency_dist: LatencyDistribution, pub execution_latency_dist: LatencyDistribution, pub exchange_latency_dist: LatencyDistribution, pub ml_inference_latency_dist: Option, pub metrics_overhead_dist: LatencyDistribution, /// Percentage of orders meeting each target pub total_target_pass_rate: f64, pub validation_target_pass_rate: f64, pub risk_check_target_pass_rate: f64, pub execution_target_pass_rate: f64, /// Bottleneck identification pub primary_bottleneck: String, pub bottleneck_contribution_pct: f64, } impl E2ELatencyAnalysis { /// Analyze collection of latency traces pub fn analyze(traces: &[E2ELatencyTrace]) -> Self { if traces.is_empty() { return Self::empty(); } // Extract latency samples let total_samples: Vec = traces.iter().map(|t| t.total_latency_ns).collect(); let validation_samples: Vec = traces.iter().map(|t| t.validation_latency_ns).collect(); let risk_check_samples: Vec = traces.iter().map(|t| t.risk_check_latency_ns).collect(); let execution_samples: Vec = traces.iter().map(|t| t.execution_latency_ns).collect(); let exchange_samples: Vec = traces.iter().map(|t| t.exchange_latency_ns).collect(); let metrics_samples: Vec = traces .iter() .map(|t| t.metrics_collection_overhead_ns) .collect(); // Calculate distributions let total_latency_dist = LatencyDistribution::from_samples(total_samples); let validation_latency_dist = LatencyDistribution::from_samples(validation_samples); let risk_check_latency_dist = LatencyDistribution::from_samples(risk_check_samples); let execution_latency_dist = LatencyDistribution::from_samples(execution_samples); let exchange_latency_dist = LatencyDistribution::from_samples(exchange_samples); let metrics_overhead_dist = LatencyDistribution::from_samples(metrics_samples); // ML inference distribution (if present) let ml_samples: Vec = traces .iter() .filter_map(|t| t.ml_inference_latency_ns) .collect(); let ml_inference_latency_dist = if !ml_samples.is_empty() { Some(LatencyDistribution::from_samples(ml_samples)) } else { None }; // Calculate target pass rates let total_target_pass_rate = traces .iter() .filter(|t| t.meets_hft_targets().total_target_met) .count() as f64 / traces.len() as f64 * 100.0; let validation_target_pass_rate = traces .iter() .filter(|t| t.meets_hft_targets().validation_target_met) .count() as f64 / traces.len() as f64 * 100.0; let risk_check_target_pass_rate = traces .iter() .filter(|t| t.meets_hft_targets().risk_check_target_met) .count() as f64 / traces.len() as f64 * 100.0; let execution_target_pass_rate = traces .iter() .filter(|t| t.meets_hft_targets().execution_target_met) .count() as f64 / traces.len() as f64 * 100.0; // Identify primary bottleneck let avg_validation = validation_latency_dist.mean_ns; let avg_risk_check = risk_check_latency_dist.mean_ns; let avg_execution = execution_latency_dist.mean_ns; let avg_exchange = exchange_latency_dist.mean_ns; let (primary_bottleneck, max_latency) = [ ("Validation", avg_validation), ("Risk Check", avg_risk_check), ("Execution", avg_execution), ("Exchange", avg_exchange), ] .iter() .max_by(|a, b| a.1.partial_cmp(&b.1).unwrap()) .map(|(name, lat)| (name.to_string(), *lat)) .unwrap(); let total_avg = total_latency_dist.mean_ns; let bottleneck_contribution_pct = if total_avg > 0.0 { (max_latency / total_avg) * 100.0 } else { 0.0 }; Self { total_orders: traces.len(), total_latency_dist, validation_latency_dist, risk_check_latency_dist, execution_latency_dist, exchange_latency_dist, ml_inference_latency_dist, metrics_overhead_dist, total_target_pass_rate, validation_target_pass_rate, risk_check_target_pass_rate, execution_target_pass_rate, primary_bottleneck, bottleneck_contribution_pct, } } fn empty() -> Self { Self { total_orders: 0, total_latency_dist: LatencyDistribution::empty(), validation_latency_dist: LatencyDistribution::empty(), risk_check_latency_dist: LatencyDistribution::empty(), execution_latency_dist: LatencyDistribution::empty(), exchange_latency_dist: LatencyDistribution::empty(), ml_inference_latency_dist: None, metrics_overhead_dist: LatencyDistribution::empty(), total_target_pass_rate: 0.0, validation_target_pass_rate: 0.0, risk_check_target_pass_rate: 0.0, execution_target_pass_rate: 0.0, primary_bottleneck: "Unknown".to_string(), bottleneck_contribution_pct: 0.0, } } /// Generate detailed analysis report pub fn generate_report(&self) -> String { format!( r#" ═══════════════════════════════════════════════════════════════════ E2E LATENCY MEASUREMENT REPORT Wave 68 Agent 10 ═══════════════════════════════════════════════════════════════════ EXECUTIVE SUMMARY ───────────────────────────────────────────────────────────────── Total Orders Measured: {} HFT Target (<50μs): {:.1}% pass rate OVERALL LATENCY DISTRIBUTION ───────────────────────────────────────────────────────────────── P50: {:.2} μs P95: {:.2} μs P99: {:.2} μs Mean: {:.2} μs ± {:.2} μs Min: {:.2} μs Max: {:.2} μs PER-STAGE BREAKDOWN (P95 Latencies) ───────────────────────────────────────────────────────────────── Validation: {:.2} μs ({:.1}% pass rate) Risk Check: {:.2} μs ({:.1}% pass rate) Execution: {:.2} μs ({:.1}% pass rate) Exchange: {:.2} μs {} Metrics: {:.2} μs BOTTLENECK ANALYSIS ───────────────────────────────────────────────────────────────── Primary Bottleneck: {} Contribution: {:.1}% of total latency HFT TARGET COMPLIANCE ───────────────────────────────────────────────────────────────── Total Latency (<50μs): {:.1}% Validation (<5μs): {:.1}% Risk Check (<15μs): {:.1}% Execution (<10μs): {:.1}% RECOMMENDATIONS ───────────────────────────────────────────────────────────────── {} ═══════════════════════════════════════════════════════════════════ "#, self.total_orders, self.total_target_pass_rate, self.total_latency_dist.p50_us(), self.total_latency_dist.p95_us(), self.total_latency_dist.p99_us(), self.total_latency_dist.mean_ns / 1000.0, self.total_latency_dist.stddev_ns / 1000.0, self.total_latency_dist.min_ns as f64 / 1000.0, self.total_latency_dist.max_ns as f64 / 1000.0, self.validation_latency_dist.p95_us(), self.validation_target_pass_rate, self.risk_check_latency_dist.p95_us(), self.risk_check_target_pass_rate, self.execution_latency_dist.p95_us(), self.execution_target_pass_rate, self.exchange_latency_dist.p95_us(), self.ml_inference_latency_dist .as_ref() .map(|dist| format!("ML Inference: {:.2} μs\n", dist.p95_us())) .unwrap_or_default(), self.metrics_overhead_dist.p95_us(), self.primary_bottleneck, self.bottleneck_contribution_pct, self.total_target_pass_rate, self.validation_target_pass_rate, self.risk_check_target_pass_rate, self.execution_target_pass_rate, self.generate_recommendations() ) } fn generate_recommendations(&self) -> String { let mut recommendations = Vec::new(); if self.total_target_pass_rate < 95.0 { recommendations.push("⚠ Overall latency target not met - requires optimization"); } if self.primary_bottleneck == "Validation" { recommendations.push("→ Optimize validation logic - consider parallel checks"); } else if self.primary_bottleneck == "Risk Check" { recommendations .push("→ Optimize risk calculations - consider caching or approximation"); } else if self.primary_bottleneck == "Execution" { recommendations.push("→ Optimize order routing - reduce broker communication overhead"); } else if self.primary_bottleneck == "Exchange" { recommendations .push("→ Exchange latency dominant - consider co-location or venue change"); } if self.metrics_overhead_dist.p95_ns > 5_000 { recommendations.push("→ Reduce metrics collection overhead"); } if let Some(ref ml_dist) = self.ml_inference_latency_dist { if ml_dist.p95_ns > 10_000 { recommendations.push("→ ML inference exceeds target - consider model optimization"); } } if recommendations.is_empty() { "✓ All HFT targets met - system performing within specifications".to_string() } else { recommendations.join("\n") } } } #[cfg(test)] mod tests { use super::*; #[test] fn test_latency_trace_creation() { let mut trace = E2ELatencyTrace::new("order-001".to_string()); trace.record_checkpoint(LatencyCheckpoint::OrderSubmission); std::thread::sleep(Duration::from_micros(10)); trace.record_checkpoint(LatencyCheckpoint::ValidationStart); std::thread::sleep(Duration::from_micros(5)); trace.record_checkpoint(LatencyCheckpoint::ValidationComplete); std::thread::sleep(Duration::from_micros(15)); trace.record_checkpoint(LatencyCheckpoint::RiskCheckStart); std::thread::sleep(Duration::from_micros(10)); trace.record_checkpoint(LatencyCheckpoint::RiskCheckComplete); assert!(trace.calculate_latencies().is_ok()); assert!(trace.validation_latency_ns > 0); assert!(trace.risk_check_latency_ns > 0); assert!(trace.total_latency_ns > 0); } #[test] fn test_latency_distribution() { let samples = vec![ 1000, 2000, 3000, 4000, 5000, 10000, 15000, 20000, 50000, 100000, ]; let dist = LatencyDistribution::from_samples(samples); assert!(dist.p50_ns > 0); assert!(dist.p95_ns > dist.p50_ns); assert!(dist.p99_ns >= dist.p95_ns); assert_eq!(dist.min_ns, 1000); assert_eq!(dist.max_ns, 100000); } #[test] fn test_hft_target_validation() { let mut trace = E2ELatencyTrace::new("order-001".to_string()); trace.total_latency_ns = 40_000; // 40μs - meets target trace.validation_latency_ns = 3_000; // 3μs - meets target trace.risk_check_latency_ns = 12_000; // 12μs - meets target trace.execution_latency_ns = 8_000; // 8μs - meets target trace.metrics_collection_overhead_ns = 4_000; // 4μs - meets target let result = trace.meets_hft_targets(); assert!(result.total_target_met); assert!(result.validation_target_met); assert!(result.risk_check_target_met); assert!(result.execution_target_met); assert!(result.metrics_overhead_target_met); assert!(result.all_targets_met()); } #[test] fn test_e2e_analysis() { // Calibrate TSC first let _ = calibrate_tsc(); let mut traces = Vec::new(); for i in 0..100 { let mut trace = E2ELatencyTrace::new(format!("order-{:03}", i)); trace.total_latency_ns = 30_000 + (i * 100); // Simulated latencies trace.validation_latency_ns = 2_000 + (i * 10); trace.risk_check_latency_ns = 10_000 + (i * 30); trace.execution_latency_ns = 8_000 + (i * 20); trace.exchange_latency_ns = 5_000 + (i * 15); trace.metrics_collection_overhead_ns = 3_000 + (i * 5); traces.push(trace); } let analysis = E2ELatencyAnalysis::analyze(&traces); assert_eq!(analysis.total_orders, 100); assert!(analysis.total_latency_dist.p50_ns > 0); assert!(analysis.total_latency_dist.p95_ns > analysis.total_latency_dist.p50_ns); assert!(!analysis.primary_bottleneck.is_empty()); assert!(analysis.bottleneck_contribution_pct > 0.0); // Print report for visual inspection println!("{}", analysis.generate_report()); } }