#
cargo/ops/cargo_report/
timings.rs

    1//! The `cargo report timings` command.
    2
    3use std::collections::HashSet;
    4use std::fs::File;
    5use std::io::BufReader;
    6use std::path::Path;
    7use std::path::PathBuf;
    8
    9use annotate_snippets::Level;
    10use anyhow::Context as _;
    11use cargo_util::paths;
    12use indexmap::IndexMap;
    13use indexmap::map::Entry;
    14use itertools::Itertools as _;
    15use tempfile::TempDir;
    16
    17use crate::AlreadyPrintedError;
    18use crate::CargoResult;
    19use crate::GlobalContext;
    20use crate::core::Workspace;
    21use crate::core::compiler::UnitIndex;
    22use crate::core::compiler::timings::CompilationSection;
    23use crate::core::compiler::timings::UnitData;
    24use crate::core::compiler::timings::report::RenderContext;
    25use crate::core::compiler::timings::report::aggregate_sections;
    26use crate::core::compiler::timings::report::compute_concurrency;
    27use crate::core::compiler::timings::report::round_to_centisecond;
    28use crate::core::compiler::timings::report::write_html;
    29use crate::ops::cargo_report::util::find_log_file;
    30use crate::ops::cargo_report::util::unit_target_description;
    31use crate::util::log_message::FingerprintStatus;
    32use crate::util::log_message::LogMessage;
    33use crate::util::log_message::Target;
    34use crate::util::logger::RunId;
    35use crate::util::style;
    36
    37pub struct ReportTimingsOptions<'gctx> {
    38    /// Whether to attempt to open the browser after the report is generated
    39    pub open_result: bool,
    40    pub gctx: &'gctx GlobalContext,
    41    pub id: Option<RunId>,
    42}
    43
    44/// Collects sections data for later post-processing through [`aggregate_sections`].
    45struct UnitEntry {
    46    target: Target,
    47    data: UnitData,
    48    sections: IndexMap<String, CompilationSection>,
    49    rmeta_time: Option<f64>,
    50}
    51
    52pub fn report_timings(
    53    gctx: &GlobalContext,
    54    ws: Option<&Workspace<'_>>,
    55    opts: ReportTimingsOptions<'_>,
    56) -> CargoResult<()> {
    57    let Some((log, run_id)) = find_log_file(gctx, ws, opts.id.as_ref())? else {
    58        let context = if let Some(ws) = ws {
    59            format!(" for workspace at `{}`", ws.root().display())
    60        } else {
    61            String::new()
    62        };
    63        let (title, note) = if let Some(id) = &opts.id {
    64            (
    65                format!("session `{id}` not found{context}"),
    66                "run `cargo report sessions` to list available sessions",
    67            )
    68        } else {
    69            (
    70                format!("no sessions found{context}"),
    71                "run command with `-Z build-analysis` to generate log files",
    72            )
    73        };
    74        let report = [Level::ERROR
    75            .primary_title(title)
    76            .element(Level::NOTE.message(note))];
    77        gctx.shell().print_report(&report, false)?;
    78        return Err(AlreadyPrintedError::new(anyhow::anyhow!("")).into());
    79    };
    80
    81    let ctx = prepare_context(&log, &run_id)
    82        .with_context(|| format!("failed to analyze log at `{}`", log.display()))?;
    83
    84    // If we are in a workspace,
    85    // put timing reports in <target-dir>/cargo-timings/` as usual for easy access.
    86    // Otherwise in a temporary directory
    87    let reports_dir = if let Some(ws) = ws {
    88        let target_dir = ws.target_dir();
    89        let target_dir = target_dir.as_path_unlocked();
    90        paths::create_dir_all_excluded_from_backups_atomic(target_dir)?;
    91        let timings_dir = target_dir.join("cargo-timings");
    92        paths::create_dir_all(&timings_dir)?;
    93        timings_dir
    94    } else if let Ok(path) = gctx.get_env("__CARGO_TEST_REPORT_TIMINGS_TEMPDIR") {
    95        PathBuf::from(path.to_owned())
    96    } else {
    97        TempDir::with_prefix("cargo-timings-")?.keep()
    98    };
    99
    100    let timing_path = reports_dir.join(format!("cargo-timing-{run_id}.html"));
    101
    102    let mut out_file = std::fs::OpenOptions::new()
    103        .write(true)
    104        .create(true)
    105        .truncate(true)
    106        .open(&timing_path)
    107        .with_context(|| format!("failed to open `{}`", timing_path.display()))?;
    108
    109    write_html(ctx, &mut out_file)?;
    110
    111    let link = gctx.shell().err_file_hyperlink(&timing_path);
    112    let msg = format!("report saved to {link}{}{link:#}", timing_path.display());
    113    gctx.shell()
    114        .status_with_color("Timing", msg, &style::NOTE)?;
    115
    116    if opts.open_result {
    117        crate::util::open::open(&timing_path, gctx)?;
    118    }
    119
    120    Ok(())
    121}
    122
    123fn prepare_context(log: &Path, run_id: &RunId) -> CargoResult<RenderContext<'static>> {
    124    let reader = BufReader::new(File::open(&log)?);
    125
    126    let mut ctx = RenderContext {
    127        start_str: run_id.timestamp().to_string(),
    128        root_units: Default::default(),
    129        profile: Default::default(),
    130        total_fresh: Default::default(),
    131        total_dirty: Default::default(),
    132        unit_data: Default::default(),
    133        concurrency: Default::default(),
    134        cpu_usage: Default::default(),
    135        rustc_version: Default::default(),
    136        host: Default::default(),
    137        requested_targets: Default::default(),
    138        jobs: 0,
    139        num_cpus: None,
    140        error: &None,
    141    };
    142    let mut units: IndexMap<_, UnitEntry> = IndexMap::new();
    143
    144    let mut platform_targets = HashSet::new();
    145
    146    let mut requested_units: HashSet<UnitIndex> = HashSet::new();
    147
    148    for (log_index, result) in serde_json::Deserializer::from_reader(reader)
    149        .into_iter::<LogMessage>()
    150        .enumerate()
    151    {
    152        let msg = match result {
    153            Ok(msg) => msg,
    154            Err(e) => {
    155                tracing::warn!("failed to parse log message at index {log_index}: {e}");
    156                continue;
    157            }
    158        };
    159
    160        match msg {
    161            LogMessage::BuildStarted {
    162                cwd: _,
    163                host,
    164                jobs,
    165                num_cpus,
    166                profile,
    167                rustc_version,
    168                rustc_version_verbose,
    169                target_dir: _,
    170                workspace_root: _,
    171            } => {
    172                let rustc_version = rustc_version_verbose
    173                    .lines()
    174                    .next()
    175                    .map(ToOwned::to_owned)
    176                    .unwrap_or(rustc_version);
    177                ctx.host = host;
    178                ctx.jobs = jobs;
    179                ctx.num_cpus = num_cpus;
    180                ctx.profile = profile;
    181                ctx.rustc_version = rustc_version;
    182            }
    183            LogMessage::UnitRegistered {
    184                package_id,
    185                target,
    186                mode,
    187                platform,
    188                index,
    189                features,
    190                requested,
    191                dependencies: _,
    192            } => {
    193                if requested {
    194                    requested_units.insert(index);
    195                }
    196                platform_targets.insert(platform);
    197
    198                let version = package_id
    199                    .version()
    200                    .map(|v| v.to_string())
    201                    .unwrap_or_else(|| "N/A".into());
    202
    203                let target_str = unit_target_description(&target, mode);
    204
    205                let mode_str = if mode.is_run_custom_build() {
    206                    "run-custom-build"
    207                } else {
    208                    "todo"
    209                };
    210
    211                let data = UnitData {
    212                    i: index,
    213                    name: package_id.name().to_string(),
    214                    version,
    215                    mode: mode_str.to_owned(),
    216                    target: target_str,
    217                    features,
    218                    start: 0.0,
    219                    duration: 0.0,
    220                    unblocked_units: Vec::new(),
    221                    unblocked_rmeta_units: Vec::new(),
    222                    sections: None,
    223                };
    224
    225                units.insert(
    226                    index,
    227                    UnitEntry {
    228                        target,
    229                        data,
    230                        sections: IndexMap::new(),
    231                        rmeta_time: None,
    232                    },
    233                );
    234            }
    235            LogMessage::UnitFingerprint { status, .. } => match status {
    236                FingerprintStatus::New => ctx.total_dirty += 1,
    237                FingerprintStatus::Dirty => ctx.total_dirty += 1,
    238                FingerprintStatus::Fresh => ctx.total_fresh += 1,
    239            },
    240            LogMessage::UnitStarted { index, elapsed } => {
    241                units
    242                    .entry(index)
    243                    .and_modify(|unit| unit.data.start = elapsed)
    244                    .or_insert_with(|| {
    245                        unreachable!("unit {index} must have been registered first")
    246                    });
    247            }
    248            LogMessage::UnitRmetaFinished {
    249                index,
    250                elapsed,
    251                unblocked,
    252            } => match units.entry(index) {
    253                Entry::Occupied(mut e) => {
    254                    let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
    255                    e.get_mut().data.unblocked_rmeta_units = unblocked;
    256                    e.get_mut().data.duration = elapsed;
    257                    e.get_mut().rmeta_time = Some(elapsed);
    258                }
    259                Entry::Vacant(_) => {
    260                    tracing::warn!(
    261                        "section `frontend` ended, but unit {index} has no start recorded"
    262                    )
    263                }
    264            },
    265            LogMessage::UnitSectionStarted {
    266                index,
    267                elapsed,
    268                section,
    269            } => match units.entry(index) {
    270                Entry::Occupied(mut e) => {
    271                    let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
    272                    if e.get_mut()
    273                        .sections
    274                        .insert(
    275                            section.clone(),
    276                            CompilationSection {
    277                                start: elapsed,
    278                                end: None,
    279                            },
    280                        )
    281                        .is_some()
    282                    {
    283                        tracing::warn!(
    284                            "section `{section}` for unit {index} started more than once",
    285                        );
    286                    }
    287                }
    288                Entry::Vacant(_) => {
    289                    tracing::warn!(
    290                        "section `{section}` started, but unit {index} has no start recorded"
    291                    )
    292                }
    293            },
    294            LogMessage::UnitSectionFinished {
    295                index,
    296                elapsed,
    297                section,
    298            } => match units.entry(index) {
    299                Entry::Occupied(mut e) => {
    300                    let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
    301                    if let Some(section) = e.get_mut().sections.get_mut(&section) {
    302                        section.end = Some(elapsed);
    303                    } else {
    304                        tracing::warn!(
    305                            "section `{section}` for unit {index} ended, but section `{section}` has no start recorded"
    306                        );
    307                    }
    308                }
    309                Entry::Vacant(_) => {
    310                    tracing::warn!(
    311                        "section `{section}` ended, but unit {index} has no start recorded"
    312                    )
    313                }
    314            },
    315            LogMessage::UnitFinished {
    316                index,
    317                elapsed,
    318                unblocked,
    319            } => match units.entry(index) {
    320                Entry::Occupied(mut e) => {
    321                    let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
    322                    e.get_mut().data.duration = elapsed;
    323                    e.get_mut().data.unblocked_units = unblocked;
    324                }
    325                Entry::Vacant(_) => {
    326                    tracing::warn!("unit {index} ended, but it has no start recorded");
    327                }
    328            },
    329            _ => {} // skip non-timing logs
    330        }
    331    }
    332
    333    ctx.root_units = {
    334        let mut root_map: IndexMap<_, Vec<_>> = IndexMap::new();
    335        for index in requested_units {
    336            let unit = &units[&index];
    337            // Pretty much like `core::Target::description_named`
    338            let target_desc = if unit.target.kind == "lib" {
    339                "lib".to_owned()
    340            } else if unit.target.kind == "build-script" {
    341                "build script".to_owned()
    342            } else {
    343                format!(r#" {} "{}""#, unit.target.name, unit.target.kind)
    344            };
    345            root_map.entry(index).or_default().push(target_desc);
    346        }
    347        root_map
    348            .into_iter()
    349            .sorted_by_key(|(i, _)| *i)
    350            .map(|(index, targets)| {
    351                let unit = &units[&index];
    352                let pkg_desc = format!("{} {}", unit.data.name, unit.data.version);
    353                (pkg_desc, targets)
    354            })
    355            .collect()
    356    };
    357
    358    let unit_data: Vec<_> = units
    359        .into_values()
    360        .map(
    361            |UnitEntry {
    362                 target: _,
    363                 mut data,
    364                 sections,
    365                 rmeta_time,
    366             }| {
    367                // Post-processing for compilation sections we've collected so far.
    368                data.sections = aggregate_sections(sections, data.duration, rmeta_time);
    369                data.start = round_to_centisecond(data.start);
    370                data.duration = round_to_centisecond(data.duration);
    371                data
    372            },
    373        )
    374        .sorted_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap())
    375        .collect();
    376
    377    if unit_data.is_empty() {
    378        anyhow::bail!("no timing data found in log");
    379    }
    380
    381    ctx.unit_data = unit_data;
    382    ctx.concurrency = compute_concurrency(&ctx.unit_data);
    383    ctx.requested_targets = platform_targets.into_iter().sorted_unstable().collect();
    384
    385    Ok(ctx)
    386}