| 1 | //! Lightweight startup milestone tracing (#3757). |
| 2 | //! |
| 3 | //! Records named milestones against a single process-start instant and emits |
| 4 | //! one summary line to the runtime log when the TUI enters its event loop. |
| 5 | //! Milestones are buffered in memory because most of them occur before the |
| 6 | //! runtime log is initialized; the summary is the artifact, not the events. |
| 7 | |
| 8 | use std::sync::{Mutex, OnceLock}; |
| 9 | use std::time::Instant; |
| 10 | |
| 11 | static PROCESS_START: OnceLock<Instant> = OnceLock::new(); |
| 12 | static MILESTONES: Mutex<Vec<(&'static str, u64)>> = Mutex::new(Vec::new()); |
| 13 | |
| 14 | /// Pin the process-start instant. First call wins; later calls are no-ops so |
| 15 | /// tests and alternate entry points cannot skew the timeline. |
| 16 | pub fn mark_process_start() { |
| 17 | let _ = PROCESS_START.set(Instant::now()); |
| 18 | } |
| 19 | |
| 20 | /// Record `label` at the current elapsed time since process start. No-op if |
| 21 | /// [`mark_process_start`] was never called (e.g. non-interactive subcommands). |
| 22 | pub fn mark(label: &'static str) { |
| 23 | let Some(start) = PROCESS_START.get() else { |
| 24 | return; |
| 25 | }; |
| 26 | let elapsed_ms = start.elapsed().as_millis() as u64; |
| 27 | if let Ok(mut milestones) = MILESTONES.lock() { |
| 28 | milestones.push((label, elapsed_ms)); |
| 29 | } |
| 30 | } |
| 31 | |
| 32 | /// Milliseconds since process start, or `None` when [`mark_process_start`] was |
| 33 | /// never called. |
| 34 | /// |
| 35 | /// [`log_summary`] computes the same number into a local, emits it through |
| 36 | /// `tracing`, and returns `()` — and it clears the milestone buffer on the way |
| 37 | /// out, so a second caller reading through it would get a different answer. |
| 38 | /// This reads `PROCESS_START` directly and is independent of that. |
| 39 | pub fn elapsed_ms() -> Option<u64> { |
| 40 | PROCESS_START |
| 41 | .get() |
| 42 | .map(|start| start.elapsed().as_millis() as u64) |
| 43 | } |
| 44 | |
| 45 | /// The cold-start measurement, taken once when the event loop begins. |
| 46 | static COLD_START_MS: OnceLock<u64> = OnceLock::new(); |
| 47 | |
| 48 | /// Pin the cold-start measurement. First call wins. |
| 49 | /// |
| 50 | /// Only the interactive path calls this, which is what makes the cold-start |
| 51 | /// bucket absent rather than invented on surfaces that have no event loop. |
| 52 | pub fn mark_cold_start() { |
| 53 | if let Some(elapsed) = elapsed_ms() { |
| 54 | let _ = COLD_START_MS.set(elapsed); |
| 55 | } |
| 56 | } |
| 57 | |
| 58 | /// The pinned cold-start measurement, or `None` if the event loop never began. |
| 59 | pub fn cold_start_ms() -> Option<u64> { |
| 60 | COLD_START_MS.get().copied() |
| 61 | } |
| 62 | |
| 63 | /// Emit the buffered milestones as one summary line and clear the buffer. |
| 64 | /// Called once the runtime log exists (just before the event loop starts). |
| 65 | pub fn log_summary() { |
| 66 | let Some(start) = PROCESS_START.get() else { |
| 67 | return; |
| 68 | }; |
| 69 | let total_ms = start.elapsed().as_millis() as u64; |
| 70 | let Ok(mut milestones) = MILESTONES.lock() else { |
| 71 | return; |
| 72 | }; |
| 73 | let line = milestones |
| 74 | .iter() |
| 75 | .map(|(label, ms)| format!("{label}={ms}ms")) |
| 76 | .collect::<Vec<_>>() |
| 77 | .join(" "); |
| 78 | milestones.clear(); |
| 79 | tracing::info!(target: "startup", "startup {line} event_loop={total_ms}ms"); |
| 80 | } |
| 81 | |
| 82 | #[cfg(test)] |
| 83 | mod tests { |
| 84 | use super::*; |
| 85 | |
| 86 | #[test] |
| 87 | fn milestones_accumulate_and_summary_drains() { |
| 88 | mark_process_start(); |
| 89 | mark("alpha"); |
| 90 | mark("beta"); |
| 91 | { |
| 92 | let milestones = MILESTONES.lock().unwrap(); |
| 93 | let labels: Vec<&str> = milestones.iter().map(|(l, _)| *l).collect(); |
| 94 | assert!(labels.contains(&"alpha")); |
| 95 | assert!(labels.contains(&"beta")); |
| 96 | } |
| 97 | log_summary(); |
| 98 | assert!(MILESTONES.lock().unwrap().is_empty()); |
| 99 | } |
| 100 | } |
| 101 |