|
| 1 | +use once_cell::sync::OnceCell; |
| 2 | +use rustc_hash::FxHashMap; |
| 3 | +use std::{ |
| 4 | + cmp::Ordering, |
| 5 | + sync::{Arc, Mutex, MutexGuard}, |
| 6 | + time::Instant, |
| 7 | +}; |
| 8 | +use terminal_size::{Width, terminal_size}; |
| 9 | + |
| 10 | +enum Run { |
| 11 | + Started(Instant), |
| 12 | + Finished(Instant, Instant), |
| 13 | +} |
| 14 | + |
| 15 | +#[derive(Default)] |
| 16 | +struct Experiment { |
| 17 | + start: Option<Instant>, |
| 18 | + runs: FxHashMap<String, Run>, |
| 19 | +} |
| 20 | + |
| 21 | +static EXPERIMENT: OnceCell<Arc<Mutex<Experiment>>> = OnceCell::new(); |
| 22 | + |
| 23 | +fn get_experiment() -> MutexGuard<'static, Experiment> { |
| 24 | + EXPERIMENT |
| 25 | + .get_or_init(|| Arc::new(Mutex::new(Experiment::default()))) |
| 26 | + .lock() |
| 27 | + .expect("Failed to acquire lock") |
| 28 | +} |
| 29 | + |
| 30 | +/// Records or updates timing events for a labeled operation in a global |
| 31 | +/// experiment tracker. |
| 32 | +/// |
| 33 | +/// This function is used to mark the **start** or **end** of a timed operation |
| 34 | +/// identified by `tag`. |
| 35 | +/// - On the **first call** with a given `tag`, it records a `Run::Started` event. |
| 36 | +/// - On the **second call** with the same `tag`, it updates the event to |
| 37 | +/// `Run::Finished` (with start/end times). |
| 38 | +/// - Panics if a `tag` is called more than twice (i.e., already finished). |
| 39 | +/// |
| 40 | +/// # Global State |
| 41 | +/// The timing data is stored in a thread-safe global [`Experiment`] (accessed |
| 42 | +/// via [`Arc`] + [`Mutex`]). |
| 43 | +/// |
| 44 | +/// The experiment's global start time is set on the first call to `clock`. |
| 45 | +/// |
| 46 | +/// # Panics |
| 47 | +/// - If a `tag` is used after it has already been marked `Finished`. |
| 48 | +/// - If the global [`Mutex`] is poisoned by another thread. |
| 49 | +/// |
| 50 | +/// # Example |
| 51 | +/// ```rust |
| 52 | +/// cronos::clock("work"); // Start tracking "work" |
| 53 | +/// do_work(); |
| 54 | +/// cronos::clock("work"); // Finish tracking "work" (start → end) |
| 55 | +/// ``` |
| 56 | +/// |
| 57 | +/// # Performance |
| 58 | +/// - Uses [`FxHashMap`] for efficient string-keyed lookups. |
| 59 | +/// - Locks the global [`Mutex`] briefly during updates. |
| 60 | +pub fn clock(tag: impl AsRef<str>) { |
| 61 | + let mut experiment = get_experiment(); |
| 62 | + let now = Instant::now(); |
| 63 | + if experiment.start.is_none() { |
| 64 | + experiment.start = Some(now); |
| 65 | + } |
| 66 | + let tag = tag.as_ref(); |
| 67 | + if let Some(run) = experiment.runs.get_mut(tag) { |
| 68 | + match run { |
| 69 | + Run::Finished(..) => panic!("{tag} is already finished."), |
| 70 | + Run::Started(start) => *run = Run::Finished(*start, now), |
| 71 | + } |
| 72 | + } else { |
| 73 | + experiment.runs.insert(tag.to_string(), Run::Started(now)); |
| 74 | + } |
| 75 | +} |
| 76 | + |
| 77 | +#[allow(clippy::cast_precision_loss)] |
| 78 | +fn format_duration(nanos: u128) -> String { |
| 79 | + if nanos < 1_000 { |
| 80 | + format!("{nanos}ns") |
| 81 | + } else if nanos < 1_000_000 { |
| 82 | + format!("{:.2}μs", nanos as f64 / 1_000.0) |
| 83 | + } else if nanos < 1_000_000_000 { |
| 84 | + format!("{:.2}ms", nanos as f64 / 1_000_000.0) |
| 85 | + } else if nanos < 60_000_000_000 { |
| 86 | + format!("{:.2}s", nanos as f64 / 1_000_000_000.0) |
| 87 | + } else if nanos < 3_600_000_000_000 { |
| 88 | + let secs = nanos as f64 / 1_000_000_000.0; |
| 89 | + format!("{:.2}m", secs / 60.0) |
| 90 | + } else { |
| 91 | + let secs = nanos as f64 / 1_000_000_000.0; |
| 92 | + format!("{:.2}h", secs / 3_600.0) |
| 93 | + } |
| 94 | +} |
| 95 | + |
| 96 | +struct RunStats<'a> { |
| 97 | + tag: &'a str, |
| 98 | + tag_len: usize, |
| 99 | + to_start_ns: u128, |
| 100 | + duration_ns: u128, |
| 101 | + duration_fmt: String, |
| 102 | + duration_fmt_len: usize, |
| 103 | +} |
| 104 | + |
| 105 | +/// Prints a visual timeline of all completed experiment runs to the terminal. |
| 106 | +/// |
| 107 | +/// Displays a horizontal bar chart showing: |
| 108 | +/// - Relative timing of each run (position along the x-axis) |
| 109 | +/// - Duration of each run (length of the bar) |
| 110 | +/// - Absolute durations in human-readable format |
| 111 | +/// |
| 112 | +/// # Behavior |
| 113 | +/// - Only prints if: |
| 114 | +/// * A TTY is detected (via `terminal_size()`) |
| 115 | +/// * At least one experiment has been started (`clock(<tag>)` called) |
| 116 | +/// * All tracked tags have been properly finished |
| 117 | +/// - Automatically scales the timeline to fit the terminal width |
| 118 | +/// - Includes a summary bar for the total experiment duration |
| 119 | +/// |
| 120 | +/// # Panics |
| 121 | +/// - If any tracked tag hasn't been finished (missing `clock(<tag>)` call) |
| 122 | +/// - If terminal width would cause arithmetic overflow (extremely unlikely) |
| 123 | +/// |
| 124 | +/// # Example Output |
| 125 | +/// ```text |
| 126 | +/// │1.62s ├─────────────────────────────────────────────────────────┤ |
| 127 | +/// s1commit│302.69ms├──────────┤ |
| 128 | +/// s2traces│37.97ms ├┤ |
| 129 | +/// s2commit│196.21ms ├──────┤ |
| 130 | +/// qcommit │527.96ms ├──────────────────┤ |
| 131 | +/// qeval-0 │135.20ms ├───┤ |
| 132 | +/// qeval-1 │73.02ms ├─┤ |
| 133 | +/// open │554.95ms ├───────────────────┤ |
| 134 | +/// ``` |
| 135 | +pub fn print() { |
| 136 | + let Some((Width(terminal_width), _)) = terminal_size() else { |
| 137 | + return; // No TTY available |
| 138 | + }; |
| 139 | + |
| 140 | + // Gather data from runs |
| 141 | + let experiment = get_experiment(); |
| 142 | + let Some(experiment_start) = experiment.start else { |
| 143 | + return; // No experiment performed |
| 144 | + }; |
| 145 | + let mut experiment_end = experiment_start; |
| 146 | + let mut biggest_tag_len = 0; |
| 147 | + let mut biggest_duration_fmt_len = 0; |
| 148 | + let mut finished_runs = Vec::with_capacity(experiment.runs.len()); |
| 149 | + for (tag, run) in &experiment.runs { |
| 150 | + let tag_len = tag.chars().count(); |
| 151 | + biggest_tag_len = biggest_tag_len.max(tag_len); |
| 152 | + let Run::Finished(start, end) = run else { |
| 153 | + panic!("{tag} is not finished."); |
| 154 | + }; |
| 155 | + if end > &experiment_end { |
| 156 | + experiment_end = *end; // .max wouldn't avoid this copy |
| 157 | + } |
| 158 | + let duration_ns = (*end - *start).as_nanos(); |
| 159 | + let duration_fmt = format_duration(duration_ns); |
| 160 | + let duration_fmt_len = duration_fmt.chars().count(); |
| 161 | + biggest_duration_fmt_len = biggest_duration_fmt_len.max(duration_fmt_len); |
| 162 | + let stats = RunStats { |
| 163 | + tag, |
| 164 | + tag_len, |
| 165 | + to_start_ns: (*start - experiment_start).as_nanos(), |
| 166 | + duration_ns, |
| 167 | + duration_fmt, |
| 168 | + duration_fmt_len, |
| 169 | + }; |
| 170 | + finished_runs.push(stats); |
| 171 | + } |
| 172 | + let experiment_duration_ns = (experiment_end - experiment_start).as_nanos(); |
| 173 | + let experiment_duration_fmt = format_duration(experiment_duration_ns); |
| 174 | + let experiment_duration_fmt_len = experiment_duration_fmt.chars().count(); |
| 175 | + biggest_duration_fmt_len = biggest_duration_fmt_len.max(experiment_duration_fmt_len); |
| 176 | + |
| 177 | + // Push the stats for the full experiment and then sort |
| 178 | + finished_runs.push(RunStats { |
| 179 | + tag: "", |
| 180 | + tag_len: 0, |
| 181 | + to_start_ns: 0, |
| 182 | + duration_ns: experiment_duration_ns, |
| 183 | + duration_fmt: experiment_duration_fmt, |
| 184 | + duration_fmt_len: experiment_duration_fmt_len, |
| 185 | + }); |
| 186 | + finished_runs.sort_by(|a, b| { |
| 187 | + if a.to_start_ns < b.to_start_ns { |
| 188 | + Ordering::Less |
| 189 | + } else if a.to_start_ns == b.to_start_ns { |
| 190 | + b.duration_ns.cmp(&a.duration_ns) |
| 191 | + } else { |
| 192 | + Ordering::Greater |
| 193 | + } |
| 194 | + }); |
| 195 | + |
| 196 | + // Finally print the duration bars |
| 197 | + let width = // Consider the vertical pipe that separates tags and durations |
| 198 | + (terminal_width as usize).saturating_sub(biggest_tag_len + biggest_duration_fmt_len + 1); |
| 199 | + let width_u128 = width as u128; |
| 200 | + let transform = |x: u128| (x * width_u128).div_ceil(experiment_duration_ns); |
| 201 | + for run in finished_runs { |
| 202 | + let RunStats { |
| 203 | + tag, |
| 204 | + tag_len, |
| 205 | + to_start_ns, |
| 206 | + duration_ns, |
| 207 | + duration_fmt, |
| 208 | + duration_fmt_len, |
| 209 | + } = run; |
| 210 | + |
| 211 | + let bar_pos = usize::try_from(transform(to_start_ns)).unwrap(); |
| 212 | + let bar_len = usize::try_from(transform(duration_ns)).unwrap(); |
| 213 | + |
| 214 | + let bar = match bar_len { |
| 215 | + 0 => "│".to_string(), |
| 216 | + 1 => "┃".to_string(), |
| 217 | + _ => format!("├{}┤", "─".repeat(bar_len - 2)), |
| 218 | + }; |
| 219 | + |
| 220 | + println!( |
| 221 | + "{tag}{}│{duration_fmt}{}{}{bar}", |
| 222 | + " ".repeat(biggest_tag_len - tag_len), |
| 223 | + " ".repeat(biggest_duration_fmt_len - duration_fmt_len), |
| 224 | + " ".repeat(bar_pos.saturating_sub(1)), |
| 225 | + ); |
| 226 | + } |
| 227 | +} |
0 commit comments