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