|
| 1 | +// SPDX-License-Identifier: GPL-3.0-or-later |
| 2 | +// SPDX-FileCopyrightText: 2026 Mohamed Hammad |
| 3 | + |
| 4 | +//! `zamak bench parse-serial` — host-side consumer for the |
| 5 | +//! TSC-based boot-phase instrumentation `zamak-uefi` emits to |
| 6 | +//! COM1 (M6-3 part 1). |
| 7 | +//! |
| 8 | +//! Reads a UEFI serial log (file path or stdin) and emits an |
| 9 | +//! SFRS-canonical JSON envelope whose `data` payload is: |
| 10 | +//! |
| 11 | +//! ```json |
| 12 | +//! { |
| 13 | +//! "tsc_mhz": 2400, |
| 14 | +//! "phases": [ |
| 15 | +//! {"phase": "uefi_entry", "tsc": 1000000, "delta_cycles": 0}, |
| 16 | +//! {"phase": "config_parsed", "tsc": 1100000, "delta_cycles": 100000, |
| 17 | +//! "delta_ns": 41666.67}, |
| 18 | +//! ... |
| 19 | +//! ] |
| 20 | +//! } |
| 21 | +//! ``` |
| 22 | +//! |
| 23 | +//! `delta_ns` is emitted only when a TSC frequency is known — |
| 24 | +//! either the log contained a `ZAMAK_TSC_MHZ=<n>` line or the |
| 25 | +//! caller passed `--tsc-mhz <n>` on the CLI (explicit wins over |
| 26 | +//! log-reported). |
| 27 | +
|
| 28 | +// Rust guideline compliant 2026-03-30 |
| 29 | + |
| 30 | +use std::fs; |
| 31 | +use std::io::{self, Read as _}; |
| 32 | + |
| 33 | +use crate::error::CliError; |
| 34 | +use crate::json::{obj, Value}; |
| 35 | + |
| 36 | +/// Entry point wired into `main.rs`' sub-command match. |
| 37 | +pub fn run(args: &[String]) -> Result<Value, CliError> { |
| 38 | + let sub = args |
| 39 | + .first() |
| 40 | + .ok_or_else(|| CliError::usage("bench: missing sub-verb (expected 'parse-serial')"))?; |
| 41 | + match sub.as_str() { |
| 42 | + "parse-serial" => run_parse_serial(&args[1..]), |
| 43 | + other => Err(CliError::usage(format!( |
| 44 | + "bench: unknown sub-verb '{other}' (expected 'parse-serial')" |
| 45 | + ))), |
| 46 | + } |
| 47 | +} |
| 48 | + |
| 49 | +/// `zamak bench parse-serial [--tsc-mhz <n>] [<path>]`. |
| 50 | +fn run_parse_serial(args: &[String]) -> Result<Value, CliError> { |
| 51 | + let mut tsc_mhz_override: Option<u64> = None; |
| 52 | + let mut path: Option<String> = None; |
| 53 | + let mut i = 0; |
| 54 | + while i < args.len() { |
| 55 | + match args[i].as_str() { |
| 56 | + "--tsc-mhz" => { |
| 57 | + let v = args |
| 58 | + .get(i + 1) |
| 59 | + .ok_or_else(|| CliError::usage("--tsc-mhz requires a value (MHz integer)"))?; |
| 60 | + let n: u64 = v |
| 61 | + .parse() |
| 62 | + .map_err(|_| CliError::usage(format!("--tsc-mhz: invalid MHz value '{v}'")))?; |
| 63 | + if n == 0 { |
| 64 | + return Err(CliError::usage("--tsc-mhz must be > 0")); |
| 65 | + } |
| 66 | + tsc_mhz_override = Some(n); |
| 67 | + i += 2; |
| 68 | + } |
| 69 | + "--help" | "-h" => { |
| 70 | + return Err(CliError::usage( |
| 71 | + "usage: zamak bench parse-serial [--tsc-mhz <mhz>] [<path>]", |
| 72 | + )); |
| 73 | + } |
| 74 | + arg if arg.starts_with("--") => { |
| 75 | + return Err(CliError::usage(format!( |
| 76 | + "bench parse-serial: unknown flag '{arg}'" |
| 77 | + ))); |
| 78 | + } |
| 79 | + _ => { |
| 80 | + if path.is_some() { |
| 81 | + return Err(CliError::usage( |
| 82 | + "bench parse-serial: only one positional path allowed", |
| 83 | + )); |
| 84 | + } |
| 85 | + path = Some(args[i].clone()); |
| 86 | + i += 1; |
| 87 | + } |
| 88 | + } |
| 89 | + } |
| 90 | + |
| 91 | + let input = match path { |
| 92 | + Some(p) => fs::read_to_string(&p).map_err(|e| { |
| 93 | + CliError::new( |
| 94 | + crate::error::ErrorCode::NotFound, |
| 95 | + format!("bench parse-serial: cannot read '{p}': {e}"), |
| 96 | + ) |
| 97 | + })?, |
| 98 | + None => { |
| 99 | + let mut buf = String::new(); |
| 100 | + io::stdin().read_to_string(&mut buf).map_err(|e| { |
| 101 | + CliError::new( |
| 102 | + crate::error::ErrorCode::General, |
| 103 | + format!("bench parse-serial: stdin read failed: {e}"), |
| 104 | + ) |
| 105 | + })?; |
| 106 | + buf |
| 107 | + } |
| 108 | + }; |
| 109 | + |
| 110 | + Ok(parse_serial_to_value(&input, tsc_mhz_override)) |
| 111 | +} |
| 112 | + |
| 113 | +/// Pure string-in → Value-out. Exposed for unit tests. |
| 114 | +pub(crate) fn parse_serial_to_value(log: &str, tsc_mhz_override: Option<u64>) -> Value { |
| 115 | + let mut phases: Vec<(String, u64)> = Vec::new(); |
| 116 | + let mut tsc_mhz_from_log: Option<u64> = None; |
| 117 | + for line in log.lines() { |
| 118 | + if let Some((name, tsc)) = parse_phase_line(line) { |
| 119 | + phases.push((name, tsc)); |
| 120 | + } else if let Some(mhz) = parse_tsc_mhz_line(line) { |
| 121 | + tsc_mhz_from_log = Some(mhz); |
| 122 | + } |
| 123 | + } |
| 124 | + |
| 125 | + let tsc_mhz_used = tsc_mhz_override.or(tsc_mhz_from_log); |
| 126 | + |
| 127 | + let mut phase_values: Vec<Value> = Vec::with_capacity(phases.len()); |
| 128 | + let mut prev: Option<u64> = None; |
| 129 | + for (name, tsc) in &phases { |
| 130 | + let delta_cycles = prev.map_or(0u64, |p| tsc.saturating_sub(p)); |
| 131 | + let mut entry = obj([ |
| 132 | + ("phase", Value::str(name)), |
| 133 | + ("tsc", Value::UInt(*tsc)), |
| 134 | + ("delta_cycles", Value::UInt(delta_cycles)), |
| 135 | + ]); |
| 136 | + if let Some(mhz) = tsc_mhz_used { |
| 137 | + // cycles × (1 / MHz) = cycles × (1 / (cycles/μs)) = μs |
| 138 | + // multiply by 1000 for ns. |
| 139 | + let ns = (delta_cycles as f64) * 1000.0 / (mhz as f64); |
| 140 | + entry.insert("delta_ns", Value::Float(ns)); |
| 141 | + } |
| 142 | + phase_values.push(entry); |
| 143 | + prev = Some(*tsc); |
| 144 | + } |
| 145 | + |
| 146 | + let mut out = obj([("phases", Value::Array(phase_values))]); |
| 147 | + if let Some(mhz) = tsc_mhz_used { |
| 148 | + out.insert("tsc_mhz", Value::UInt(mhz)); |
| 149 | + } |
| 150 | + out |
| 151 | +} |
| 152 | + |
| 153 | +/// Finds `ZAMAK_PHASE=<name> tsc=<u64>` anywhere in the line. |
| 154 | +/// Accepts log-framed lines (e.g. the `[ INFO]: file@line:` prefix |
| 155 | +/// that `uefi_services`' logger adds). |
| 156 | +fn parse_phase_line(line: &str) -> Option<(String, u64)> { |
| 157 | + let after_tag = line.split_once("ZAMAK_PHASE=")?.1; |
| 158 | + // Phase name goes up to the next whitespace. |
| 159 | + let (name, rest) = after_tag.split_once(char::is_whitespace)?; |
| 160 | + let tsc_part = rest.split_once("tsc=")?.1; |
| 161 | + // TSC digits: parse until whitespace / end. |
| 162 | + let digits: String = tsc_part |
| 163 | + .chars() |
| 164 | + .take_while(|c| c.is_ascii_digit()) |
| 165 | + .collect(); |
| 166 | + let tsc: u64 = digits.parse().ok()?; |
| 167 | + Some((name.to_string(), tsc)) |
| 168 | +} |
| 169 | + |
| 170 | +/// Finds `ZAMAK_TSC_MHZ=<n>` anywhere in the line (ignores |
| 171 | +/// `ZAMAK_TSC_MHZ=unknown`). |
| 172 | +fn parse_tsc_mhz_line(line: &str) -> Option<u64> { |
| 173 | + let rest = line.split_once("ZAMAK_TSC_MHZ=")?.1; |
| 174 | + let digits: String = rest.chars().take_while(|c| c.is_ascii_digit()).collect(); |
| 175 | + if digits.is_empty() { |
| 176 | + return None; |
| 177 | + } |
| 178 | + digits.parse().ok() |
| 179 | +} |
| 180 | + |
| 181 | +#[cfg(test)] |
| 182 | +mod tests { |
| 183 | + use super::*; |
| 184 | + |
| 185 | + const SAMPLE_LOG: &str = "\ |
| 186 | +[ INFO]: zamak-uefi/src/main.rs@565: ZAMAK_TSC_MHZ=2400 |
| 187 | +[ INFO]: zamak-uefi/src/main.rs@542: ZAMAK_PHASE=uefi_entry tsc=1000000 |
| 188 | +[ INFO]: Zamak starting up (0.8.4)... |
| 189 | +[ INFO]: zamak-uefi/src/main.rs@542: ZAMAK_PHASE=config_parsed tsc=1120000 |
| 190 | +[ INFO]: zamak-uefi/src/main.rs@542: ZAMAK_PHASE=pre_exit_boot_services tsc=1240000 |
| 191 | +"; |
| 192 | + |
| 193 | + fn phase_at(v: &Value, idx: usize) -> &Vec<(String, Value)> { |
| 194 | + let Value::Object(root) = v else { |
| 195 | + panic!("expected object") |
| 196 | + }; |
| 197 | + let phases = &root.iter().find(|(k, _)| k == "phases").unwrap().1; |
| 198 | + let Value::Array(items) = phases else { |
| 199 | + panic!("expected array") |
| 200 | + }; |
| 201 | + let Value::Object(entry) = &items[idx] else { |
| 202 | + panic!("expected object") |
| 203 | + }; |
| 204 | + entry |
| 205 | + } |
| 206 | + |
| 207 | + fn field<'a>(entry: &'a [(String, Value)], k: &str) -> Option<&'a Value> { |
| 208 | + entry.iter().find(|(key, _)| key == k).map(|(_, v)| v) |
| 209 | + } |
| 210 | + |
| 211 | + #[test] |
| 212 | + fn parses_phases_in_order() { |
| 213 | + let v = parse_serial_to_value(SAMPLE_LOG, None); |
| 214 | + let p0 = phase_at(&v, 0); |
| 215 | + assert!(matches!(field(p0, "phase"), Some(Value::Str(s)) if s == "uefi_entry")); |
| 216 | + assert!(matches!(field(p0, "tsc"), Some(Value::UInt(1000000)))); |
| 217 | + assert!(matches!(field(p0, "delta_cycles"), Some(Value::UInt(0)))); |
| 218 | + |
| 219 | + let p1 = phase_at(&v, 1); |
| 220 | + assert!(matches!(field(p1, "phase"), Some(Value::Str(s)) if s == "config_parsed")); |
| 221 | + assert!(matches!( |
| 222 | + field(p1, "delta_cycles"), |
| 223 | + Some(Value::UInt(120000)) |
| 224 | + )); |
| 225 | + } |
| 226 | + |
| 227 | + #[test] |
| 228 | + fn log_tsc_mhz_enables_delta_ns() { |
| 229 | + let v = parse_serial_to_value(SAMPLE_LOG, None); |
| 230 | + let p1 = phase_at(&v, 1); |
| 231 | + let Some(Value::Float(ns)) = field(p1, "delta_ns") else { |
| 232 | + panic!("expected delta_ns float"); |
| 233 | + }; |
| 234 | + // 120000 cycles at 2400 MHz = 50_000 ns exactly. |
| 235 | + assert!((ns - 50000.0).abs() < 0.01); |
| 236 | + } |
| 237 | + |
| 238 | + #[test] |
| 239 | + fn explicit_tsc_mhz_overrides_log() { |
| 240 | + let v = parse_serial_to_value(SAMPLE_LOG, Some(1200)); |
| 241 | + let p1 = phase_at(&v, 1); |
| 242 | + let Some(Value::Float(ns)) = field(p1, "delta_ns") else { |
| 243 | + panic!("expected delta_ns float"); |
| 244 | + }; |
| 245 | + // 120000 / 1200 MHz = 100 μs = 100_000 ns. |
| 246 | + assert!((ns - 100000.0).abs() < 0.01); |
| 247 | + } |
| 248 | + |
| 249 | + #[test] |
| 250 | + fn missing_tsc_mhz_omits_delta_ns() { |
| 251 | + let log = "\ |
| 252 | +[ INFO]: ZAMAK_PHASE=uefi_entry tsc=10 |
| 253 | +[ INFO]: ZAMAK_PHASE=config_parsed tsc=20 |
| 254 | +"; |
| 255 | + let v = parse_serial_to_value(log, None); |
| 256 | + let p1 = phase_at(&v, 1); |
| 257 | + assert!(field(p1, "delta_ns").is_none()); |
| 258 | + assert!(matches!(field(p1, "delta_cycles"), Some(Value::UInt(10)))); |
| 259 | + // Envelope must NOT advertise a tsc_mhz if we don't know one. |
| 260 | + let Value::Object(root) = &v else { panic!() }; |
| 261 | + assert!(!root.iter().any(|(k, _)| k == "tsc_mhz")); |
| 262 | + } |
| 263 | + |
| 264 | + #[test] |
| 265 | + fn unknown_tsc_mhz_line_is_ignored() { |
| 266 | + let log = "\ |
| 267 | +[ INFO]: ZAMAK_TSC_MHZ=unknown |
| 268 | +[ INFO]: ZAMAK_PHASE=uefi_entry tsc=10 |
| 269 | +[ INFO]: ZAMAK_PHASE=config_parsed tsc=20 |
| 270 | +"; |
| 271 | + let v = parse_serial_to_value(log, None); |
| 272 | + let Value::Object(root) = &v else { panic!() }; |
| 273 | + // No tsc_mhz field, no delta_ns on phases. |
| 274 | + assert!(!root.iter().any(|(k, _)| k == "tsc_mhz")); |
| 275 | + assert!(field(phase_at(&v, 1), "delta_ns").is_none()); |
| 276 | + } |
| 277 | + |
| 278 | + #[test] |
| 279 | + fn empty_input_produces_empty_phases() { |
| 280 | + let v = parse_serial_to_value("", Some(2400)); |
| 281 | + let Value::Object(root) = &v else { panic!() }; |
| 282 | + // tsc_mhz still present because explicit. |
| 283 | + assert!(matches!( |
| 284 | + root.iter().find(|(k, _)| k == "tsc_mhz").map(|(_, v)| v), |
| 285 | + Some(Value::UInt(2400)), |
| 286 | + )); |
| 287 | + let phases = &root.iter().find(|(k, _)| k == "phases").unwrap().1; |
| 288 | + assert!(matches!(phases, Value::Array(a) if a.is_empty())); |
| 289 | + } |
| 290 | + |
| 291 | + #[test] |
| 292 | + fn malformed_phase_line_is_skipped() { |
| 293 | + let log = "\ |
| 294 | +[ INFO]: ZAMAK_PHASE=good tsc=10 |
| 295 | +[ INFO]: ZAMAK_PHASE=bad tsc=not-a-number |
| 296 | +[ INFO]: ZAMAK_PHASE=other_good tsc=30 |
| 297 | +"; |
| 298 | + let v = parse_serial_to_value(log, None); |
| 299 | + let Value::Object(root) = &v else { panic!() }; |
| 300 | + let phases = &root.iter().find(|(k, _)| k == "phases").unwrap().1; |
| 301 | + let Value::Array(items) = phases else { |
| 302 | + panic!() |
| 303 | + }; |
| 304 | + assert_eq!(items.len(), 2); |
| 305 | + assert!(matches!( |
| 306 | + field(phase_at(&v, 0), "phase"), |
| 307 | + Some(Value::Str(s)) if s == "good", |
| 308 | + )); |
| 309 | + assert!(matches!( |
| 310 | + field(phase_at(&v, 1), "phase"), |
| 311 | + Some(Value::Str(s)) if s == "other_good", |
| 312 | + )); |
| 313 | + } |
| 314 | +} |
0 commit comments