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

cargo/core/compiler/timings/
mod.rs
