#
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}