cargo/compiler/timings/
mod.rs

1//! Timing tracking.
2//!
3//! This module implements some simple tracking information for timing of how
4//! long it takes for different units to compile.
5
6pub mod report;
7
8use super::CompileMode;
9use super::Unit;
10use super::UnitIndex;
11use crate::compiler::BuildContext;
12use crate::compiler::BuildRunner;
13use crate::compiler::job_queue::JobId;
14use crate::ops::cargo_report::timings::prepare_context;
15use crate::util::cpu::State;
16use crate::util::log_message::LogMessage;
17use crate::util::style;
18use crate::util::{CargoResult, GlobalContext};
19
20use crate::util::data_structures::HashMap;
21use cargo_util::paths;
22use std::io::BufWriter;
23use std::time::{Duration, Instant};
24
25/// Tracking information for the entire build.
26///
27/// Methods on this structure are generally called from the main thread of a
28/// running [`JobQueue`] instance (`DrainState` in specific) when the queue
29/// receives messages from spawned off threads.
30///
31/// [`JobQueue`]: super::JobQueue
32pub struct Timings<'gctx> {
33    gctx: &'gctx GlobalContext,
34    /// Whether or not timings should be captured.
35    enabled: bool,
36    /// When Cargo started.
37    start: Instant,
38    /// A summary of the root units.
39    ///
40    /// A map from unit to index.
41    unit_to_index: HashMap<Unit, UnitIndex>,
42    /// Units that are in the process of being built.
43    /// When they finished, they are moved to `unit_times`.
44    active: HashMap<JobId, Unit>,
45    /// Last recorded state of the system's CPUs and when it happened
46    last_cpu_state: Option<State>,
47    last_cpu_recording: Instant,
48    /// Recorded CPU states, stored as tuples. First element is when the
49    /// recording was taken and second element is percentage usage of the
50    /// system.
51    cpu_usage: Vec<(f64, f64)>,
52}
53
54/// Section of compilation (e.g. frontend, backend, linking).
55#[derive(Copy, Clone, serde::Serialize)]
56pub struct CompilationSection {
57    /// Start of the section, as an offset in seconds from `UnitTime::start`.
58    pub start: f64,
59    /// End of the section, as an offset in seconds from `UnitTime::start`.
60    pub end: Option<f64>,
61}
62
63/// Data for a single compilation unit, prepared for serialization to JSON.
64///
65/// This is used by the HTML report's JavaScript to render the pipeline graph.
66#[derive(serde::Serialize)]
67pub struct UnitData {
68    pub i: UnitIndex,
69    pub name: String,
70    pub version: String,
71    pub mode: String,
72    pub target: String,
73    pub features: Vec<String>,
74    pub start: f64,
75    pub duration: f64,
76    /// Peak resident set size of the unit's process, in bytes.
77    #[serde(skip_serializing_if = "Option::is_none")]
78    pub peak_memory: Option<u64>,
79    pub unblocked_units: Vec<UnitIndex>,
80    pub unblocked_rmeta_units: Vec<UnitIndex>,
81    pub sections: Option<Vec<(report::SectionName, report::SectionData)>>,
82}
83
84impl<'gctx> Timings<'gctx> {
85    pub fn new(bcx: &BuildContext<'_, 'gctx>) -> Timings<'gctx> {
86        let start = bcx.gctx.invocation_instant();
87        let enabled = bcx.logger.is_some();
88
89        if !enabled {
90            return Timings {
91                gctx: bcx.gctx,
92                enabled,
93                start,
94                unit_to_index: HashMap::default(),
95                active: HashMap::default(),
96                last_cpu_state: None,
97                last_cpu_recording: Instant::now(),
98                cpu_usage: Vec::new(),
99            };
100        }
101
102        let last_cpu_state = match State::current() {
103            Ok(state) => Some(state),
104            Err(e) => {
105                tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e);
106                None
107            }
108        };
109
110        Timings {
111            gctx: bcx.gctx,
112            enabled,
113            start,
114            unit_to_index: bcx.unit_to_index.clone(),
115            active: HashMap::default(),
116            last_cpu_state,
117            last_cpu_recording: Instant::now(),
118            cpu_usage: Vec::new(),
119        }
120    }
121
122    /// Mark that a unit has started running.
123    pub fn unit_start(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, unit: Unit) {
124        let Some(logger) = build_runner.bcx.logger else {
125            return;
126        };
127        let mut target = if unit.target.is_lib()
128            && matches!(unit.mode, CompileMode::Build | CompileMode::Check { .. })
129        {
130            // Special case for brevity, since most dependencies hit this path.
131            "".to_string()
132        } else {
133            format!(" {}", unit.target.description_named())
134        };
135        match unit.mode {
136            CompileMode::Test => target.push_str(" (test)"),
137            CompileMode::Build => {}
138            CompileMode::Check { test: true } => target.push_str(" (check-test)"),
139            CompileMode::Check { test: false } => target.push_str(" (check)"),
140            CompileMode::Doc { .. } => target.push_str(" (doc)"),
141            CompileMode::Doctest => target.push_str(" (doc test)"),
142            CompileMode::Docscrape => target.push_str(" (doc scrape)"),
143            CompileMode::RunCustomBuild => target.push_str(" (run)"),
144        }
145        let start = self.start.elapsed().as_secs_f64();
146        logger.log(LogMessage::UnitStarted {
147            index: self.unit_to_index[&unit],
148            elapsed: start,
149        });
150
151        assert!(self.active.insert(id, unit).is_none());
152    }
153
154    /// Mark that the `.rmeta` file as generated.
155    pub fn unit_rmeta_finished(
156        &mut self,
157        build_runner: &BuildRunner<'_, '_>,
158        id: JobId,
159        unblocked: Vec<&Unit>,
160    ) {
161        let Some(logger) = build_runner.bcx.logger else {
162            return;
163        };
164        // `id` may not always be active. "fresh" units unconditionally
165        // generate `Message::Finish`, but this active map only tracks dirty
166        // units.
167        let Some(unit) = self.active.get(&id) else {
168            return;
169        };
170        let elapsed = self.start.elapsed().as_secs_f64();
171
172        let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
173        logger.log(LogMessage::UnitRmetaFinished {
174            index: self.unit_to_index[unit],
175            elapsed,
176            unblocked,
177        });
178    }
179
180    /// Mark that a unit has finished running.
181    pub fn unit_finished(
182        &mut self,
183        build_runner: &BuildRunner<'_, '_>,
184        id: JobId,
185        unblocked: Vec<&Unit>,
186    ) {
187        let Some(logger) = build_runner.bcx.logger else {
188            return;
189        };
190        // See note above in `unit_rmeta_finished`, this may not always be active.
191        let Some(unit) = self.active.remove(&id) else {
192            return;
193        };
194        let elapsed = self.start.elapsed().as_secs_f64();
195
196        let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
197        logger.log(LogMessage::UnitFinished {
198            index: self.unit_to_index[&unit],
199            elapsed,
200            unblocked,
201        });
202    }
203
204    /// Handle the start/end of a compilation section.
205    pub fn unit_section_timing(
206        &mut self,
207        build_runner: &BuildRunner<'_, '_>,
208        id: JobId,
209        section_timing: &SectionTiming,
210    ) {
211        let Some(logger) = build_runner.bcx.logger else {
212            return;
213        };
214        let Some(unit) = self.active.get(&id) else {
215            return;
216        };
217        let elapsed = self.start.elapsed().as_secs_f64();
218
219        let index = self.unit_to_index[&unit];
220        let section = section_timing.name.clone();
221        logger.log(match section_timing.event {
222            SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
223                index,
224                elapsed,
225                section,
226            },
227            SectionTimingEvent::End => LogMessage::UnitSectionFinished {
228                index,
229                elapsed,
230                section,
231            },
232        })
233    }
234
235    /// Record the peak memory usage (in bytes) of a unit's process.
236    ///
237    /// This should only be called when `-Zmem-stats` is enabled.
238    pub fn unit_peak_memory(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, bytes: u64) {
239        let Some(logger) = build_runner.bcx.logger else {
240            return;
241        };
242        let Some(unit) = self.active.get(&id) else {
243            return;
244        };
245        logger.log(LogMessage::UnitPeakMemory {
246            index: self.unit_to_index[unit],
247            bytes,
248        });
249    }
250
251    /// Take a sample of CPU usage
252    pub fn record_cpu(&mut self) {
253        if !self.enabled {
254            return;
255        }
256        let Some(prev) = &mut self.last_cpu_state else {
257            return;
258        };
259        // Don't take samples too frequently, even if requested.
260        let now = Instant::now();
261        if self.last_cpu_recording.elapsed() < Duration::from_millis(100) {
262            return;
263        }
264        let current = match State::current() {
265            Ok(s) => s,
266            Err(e) => {
267                tracing::info!("failed to get CPU state: {:?}", e);
268                return;
269            }
270        };
271        let pct_idle = current.idle_since(prev);
272        *prev = current;
273        self.last_cpu_recording = now;
274        let dur = now.duration_since(self.start).as_secs_f64();
275        self.cpu_usage.push((dur, 100.0 - pct_idle));
276    }
277
278    /// Call this when all units are finished.
279    pub fn finished(
280        &mut self,
281        build_runner: &BuildRunner<'_, '_>,
282        error: &Option<anyhow::Error>,
283    ) -> CargoResult<()> {
284        if let Some(logger) = build_runner.bcx.logger
285            && let Some(logs) = logger.get_logs()
286        {
287            let timings_path = build_runner
288                .files()
289                .timings_dir()
290                .expect("artifact-dir was not locked");
291            paths::create_dir_all(&timings_path)?;
292            let run_id = logger.run_id();
293            let filename = timings_path.join(format!("cargo-timing-{run_id}.html"));
294            let mut f = BufWriter::new(paths::create(&filename)?);
295
296            let mut ctx = prepare_context(logs.into_iter(), run_id, false)?;
297            ctx.error = error;
298            ctx.cpu_usage = &self.cpu_usage;
299            report::write_html(ctx, &mut f)?;
300
301            let unstamped_filename = timings_path.join("cargo-timing.html");
302            paths::link_or_copy(&filename, &unstamped_filename)?;
303
304            let mut shell = self.gctx.shell();
305            let timing_path = std::env::current_dir().unwrap_or_default().join(&filename);
306            let link = shell.err_file_hyperlink(&timing_path);
307            let msg = format!("report saved to {link}{}{link:#}", timing_path.display(),);
308            shell.status_with_color("Timing", msg, &style::NOTE)?;
309        }
310        Ok(())
311    }
312}
313
314/// Start or end of a section timing.
315#[derive(serde::Deserialize, Debug)]
316#[serde(rename_all = "kebab-case")]
317pub enum SectionTimingEvent {
318    Start,
319    End,
320}
321
322/// Represents a certain section (phase) of rustc compilation.
323/// It is emitted by rustc when the `--json=timings` flag is used.
324#[derive(serde::Deserialize, Debug)]
325pub struct SectionTiming {
326    pub name: String,
327    pub event: SectionTimingEvent,
328}
cargo/compiler/timings/mod.rs

cargo/compiler/timings/
mod.rs
