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

cargo/core/compiler/timings/
mod.rs
