mod critical_path;
use crate::config::Config;
use crate::events::{ActionOutcome, SessionEvent};
use crate::explain::{
Baselines, RecordedSession, changed_keys, dependencies_behind, dependency_name, guidance,
is_truncated, join_names, previous_recording,
};
use crate::util::format_duration;
use critical_path::CriticalPath;
use eyre::Result;
use mbx_cache_core::ActionDiagnostic;
use std::collections::{BTreeMap, BTreeSet};
use std::fmt::Write as _;
use std::process::ExitCode;
use std::time::Duration;
pub(crate) fn run(config: &Config) -> Result<ExitCode> {
let (target, baselines) = crate::explain::last_recorded(config)?;
print!("{}", Analysis::of(&target, &baselines).text());
Ok(ExitCode::SUCCESS)
}
const EXPECTED_BYPASSES: &[&str] = &[
"compiler-query",
"standard-input",
"cc-compiler-query",
"cc-not-a-compile",
"cc-non-object-output",
];
#[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord)]
pub(crate) enum Cause {
Changed(String),
Settings(Setting),
Unavailable,
Unpredicted,
NoHistory,
FirstBuild,
Bypass(String),
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
pub(crate) enum Setting {
Toolchain,
ActionModel,
Flags,
Environment,
Linker,
Other,
}
enum Own {
Cause(Cause, Vec<String>),
Dependencies(Vec<String>),
}
#[derive(Debug, Default)]
struct Group {
duration_ns: u64,
direct: BTreeMap<String, u64>,
direct_count: u64,
dependents: BTreeMap<String, u64>,
dependent_count: u64,
details: BTreeMap<String, u64>,
}
#[derive(Debug)]
pub(crate) struct Analysis {
command: String,
hits: u64,
verifications: u64,
divergences: u64,
avoided_ns: u64,
uncached_count: u64,
uncached_ns: u64,
groups: BTreeMap<Cause, Group>,
critical: Option<CriticalPath>,
truncated: bool,
baseline_truncated: bool,
}
impl Analysis {
pub(crate) fn of(session: &RecordedSession, baselines: &Baselines) -> Self {
let mut hits = 0;
let mut verifications = 0;
let mut divergences = 0;
let mut avoided_ns = 0u64;
let mut records = Vec::new();
for event in &session.events {
let SessionEvent::Action {
outcome,
crate_name,
duration_ns,
detail,
diagnostic,
..
} = event
else {
continue;
};
let name = crate_name
.clone()
.unwrap_or_else(|| "<unknown crate>".into());
let own = match outcome {
ActionOutcome::Hit => {
hits += 1;
avoided_ns = avoided_ns.saturating_add(detail.avoided_compiler_ns);
continue;
}
ActionOutcome::Verification { matched } => {
verifications += 1;
if !matched {
divergences += 1;
}
continue;
}
ActionOutcome::Unconsulted => {
match (
diagnostic.as_ref(),
previous_recording(baselines, &name, diagnostic.as_ref()),
) {
(Some(current), Some(previous)) if current.action == previous.action => {
Own::Cause(Cause::Unpredicted, Vec::new())
}
(Some(current), Some(previous)) => {
classify_miss(&name, Some(current), Some(previous))
}
_ => Own::Cause(Cause::FirstBuild, Vec::new()),
}
}
ActionOutcome::Bypass { reason } => {
Own::Cause(Cause::Bypass(reason.clone()), Vec::new())
}
ActionOutcome::Miss => classify_miss(
&name,
diagnostic.as_ref(),
previous_recording(baselines, &name, diagnostic.as_ref()),
),
};
records.push((name, *duration_ns, own));
}
let mut verdicts: BTreeMap<&str, &Own> = BTreeMap::new();
let mut own_time: BTreeMap<&str, u64> = BTreeMap::new();
for (name, duration_ns, own) in &records {
verdicts.entry(name).or_insert(own);
*own_time.entry(name).or_default() += duration_ns;
}
let mut groups: BTreeMap<Cause, Group> = BTreeMap::new();
let mut uncached_ns = 0u64;
let mut uncached_count = 0u64;
for (name, duration_ns, own) in &records {
if *duration_ns > 0 || !matches!(own, Own::Cause(cause, _) if is_expected(cause)) {
uncached_ns = uncached_ns.saturating_add(*duration_ns);
uncached_count += 1;
}
let (cause, details) = match own {
Own::Cause(cause, details) => (cause.clone(), Some(details)),
Own::Dependencies(dependencies) => {
let mut seen = BTreeSet::from([name.as_str()]);
let mut roots = BTreeSet::new();
for dependency in dependencies {
collect_roots(dependency, &verdicts, &mut seen, &mut roots);
}
let root = roots
.into_iter()
.max_by_key(|root| (own_time.get(root).copied().unwrap_or(0), *root))
.unwrap_or(name.as_str());
(root_cause(root, &verdicts), None)
}
};
let group = groups.entry(cause).or_default();
group.duration_ns = group.duration_ns.saturating_add(*duration_ns);
if let Some(details) = details {
group.direct_count += 1;
*group.direct.entry(name.clone()).or_default() += duration_ns;
for detail in details {
*group.details.entry(detail.clone()).or_default() += 1;
}
} else {
group.dependent_count += 1;
*group.dependents.entry(name.clone()).or_default() += duration_ns;
}
}
Self {
command: if session.command.is_empty() {
"cargo".into()
} else {
format!("cargo {}", session.command.join(" "))
},
hits,
verifications,
divergences,
avoided_ns,
uncached_count,
uncached_ns,
groups,
critical: CriticalPath::of(&session.events),
truncated: is_truncated(session),
baseline_truncated: baselines.truncated,
}
}
pub(crate) fn text(&self) -> String {
let mut out = String::new();
let _ = writeln!(out, "last recorded build: {}", self.command);
let _ = write!(
out,
"compiler time: {} in {} uncached {}",
duration(self.uncached_ns),
self.uncached_count,
plural(self.uncached_count, "compilation", "compilations"),
);
if self.hits > 0 {
let _ = write!(
out,
"; {} {} avoided an estimated {}",
self.hits,
plural(self.hits, "hit", "hits"),
duration(self.avoided_ns),
);
}
if self.verifications > 0 {
let _ = write!(
out,
"; {} {} rebuilt to verify",
self.verifications,
plural(self.verifications, "hit", "hits"),
);
if self.divergences > 0 {
let _ = write!(out, ", {} diverged", self.divergences);
}
}
out.push('\n');
if self.truncated {
let _ = writeln!(
out,
"this build reached the per-session history limit, so only part of it was recorded; raise MBX_EVENTS_MAX_SIZE and build again to analyze all of it"
);
}
let mut ranked: Vec<_> = self
.groups
.iter()
.filter(|(cause, _)| !is_expected(cause))
.collect();
ranked.sort_by(|(left_cause, left), (right_cause, right)| {
right
.duration_ns
.cmp(&left.duration_ns)
.then_with(|| {
(right.direct_count + right.dependent_count)
.cmp(&(left.direct_count + left.dependent_count))
})
.then_with(|| left_cause.cmp(right_cause))
});
if self.divergences > 0 {
let _ = writeln!(
out,
"\nwarning: {} verified {} did not match {} cached result: the rebuild failed or produced different output",
self.divergences,
plural(self.divergences, "hit", "hits"),
plural(self.divergences, "its", "their"),
);
for line in wrap(
"The build printed the details as warnings, which this history does not keep. Rebuilding with MBX_VERIFY=1 in a fresh target directory repeats the comparison.",
72,
) {
let _ = writeln!(out, " {line}");
}
}
let restored = self.hits + self.verifications;
if ranked.is_empty() && restored == 0 && self.uncached_count == 0 {
let _ = writeln!(
out,
"\nnothing was compiled or restored; Cargo found every unit up to date"
);
} else if ranked.is_empty() && restored == 0 {
let _ = writeln!(
out,
"\nnothing was restored; only work with nothing to cache ran"
);
} else if ranked.is_empty() {
let _ = writeln!(out, "\nevery compilation that could be cached was restored");
} else {
let _ = writeln!(out, "\nuncached compiler time by cause");
for (cause, group) in ranked {
self.write_group(&mut out, cause, group);
}
}
if let Some(critical) = &self.critical {
write_critical_path(&mut out, critical);
}
let expected: Vec<_> = self
.groups
.iter()
.filter(|(cause, _)| is_expected(cause))
.collect();
if !expected.is_empty() {
let summary = expected
.iter()
.map(|(cause, group)| {
let Cause::Bypass(reason) = cause else {
unreachable!("only bypasses are expected");
};
format!("{reason} ({})", group.direct_count)
})
.collect::<Vec<_>>()
.join(", ");
let _ = writeln!(out, "\nexpected, nothing to cache: {summary}");
}
out
}
fn write_group(&self, out: &mut String, cause: &Cause, group: &Group) {
let count = group.direct_count + group.dependent_count;
let time = if group.duration_ns == 0 {
" -".to_string()
} else {
format!("{:>7}", duration(group.duration_ns))
};
let _ = writeln!(out, "\n{time} {} ({count})", title(cause));
let indent = " ";
if group.duration_ns == 0 {
let _ = writeln!(
out,
"{indent}compiler time was not recorded for these compilations"
);
}
if !group.details.is_empty() {
let mut details: Vec<_> = group.details.iter().collect();
details.sort_by(|left, right| right.1.cmp(left.1).then_with(|| left.0.cmp(right.0)));
let details = details
.into_iter()
.map(|(detail, count)| format!("{detail} ({count})"))
.collect::<Vec<_>>()
.join(", ");
let _ = writeln!(out, "{indent}changed: {details}");
}
if !group.direct.is_empty() {
let _ = writeln!(out, "{indent}{}", top_crates(&group.direct));
}
if group.dependent_count > 0 {
let (subject, verb) = if group.dependent_count == 1 {
("crate", "depends")
} else {
("crates", "depend")
};
let _ = writeln!(
out,
"{indent}then {} {subject} that {verb} on it rebuilt: {}",
group.dependent_count,
top_crates(&group.dependents),
);
}
if let Some(advice) = advice(cause, group, self.baseline_truncated) {
for line in wrap(&advice, 72) {
let _ = writeln!(out, "{indent}{line}");
}
}
}
}
fn write_critical_path(out: &mut String, critical: &CriticalPath) {
let micros = |us: u64| duration(us.saturating_mul(1_000));
let share = critical
.path_us
.saturating_mul(100)
.checked_div(critical.span_us)
.unwrap_or(100);
let _ = writeln!(
out,
"\ncritical path: {}, {share}% of the {} between the first unit starting and the last finishing",
micros(critical.path_us),
micros(critical.span_us),
);
let threshold = critical.path_us / 100;
let mut folded = (0u64, 0u64);
let flush = |out: &mut String, folded: &mut (u64, u64)| {
if folded.0 > 0 {
let _ = writeln!(
out,
"{:>7} {} shorter {}",
micros(folded.1),
folded.0,
plural(folded.0, "step", "steps"),
);
*folded = (0, 0);
}
};
for step in &critical.steps {
if step.span_us < threshold {
folded.0 += 1;
folded.1 += step.span_us;
continue;
}
flush(out, &mut folded);
let waited = if step.waited_us > 0 && step.waited_us * 10 >= step.span_us {
format!(", {} of it waiting to start", micros(step.waited_us))
} else {
String::new()
};
let _ = writeln!(out, "{:>7} {}{waited}", micros(step.span_us), step.label);
}
flush(out, &mut folded);
let indent = " ";
for line in wrap(
"The build could not finish sooner than this chain; other work overlapped with it. Shortening a step, or removing a dependency between two steps, shortens the build.",
72,
) {
let _ = writeln!(out, "{indent}{line}");
}
if critical.alone_us > 0 {
let names: Vec<_> = critical
.alone
.iter()
.take(3)
.map(|(label, us)| format!("{label} {}", micros(*us)))
.collect();
let _ = writeln!(
out,
"\nonly one recorded unit running for {}: {}",
micros(critical.alone_us),
join_names(&names),
);
}
}
fn classify_miss(
name: &str,
current: Option<&ActionDiagnostic>,
previous: Option<&ActionDiagnostic>,
) -> Own {
let (Some(current), Some(previous)) = (current, previous) else {
return Own::Cause(Cause::NoHistory, Vec::new());
};
if previous.action == current.action {
return Own::Cause(Cause::Unavailable, Vec::new());
}
let components = changed_keys(&previous.components, ¤t.components);
let inputs = changed_keys(&previous.inputs, ¤t.inputs);
let settings: Vec<_> = components
.into_iter()
.filter(|name| !follows_dependencies(name))
.collect();
if !settings.is_empty() {
let (setting, details) = setting(&settings);
return Own::Cause(Cause::Settings(setting), details);
}
if inputs.iter().any(|path| dependency_name(path).is_none()) {
return Own::Cause(Cause::Changed(name.to_string()), Vec::new());
}
let dependencies = dependencies_behind(&inputs);
if !dependencies.is_empty() {
return Own::Dependencies(dependencies);
}
Own::Cause(Cause::Settings(Setting::Other), Vec::new())
}
fn follows_dependencies(component: &str) -> bool {
[
"argument --extern",
"argument --L",
"argument --C metadata",
"argument --C extra-filename",
"argument --codegen metadata",
"argument --codegen extra-filename",
]
.iter()
.any(|prefix| component.starts_with(prefix))
}
fn setting(components: &[String]) -> (Setting, Vec<String>) {
if components.iter().any(|name| name.starts_with("compiler ")) {
return (Setting::Toolchain, Vec::new());
}
if components.iter().any(|name| name == "action model") {
return (Setting::ActionModel, Vec::new());
}
let flags: BTreeSet<_> = components
.iter()
.filter(|name| !follows_dependencies(name))
.filter_map(|name| name.strip_prefix("argument "))
.map(|flag| {
let flag = flag.split(" #").next().unwrap_or(flag);
if flag.starts_with('#') {
return "argument values".to_string();
}
for (long, short) in [("--C ", "-C "), ("--codegen ", "-C "), ("--Z ", "-Z ")] {
if let Some(name) = flag.strip_prefix(long) {
return format!("{short}{name}");
}
}
flag.to_string()
})
.collect();
if !flags.is_empty() {
return (Setting::Flags, flags.into_iter().collect());
}
let environment: Vec<_> = components
.iter()
.filter_map(|name| name.strip_prefix("environment "))
.map(str::to_string)
.collect();
if !environment.is_empty() {
return (Setting::Environment, environment);
}
if components.iter().any(|name| name.starts_with("linker ")) {
return (Setting::Linker, Vec::new());
}
(Setting::Other, components.to_vec())
}
fn collect_roots<'a>(
name: &'a str,
verdicts: &BTreeMap<&'a str, &'a Own>,
seen: &mut BTreeSet<&'a str>,
roots: &mut BTreeSet<&'a str>,
) {
match verdicts.get(name) {
Some(Own::Dependencies(dependencies)) => {
if seen.insert(name) {
for dependency in dependencies {
collect_roots(dependency, verdicts, seen, roots);
}
}
}
_ => {
roots.insert(name);
}
}
}
fn root_cause(root: &str, verdicts: &BTreeMap<&str, &Own>) -> Cause {
match verdicts.get(root) {
Some(Own::Cause(cause, _)) => cause.clone(),
_ => Cause::Changed(root.to_string()),
}
}
fn is_expected(cause: &Cause) -> bool {
matches!(cause, Cause::Bypass(reason) if EXPECTED_BYPASSES.contains(&reason.as_str()))
}
fn title(cause: &Cause) -> String {
match cause {
Cause::Changed(name) => format!("inputs of {name} changed"),
Cause::Settings(Setting::Toolchain) => "the Rust toolchain changed".into(),
Cause::Settings(Setting::ActionModel) => "the mbx key format changed".into(),
Cause::Settings(Setting::Flags) => "compiler arguments changed".into(),
Cause::Settings(Setting::Environment) => "environment changed".into(),
Cause::Settings(Setting::Linker) => "the linker changed".into(),
Cause::Settings(Setting::Other) => "other key details changed".into(),
Cause::Unavailable => "results missing for keys built before".into(),
Cause::Unpredicted => "keys built before, but not looked up".into(),
Cause::NoHistory => "misses with no earlier recording".into(),
Cause::FirstBuild => "first build of these compilations".into(),
Cause::Bypass(reason) => format!("not cacheable: {reason}"),
}
}
fn advice(cause: &Cause, group: &Group, baseline_truncated: bool) -> Option<String> {
let advice = match cause {
Cause::Changed(name) if group.dependent_count > 0 => format!(
"Every crate that depends on {name} recompiled after it changed. Code that changes often costs less in a crate few others depend on."
),
Cause::Changed(_) => return None,
Cause::Settings(Setting::Toolchain) => "Every key includes the compiler, so a toolchain change rebuilds each crate once. A rust-toolchain.toml keeps every checkout and CI job on one toolchain.".into(),
Cause::Settings(Setting::ActionModel) => {
"A new mbx version can change how keys are computed. This is paid once per update.".into()
}
Cause::Settings(Setting::Flags) => "These crates were built with different arguments than their last recording. Commands that differ in RUSTFLAGS, profile, or features keep separate cache entries, so alternating between them rebuilds each time.".into(),
Cause::Settings(Setting::Environment) => "These variables are part of the key. A value that differs between shells, editors, and CI keeps separate cache entries.".into(),
Cause::Settings(Setting::Linker) => {
"A link's key includes its linker. Builds that switch linkers keep separate entries.".into()
}
Cause::Settings(Setting::Other) => "Run `mbx explain --last` to see each crate's changed key details.".into(),
Cause::Unavailable => "These keys were built before, but their results were no longer in the store or on the remote. `mbx gc --dry-run` shows what the store budget keeps.".into(),
Cause::NoHistory if baseline_truncated => "An earlier build stopped recording at the per-session size limit, so its details for these crates may be among the rows it dropped.".into(),
Cause::NoHistory => "No earlier build recorded key details for these crates. The store may be new, its history may have expired, or they were built by another adapter.".into(),
Cause::Unpredicted => "An earlier build produced these exact keys, but this build had no prediction naming them, so it did not look them up. The predictions this build recorded let the next run of the same command find them, except for crates mbx is keeping private incremental state for while you edit them.".into(),
Cause::FirstBuild => "Nothing recorded an earlier build of these crates to compare with, and there was no key to look up. The next build with the same inputs restores them, except for crates mbx is keeping private incremental state for while you edit them.".into(),
Cause::Bypass(reason) => guidance(reason).into(),
};
Some(advice)
}
fn top_crates(crates: &BTreeMap<String, u64>) -> String {
const SHOWN: usize = 3;
let mut ranked: Vec<_> = crates.iter().collect();
ranked.sort_by(|left, right| right.1.cmp(left.1).then_with(|| left.0.cmp(right.0)));
let mut names: Vec<_> = ranked
.iter()
.take(SHOWN)
.map(|(name, duration_ns)| {
if **duration_ns == 0 {
(*name).clone()
} else {
format!("{name} {}", duration(**duration_ns))
}
})
.collect();
if ranked.len() > SHOWN {
names.push(format!("{} more", ranked.len() - SHOWN));
}
join_names(&names)
}
fn duration(nanoseconds: u64) -> String {
format_duration(Duration::from_nanos(nanoseconds))
}
fn plural<'a>(count: u64, one: &'a str, many: &'a str) -> &'a str {
if count == 1 { one } else { many }
}
fn wrap(text: &str, width: usize) -> Vec<String> {
let mut lines = Vec::new();
let mut line = String::new();
for word in text.split_whitespace() {
if !line.is_empty() && line.len() + 1 + word.len() > width {
lines.push(std::mem::take(&mut line));
}
if !line.is_empty() {
line.push(' ');
}
line.push_str(word);
}
if !line.is_empty() {
lines.push(line);
}
lines
}
#[cfg(test)]
#[path = "analyze_tests.rs"]
mod tests;