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;
9use super::Unit;
10use super::UnitIndex;
11use crate::core::PackageId;
12use crate::core::compiler::BuildContext;
13use crate::core::compiler::BuildRunner;
14use crate::core::compiler::job_queue::JobId;
15use crate::util::cpu::State;
16use crate::util::log_message::LogMessage;
17use crate::util::style;
18use crate::util::{CargoResult, GlobalContext};
19
20use cargo_util::paths;
21use indexmap::IndexMap;
22use std::collections::HashMap;
23use std::io::BufWriter;
24use std::time::{Duration, Instant};
25use tracing::warn;
26
27/// Tracking information for the entire build.
28///
29/// Methods on this structure are generally called from the main thread of a
30/// running [`JobQueue`] instance (`DrainState` in specific) when the queue
31/// receives messages from spawned off threads.
32///
33/// [`JobQueue`]: super::JobQueue
34pub struct Timings<'gctx> {
35    gctx: &'gctx GlobalContext,
36    /// Whether or not timings should be captured.
37    enabled: bool,
38    /// If true, saves an HTML report to disk.
39    report_html: 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, UnitIndex>,
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: UnitIndex,
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<UnitIndex>,
116    pub unblocked_rmeta_units: Vec<UnitIndex>,
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 report_html = bcx.build_config.timing_report;
124        let enabled = report_html | bcx.logger.is_some();
125
126        if !enabled {
127            return Timings {
128                gctx: bcx.gctx,
129                enabled,
130                report_html,
131                start,
132                start_str: String::new(),
133                root_targets: Vec::new(),
134                profile: String::new(),
135                total_fresh: 0,
136                total_dirty: 0,
137                unit_to_index: HashMap::new(),
138                unit_times: Vec::new(),
139                active: HashMap::new(),
140                last_cpu_state: None,
141                last_cpu_recording: Instant::now(),
142                cpu_usage: Vec::new(),
143            };
144        }
145
146        let mut root_map: HashMap<PackageId, Vec<String>> = HashMap::new();
147        for unit in root_units {
148            let target_desc = unit.target.description_named();
149            root_map
150                .entry(unit.pkg.package_id())
151                .or_default()
152                .push(target_desc);
153        }
154        let root_targets = root_map
155            .into_iter()
156            .map(|(pkg_id, targets)| {
157                let pkg_desc = format!("{} {}", pkg_id.name(), pkg_id.version());
158                (pkg_desc, targets)
159            })
160            .collect();
161        let start_str = jiff::Timestamp::now().to_string();
162        let profile = bcx.build_config.requested_profile.to_string();
163        let last_cpu_state = match State::current() {
164            Ok(state) => Some(state),
165            Err(e) => {
166                tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e);
167                None
168            }
169        };
170
171        Timings {
172            gctx: bcx.gctx,
173            enabled,
174            report_html,
175            start,
176            start_str,
177            root_targets,
178            profile,
179            total_fresh: 0,
180            total_dirty: 0,
181            unit_to_index: bcx.unit_to_index.clone(),
182            unit_times: Vec::new(),
183            active: HashMap::new(),
184            last_cpu_state,
185            last_cpu_recording: Instant::now(),
186            cpu_usage: Vec::new(),
187        }
188    }
189
190    /// Mark that a unit has started running.
191    pub fn unit_start(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, unit: Unit) {
192        if !self.enabled {
193            return;
194        }
195        let mut target = if unit.target.is_lib()
196            && matches!(unit.mode, CompileMode::Build | CompileMode::Check { .. })
197        {
198            // Special case for brevity, since most dependencies hit this path.
199            "".to_string()
200        } else {
201            format!(" {}", unit.target.description_named())
202        };
203        match unit.mode {
204            CompileMode::Test => target.push_str(" (test)"),
205            CompileMode::Build => {}
206            CompileMode::Check { test: true } => target.push_str(" (check-test)"),
207            CompileMode::Check { test: false } => target.push_str(" (check)"),
208            CompileMode::Doc { .. } => target.push_str(" (doc)"),
209            CompileMode::Doctest => target.push_str(" (doc test)"),
210            CompileMode::Docscrape => target.push_str(" (doc scrape)"),
211            CompileMode::RunCustomBuild => target.push_str(" (run)"),
212        }
213        let start = self.start.elapsed().as_secs_f64();
214        let unit_time = UnitTime {
215            unit,
216            target,
217            start,
218            duration: 0.0,
219            rmeta_time: None,
220            unblocked_units: Vec::new(),
221            unblocked_rmeta_units: Vec::new(),
222            sections: Default::default(),
223        };
224        if let Some(logger) = build_runner.bcx.logger {
225            logger.log(LogMessage::UnitStarted {
226                index: self.unit_to_index[&unit_time.unit],
227                elapsed: start,
228            });
229        }
230        assert!(self.active.insert(id, unit_time).is_none());
231    }
232
233    /// Mark that the `.rmeta` file as generated.
234    pub fn unit_rmeta_finished(
235        &mut self,
236        build_runner: &BuildRunner<'_, '_>,
237        id: JobId,
238        unblocked: Vec<&Unit>,
239    ) {
240        if !self.enabled {
241            return;
242        }
243        // `id` may not always be active. "fresh" units unconditionally
244        // generate `Message::Finish`, but this active map only tracks dirty
245        // units.
246        let Some(unit_time) = self.active.get_mut(&id) else {
247            return;
248        };
249        let elapsed = self.start.elapsed().as_secs_f64();
250        unit_time.rmeta_time = Some(elapsed - unit_time.start);
251        assert!(unit_time.unblocked_rmeta_units.is_empty());
252        unit_time
253            .unblocked_rmeta_units
254            .extend(unblocked.iter().cloned().cloned());
255
256        if let Some(logger) = build_runner.bcx.logger {
257            let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
258            logger.log(LogMessage::UnitRmetaFinished {
259                index: self.unit_to_index[&unit_time.unit],
260                elapsed,
261                unblocked,
262            });
263        }
264    }
265
266    /// Mark that a unit has finished running.
267    pub fn unit_finished(
268        &mut self,
269        build_runner: &BuildRunner<'_, '_>,
270        id: JobId,
271        unblocked: Vec<&Unit>,
272    ) {
273        if !self.enabled {
274            return;
275        }
276        // See note above in `unit_rmeta_finished`, this may not always be active.
277        let Some(mut unit_time) = self.active.remove(&id) else {
278            return;
279        };
280        let elapsed = self.start.elapsed().as_secs_f64();
281        unit_time.duration = elapsed - unit_time.start;
282        assert!(unit_time.unblocked_units.is_empty());
283        unit_time
284            .unblocked_units
285            .extend(unblocked.iter().cloned().cloned());
286
287        if let Some(logger) = build_runner.bcx.logger {
288            let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
289            logger.log(LogMessage::UnitFinished {
290                index: self.unit_to_index[&unit_time.unit],
291                elapsed,
292                unblocked,
293            });
294        }
295        self.unit_times.push(unit_time);
296    }
297
298    /// Handle the start/end of a compilation section.
299    pub fn unit_section_timing(
300        &mut self,
301        build_runner: &BuildRunner<'_, '_>,
302        id: JobId,
303        section_timing: &SectionTiming,
304    ) {
305        if !self.enabled {
306            return;
307        }
308        let Some(unit_time) = self.active.get_mut(&id) else {
309            return;
310        };
311        let elapsed = self.start.elapsed().as_secs_f64();
312
313        match section_timing.event {
314            SectionTimingEvent::Start => {
315                unit_time.start_section(&section_timing.name, elapsed);
316            }
317            SectionTimingEvent::End => {
318                unit_time.end_section(&section_timing.name, elapsed);
319            }
320        }
321
322        if let Some(logger) = build_runner.bcx.logger {
323            let index = self.unit_to_index[&unit_time.unit];
324            let section = section_timing.name.clone();
325            logger.log(match section_timing.event {
326                SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
327                    index,
328                    elapsed,
329                    section,
330                },
331                SectionTimingEvent::End => LogMessage::UnitSectionFinished {
332                    index,
333                    elapsed,
334                    section,
335                },
336            })
337        }
338    }
339
340    /// Mark that a fresh unit was encountered. (No re-compile needed)
341    pub fn add_fresh(&mut self) {
342        self.total_fresh += 1;
343    }
344
345    /// Mark that a dirty unit was encountered. (Re-compile needed)
346    pub fn add_dirty(&mut self) {
347        self.total_dirty += 1;
348    }
349
350    /// Take a sample of CPU usage
351    pub fn record_cpu(&mut self) {
352        if !self.enabled {
353            return;
354        }
355        let Some(prev) = &mut self.last_cpu_state else {
356            return;
357        };
358        // Don't take samples too frequently, even if requested.
359        let now = Instant::now();
360        if self.last_cpu_recording.elapsed() < Duration::from_millis(100) {
361            return;
362        }
363        let current = match State::current() {
364            Ok(s) => s,
365            Err(e) => {
366                tracing::info!("failed to get CPU state: {:?}", e);
367                return;
368            }
369        };
370        let pct_idle = current.idle_since(prev);
371        *prev = current;
372        self.last_cpu_recording = now;
373        let dur = now.duration_since(self.start).as_secs_f64();
374        self.cpu_usage.push((dur, 100.0 - pct_idle));
375    }
376
377    /// Call this when all units are finished.
378    pub fn finished(
379        &mut self,
380        build_runner: &BuildRunner<'_, '_>,
381        error: &Option<anyhow::Error>,
382    ) -> CargoResult<()> {
383        if !self.enabled {
384            return Ok(());
385        }
386        self.unit_times
387            .sort_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap());
388        if self.report_html {
389            let timestamp = self.start_str.replace(&['-', ':'][..], "");
390            let timings_path = build_runner
391                .files()
392                .timings_dir()
393                .expect("artifact-dir was not locked");
394            paths::create_dir_all(&timings_path)?;
395            let filename = timings_path.join(format!("cargo-timing-{}.html", timestamp));
396            let mut f = BufWriter::new(paths::create(&filename)?);
397
398            let rustc_version = build_runner
399                .bcx
400                .rustc()
401                .verbose_version
402                .lines()
403                .next()
404                .expect("rustc version");
405            let requested_targets = build_runner
406                .bcx
407                .build_config
408                .requested_kinds
409                .iter()
410                .map(|kind| build_runner.bcx.target_data.short_name(kind).to_owned())
411                .collect::<Vec<_>>();
412            let num_cpus = std::thread::available_parallelism()
413                .ok()
414                .map(|x| x.get() as u64);
415
416            let unit_data = report::to_unit_data(&self.unit_times, &self.unit_to_index);
417            let concurrency = report::compute_concurrency(&unit_data);
418
419            let ctx = report::RenderContext {
420                start_str: self.start_str.clone(),
421                root_units: self.root_targets.clone(),
422                profile: self.profile.clone(),
423                total_fresh: self.total_fresh,
424                total_dirty: self.total_dirty,
425                unit_data,
426                concurrency,
427                cpu_usage: &self.cpu_usage,
428                rustc_version: rustc_version.into(),
429                host: build_runner.bcx.rustc().host.to_string(),
430                requested_targets,
431                jobs: build_runner.bcx.jobs(),
432                num_cpus,
433                error,
434            };
435            report::write_html(ctx, &mut f)?;
436
437            let unstamped_filename = timings_path.join("cargo-timing.html");
438            paths::link_or_copy(&filename, &unstamped_filename)?;
439
440            let mut shell = self.gctx.shell();
441            let timing_path = std::env::current_dir().unwrap_or_default().join(&filename);
442            let link = shell.err_file_hyperlink(&timing_path);
443            let msg = format!("report saved to {link}{}{link:#}", timing_path.display(),);
444            shell.status_with_color("Timing", msg, &style::NOTE)?;
445        }
446        Ok(())
447    }
448}
449
450impl UnitTime {
451    fn start_section(&mut self, name: &str, now: f64) {
452        if self
453            .sections
454            .insert(
455                name.to_string(),
456                CompilationSection {
457                    start: now - self.start,
458                    end: None,
459                },
460            )
461            .is_some()
462        {
463            warn!("compilation section {name} started more than once");
464        }
465    }
466
467    fn end_section(&mut self, name: &str, now: f64) {
468        let Some(section) = self.sections.get_mut(name) else {
469            warn!("compilation section {name} ended, but it has no start recorded");
470            return;
471        };
472        section.end = Some(now - self.start);
473    }
474}
475
476/// Start or end of a section timing.
477#[derive(serde::Deserialize, Debug)]
478#[serde(rename_all = "kebab-case")]
479pub enum SectionTimingEvent {
480    Start,
481    End,
482}
483
484/// Represents a certain section (phase) of rustc compilation.
485/// It is emitted by rustc when the `--json=timings` flag is used.
486#[derive(serde::Deserialize, Debug)]
487pub struct SectionTiming {
488    pub name: String,
489    pub event: SectionTimingEvent,
490}
cargo/core/compiler/timings/mod.rs

cargo/core/compiler/timings/
mod.rs
