cargo/core/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, Unit};
9use crate::core::PackageId;
10use crate::core::compiler::job_queue::JobId;
11use crate::core::compiler::{BuildContext, BuildRunner, TimingOutput};
12use crate::util::cpu::State;
13use crate::util::log_message::LogMessage;
14use crate::util::machine_message::{self, Message};
15use crate::util::style;
16use crate::util::{CargoResult, GlobalContext};
17
18use cargo_util::paths;
19use indexmap::IndexMap;
20use std::collections::HashMap;
21use std::io::BufWriter;
22use std::time::{Duration, Instant};
23use tracing::warn;
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    /// If true, saves an HTML report to disk.
37    report_html: bool,
38    /// If true, emits JSON information with timing information.
39    report_json: bool,
40    /// When Cargo started.
41    start: Instant,
42    /// A rendered string of when compilation started.
43    start_str: String,
44    /// A summary of the root units.
45    ///
46    /// Tuples of `(package_description, target_descriptions)`.
47    root_targets: Vec<(String, Vec<String>)>,
48    /// The build profile.
49    profile: String,
50    /// Total number of fresh units.
51    total_fresh: u32,
52    /// Total number of dirty units.
53    total_dirty: u32,
54    /// A map from unit to index.
55    unit_to_index: HashMap<Unit, u64>,
56    /// Time tracking for each individual unit.
57    unit_times: Vec<UnitTime>,
58    /// Units that are in the process of being built.
59    /// When they finished, they are moved to `unit_times`.
60    active: HashMap<JobId, UnitTime>,
61    /// Last recorded state of the system's CPUs and when it happened
62    last_cpu_state: Option<State>,
63    last_cpu_recording: Instant,
64    /// Recorded CPU states, stored as tuples. First element is when the
65    /// recording was taken and second element is percentage usage of the
66    /// system.
67    cpu_usage: Vec<(f64, f64)>,
68}
69
70/// Section of compilation (e.g. frontend, backend, linking).
71#[derive(Copy, Clone, serde::Serialize)]
72pub struct CompilationSection {
73    /// Start of the section, as an offset in seconds from `UnitTime::start`.
74    pub start: f64,
75    /// End of the section, as an offset in seconds from `UnitTime::start`.
76    pub end: Option<f64>,
77}
78
79/// Tracking information for an individual unit.
80struct UnitTime {
81    unit: Unit,
82    /// A string describing the cargo target.
83    target: String,
84    /// The time when this unit started as an offset in seconds from `Timings::start`.
85    start: f64,
86    /// Total time to build this unit in seconds.
87    duration: f64,
88    /// The time when the `.rmeta` file was generated, an offset in seconds
89    /// from `start`.
90    rmeta_time: Option<f64>,
91    /// Reverse deps that are unblocked and ready to run after this unit finishes.
92    unblocked_units: Vec<Unit>,
93    /// Same as `unblocked_units`, but unblocked by rmeta.
94    unblocked_rmeta_units: Vec<Unit>,
95    /// Individual compilation section durations, gathered from `--json=timings`.
96    ///
97    /// IndexMap is used to keep original insertion order, we want to be able to tell which
98    /// sections were started in which order.
99    sections: IndexMap<String, CompilationSection>,
100}
101
102/// Data for a single compilation unit, prepared for serialization to JSON.
103///
104/// This is used by the HTML report's JavaScript to render the pipeline graph.
105#[derive(serde::Serialize)]
106pub struct UnitData {
107    pub i: u64,
108    pub name: String,
109    pub version: String,
110    pub mode: String,
111    pub target: String,
112    pub features: Vec<String>,
113    pub start: f64,
114    pub duration: f64,
115    pub unblocked_units: Vec<u64>,
116    pub unblocked_rmeta_units: Vec<u64>,
117    pub sections: Option<Vec<(report::SectionName, report::SectionData)>>,
118}
119
120impl<'gctx> Timings<'gctx> {
121    pub fn new(bcx: &BuildContext<'_, 'gctx>, root_units: &[Unit]) -> Timings<'gctx> {
122        let start = bcx.gctx.creation_time();
123        let has_report = |what| bcx.build_config.timing_outputs.contains(&what);
124        let report_html = has_report(TimingOutput::Html);
125        let report_json = has_report(TimingOutput::Json);
126        let enabled = report_html | report_json | bcx.logger.is_some();
127
128        if !enabled {
129            return Timings {
130                gctx: bcx.gctx,
131                enabled,
132                report_html,
133                report_json,
134                start,
135                start_str: String::new(),
136                root_targets: Vec::new(),
137                profile: String::new(),
138                total_fresh: 0,
139                total_dirty: 0,
140                unit_to_index: HashMap::new(),
141                unit_times: Vec::new(),
142                active: HashMap::new(),
143                last_cpu_state: None,
144                last_cpu_recording: Instant::now(),
145                cpu_usage: Vec::new(),
146            };
147        }
148
149        let mut root_map: HashMap<PackageId, Vec<String>> = HashMap::new();
150        for unit in root_units {
151            let target_desc = unit.target.description_named();
152            root_map
153                .entry(unit.pkg.package_id())
154                .or_default()
155                .push(target_desc);
156        }
157        let root_targets = root_map
158            .into_iter()
159            .map(|(pkg_id, targets)| {
160                let pkg_desc = format!("{} {}", pkg_id.name(), pkg_id.version());
161                (pkg_desc, targets)
162            })
163            .collect();
164        let start_str = jiff::Timestamp::now().to_string();
165        let profile = bcx.build_config.requested_profile.to_string();
166        let last_cpu_state = match State::current() {
167            Ok(state) => Some(state),
168            Err(e) => {
169                tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e);
170                None
171            }
172        };
173
174        Timings {
175            gctx: bcx.gctx,
176            enabled,
177            report_html,
178            report_json,
179            start,
180            start_str,
181            root_targets,
182            profile,
183            total_fresh: 0,
184            total_dirty: 0,
185            unit_to_index: bcx.unit_to_index.clone(),
186            unit_times: Vec::new(),
187            active: HashMap::new(),
188            last_cpu_state,
189            last_cpu_recording: Instant::now(),
190            cpu_usage: Vec::new(),
191        }
192    }
193
194    /// Mark that a unit has started running.
195    pub fn unit_start(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, unit: Unit) {
196        if !self.enabled {
197            return;
198        }
199        let mut target = if unit.target.is_lib() && unit.mode == CompileMode::Build {
200            // Special case for brevity, since most dependencies hit
201            // this path.
202            "".to_string()
203        } else {
204            format!(" {}", unit.target.description_named())
205        };
206        match unit.mode {
207            CompileMode::Test => target.push_str(" (test)"),
208            CompileMode::Build => {}
209            CompileMode::Check { test: true } => target.push_str(" (check-test)"),
210            CompileMode::Check { test: false } => target.push_str(" (check)"),
211            CompileMode::Doc { .. } => target.push_str(" (doc)"),
212            CompileMode::Doctest => target.push_str(" (doc test)"),
213            CompileMode::Docscrape => target.push_str(" (doc scrape)"),
214            CompileMode::RunCustomBuild => target.push_str(" (run)"),
215        }
216        let start = self.start.elapsed().as_secs_f64();
217        let unit_time = UnitTime {
218            unit,
219            target,
220            start,
221            duration: 0.0,
222            rmeta_time: None,
223            unblocked_units: Vec::new(),
224            unblocked_rmeta_units: Vec::new(),
225            sections: Default::default(),
226        };
227        if let Some(logger) = build_runner.bcx.logger {
228            logger.log(LogMessage::UnitStarted {
229                index: self.unit_to_index[&unit_time.unit],
230                elapsed: start,
231            });
232        }
233        assert!(self.active.insert(id, unit_time).is_none());
234    }
235
236    /// Mark that the `.rmeta` file as generated.
237    pub fn unit_rmeta_finished(
238        &mut self,
239        build_runner: &BuildRunner<'_, '_>,
240        id: JobId,
241        unblocked: Vec<&Unit>,
242    ) {
243        if !self.enabled {
244            return;
245        }
246        // `id` may not always be active. "fresh" units unconditionally
247        // generate `Message::Finish`, but this active map only tracks dirty
248        // units.
249        let Some(unit_time) = self.active.get_mut(&id) else {
250            return;
251        };
252        let elapsed = self.start.elapsed().as_secs_f64();
253        unit_time.rmeta_time = Some(elapsed - unit_time.start);
254        assert!(unit_time.unblocked_rmeta_units.is_empty());
255        unit_time
256            .unblocked_rmeta_units
257            .extend(unblocked.iter().cloned().cloned());
258
259        if let Some(logger) = build_runner.bcx.logger {
260            let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
261            logger.log(LogMessage::UnitRmetaFinished {
262                index: self.unit_to_index[&unit_time.unit],
263                elapsed,
264                unblocked,
265            });
266        }
267    }
268
269    /// Mark that a unit has finished running.
270    pub fn unit_finished(
271        &mut self,
272        build_runner: &BuildRunner<'_, '_>,
273        id: JobId,
274        unblocked: Vec<&Unit>,
275    ) {
276        if !self.enabled {
277            return;
278        }
279        // See note above in `unit_rmeta_finished`, this may not always be active.
280        let Some(mut unit_time) = self.active.remove(&id) else {
281            return;
282        };
283        let elapsed = self.start.elapsed().as_secs_f64();
284        unit_time.duration = elapsed - unit_time.start;
285        assert!(unit_time.unblocked_units.is_empty());
286        unit_time
287            .unblocked_units
288            .extend(unblocked.iter().cloned().cloned());
289        if self.report_json {
290            let msg = machine_message::TimingInfo {
291                package_id: unit_time.unit.pkg.package_id().to_spec(),
292                target: &unit_time.unit.target,
293                mode: unit_time.unit.mode,
294                duration: unit_time.duration,
295                rmeta_time: unit_time.rmeta_time,
296                sections: unit_time.sections.clone().into_iter().collect(),
297            }
298            .to_json_string();
299            crate::drop_println!(self.gctx, "{}", msg);
300        }
301        if let Some(logger) = build_runner.bcx.logger {
302            let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
303            logger.log(LogMessage::UnitFinished {
304                index: self.unit_to_index[&unit_time.unit],
305                elapsed,
306                unblocked,
307            });
308        }
309        self.unit_times.push(unit_time);
310    }
311
312    /// Handle the start/end of a compilation section.
313    pub fn unit_section_timing(
314        &mut self,
315        build_runner: &BuildRunner<'_, '_>,
316        id: JobId,
317        section_timing: &SectionTiming,
318    ) {
319        if !self.enabled {
320            return;
321        }
322        let Some(unit_time) = self.active.get_mut(&id) else {
323            return;
324        };
325        let elapsed = self.start.elapsed().as_secs_f64();
326
327        match section_timing.event {
328            SectionTimingEvent::Start => {
329                unit_time.start_section(&section_timing.name, elapsed);
330            }
331            SectionTimingEvent::End => {
332                unit_time.end_section(&section_timing.name, elapsed);
333            }
334        }
335
336        if let Some(logger) = build_runner.bcx.logger {
337            let index = self.unit_to_index[&unit_time.unit];
338            let section = section_timing.name.clone();
339            logger.log(match section_timing.event {
340                SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
341                    index,
342                    elapsed,
343                    section,
344                },
345                SectionTimingEvent::End => LogMessage::UnitSectionFinished {
346                    index,
347                    elapsed,
348                    section,
349                },
350            })
351        }
352    }
353
354    /// Mark that a fresh unit was encountered. (No re-compile needed)
355    pub fn add_fresh(&mut self) {
356        self.total_fresh += 1;
357    }
358
359    /// Mark that a dirty unit was encountered. (Re-compile needed)
360    pub fn add_dirty(&mut self) {
361        self.total_dirty += 1;
362    }
363
364    /// Take a sample of CPU usage
365    pub fn record_cpu(&mut self) {
366        if !self.enabled {
367            return;
368        }
369        let Some(prev) = &mut self.last_cpu_state else {
370            return;
371        };
372        // Don't take samples too frequently, even if requested.
373        let now = Instant::now();
374        if self.last_cpu_recording.elapsed() < Duration::from_millis(100) {
375            return;
376        }
377        let current = match State::current() {
378            Ok(s) => s,
379            Err(e) => {
380                tracing::info!("failed to get CPU state: {:?}", e);
381                return;
382            }
383        };
384        let pct_idle = current.idle_since(prev);
385        *prev = current;
386        self.last_cpu_recording = now;
387        let dur = now.duration_since(self.start).as_secs_f64();
388        self.cpu_usage.push((dur, 100.0 - pct_idle));
389    }
390
391    /// Call this when all units are finished.
392    pub fn finished(
393        &mut self,
394        build_runner: &BuildRunner<'_, '_>,
395        error: &Option<anyhow::Error>,
396    ) -> CargoResult<()> {
397        if !self.enabled {
398            return Ok(());
399        }
400        self.unit_times
401            .sort_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap());
402        if self.report_html {
403            let timestamp = self.start_str.replace(&['-', ':'][..], "");
404            let timings_path = build_runner
405                .files()
406                .timings_dir()
407                .expect("artifact-dir was not locked");
408            paths::create_dir_all(&timings_path)?;
409            let filename = timings_path.join(format!("cargo-timing-{}.html", timestamp));
410            let mut f = BufWriter::new(paths::create(&filename)?);
411
412            let rustc_version = build_runner
413                .bcx
414                .rustc()
415                .verbose_version
416                .lines()
417                .next()
418                .expect("rustc version");
419            let requested_targets = build_runner
420                .bcx
421                .build_config
422                .requested_kinds
423                .iter()
424                .map(|kind| build_runner.bcx.target_data.short_name(kind).to_owned())
425                .collect::<Vec<_>>();
426            let num_cpus = std::thread::available_parallelism()
427                .ok()
428                .map(|x| x.get() as u64);
429
430            let unit_data = report::to_unit_data(&self.unit_times, &self.unit_to_index);
431            let concurrency = report::compute_concurrency(&unit_data);
432
433            let ctx = report::RenderContext {
434                start_str: self.start_str.clone(),
435                root_units: self.root_targets.clone(),
436                profile: self.profile.clone(),
437                total_fresh: self.total_fresh,
438                total_dirty: self.total_dirty,
439                unit_data,
440                concurrency,
441                cpu_usage: &self.cpu_usage,
442                rustc_version: rustc_version.into(),
443                host: build_runner.bcx.rustc().host.to_string(),
444                requested_targets,
445                jobs: build_runner.bcx.jobs(),
446                num_cpus,
447                error,
448            };
449            report::write_html(ctx, &mut f)?;
450
451            let unstamped_filename = timings_path.join("cargo-timing.html");
452            paths::link_or_copy(&filename, &unstamped_filename)?;
453
454            let mut shell = self.gctx.shell();
455            let timing_path = std::env::current_dir().unwrap_or_default().join(&filename);
456            let link = shell.err_file_hyperlink(&timing_path);
457            let msg = format!("report saved to {link}{}{link:#}", timing_path.display(),);
458            shell.status_with_color("Timing", msg, &style::NOTE)?;
459        }
460        Ok(())
461    }
462}
463
464impl UnitTime {
465    fn start_section(&mut self, name: &str, now: f64) {
466        if self
467            .sections
468            .insert(
469                name.to_string(),
470                CompilationSection {
471                    start: now - self.start,
472                    end: None,
473                },
474            )
475            .is_some()
476        {
477            warn!("compilation section {name} started more than once");
478        }
479    }
480
481    fn end_section(&mut self, name: &str, now: f64) {
482        let Some(section) = self.sections.get_mut(name) else {
483            warn!("compilation section {name} ended, but it has no start recorded");
484            return;
485        };
486        section.end = Some(now - self.start);
487    }
488}
489
490/// Start or end of a section timing.
491#[derive(serde::Deserialize, Debug)]
492#[serde(rename_all = "kebab-case")]
493pub enum SectionTimingEvent {
494    Start,
495    End,
496}
497
498/// Represents a certain section (phase) of rustc compilation.
499/// It is emitted by rustc when the `--json=timings` flag is used.
500#[derive(serde::Deserialize, Debug)]
501pub struct SectionTiming {
502    pub name: String,
503    pub event: SectionTimingEvent,
504}
cargo/core/compiler/timings/mod.rs

cargo/core/compiler/timings/
mod.rs
