Auto merge of #93717 - pietroalbini:pa-ci-profiler, r=Mark-Simulacrum

Add build metrics to rustbuild

This PR adds a new module of rustbuild, `ci_profiler`, whose job is to gather as much information as possible about the CI build as possible and store it in a JSON file uploaded to `ci-artifacts`. Right now for each step it collects:

* Type name and debug representation of the `Step` object.
* Duration of the step (excluding child steps).
* Systemwide CPU stats for the duration of the step (both single core and all cores).
* Which child steps were executed.

This is capable of replacing both the scripts to collect CPU stats and the `[TIMING]` lines in build logs (not yet removed, until we port our tooling to use the CI profiler). The format is also extensible to be able in the future to collect more information.

r? `@Mark-Simulacrum`

Author: bors

Cargo.lock

@@ -223,6 +223,7 @@ dependencies = [
  "pretty_assertions 0.7.2",
  "serde",
  "serde_json",
+ "sysinfo",
  "tar",
  "toml",
  "winapi",
@@ -5126,6 +5127,21 @@ dependencies = [
  "unicode-xid",
 ]
 
+[[package]]
+name = "sysinfo"
+version = "0.24.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6a8e71535da31837213ac114531d31def75d7aebd133264e420a3451fa7f703"
+dependencies = [
+ "cfg-if 1.0.0",
+ "core-foundation-sys",
+ "libc",
+ "ntapi",
+ "once_cell",
+ "rayon",
+ "winapi",
+]
+
 [[package]]
 name = "tar"
 version = "0.4.37"

config.toml.example

@@ -324,6 +324,12 @@ changelog-seen = 2
 # a Nix toolchain on non-NixOS distributions.
 #patch-binaries-for-nix = false
 
+# Collect information and statistics about the current build and writes it to
+# disk. Enabling this or not has no impact on the resulting build output. The
+# schema of the file generated by the build metrics feature is unstable, and
+# this is not intended to be used during local development.
+#metrics = false
+
 # =============================================================================
 # General install configuration options
 # =============================================================================

src/bootstrap/Cargo.toml

@@ -49,6 +49,9 @@ opener = "0.5"
 once_cell = "1.7.2"
 xz2 = "0.1"
 
+# Dependencies needed by the build-metrics feature
+sysinfo = { version = "0.24.1", optional = true }
+
 [target.'cfg(windows)'.dependencies.winapi]
 version = "0.3"
 features = [
@@ -64,3 +67,6 @@ features = [
 
 [dev-dependencies]
 pretty_assertions = "0.7"
+
+[features]
+build-metrics = ["sysinfo"]

src/bootstrap/bootstrap.py

@@ -837,6 +837,9 @@ def build_bootstrap(self):
             args.append("--locked")
         if self.use_vendored_sources:
             args.append("--frozen")
+        if self.get_toml("metrics", "build"):
+            args.append("--features")
+            args.append("build-metrics")
         run(args, env=env, verbose=self.verbose)
 
     def build_triple(self):

src/bootstrap/builder.rs

@@ -2010,6 +2010,9 @@ impl<'a> Builder<'a> {
             stack.push(Box::new(step.clone()));
         }
 
+        #[cfg(feature = "build-metrics")]
+        self.metrics.enter_step(&step);
+
         let (out, dur) = {
             let start = Instant::now();
             let zero = Duration::new(0, 0);
@@ -2033,6 +2036,9 @@ impl<'a> Builder<'a> {
             );
         }
 
+        #[cfg(feature = "build-metrics")]
+        self.metrics.exit_step();
+
         {
             let mut stack = self.stack.borrow_mut();
             let cur_step = stack.pop().expect("step stack empty");

src/bootstrap/config.rs

@@ -550,6 +550,7 @@ define_config! {
         dist_stage: Option<u32> = "dist-stage",
         bench_stage: Option<u32> = "bench-stage",
         patch_binaries_for_nix: Option<bool> = "patch-binaries-for-nix",
+        metrics: Option<bool> = "metrics",
     }
 }
 

src/bootstrap/lib.rs

@@ -150,6 +150,9 @@ mod tool;
 mod toolstate;
 pub mod util;
 
+#[cfg(feature = "build-metrics")]
+mod metrics;
+
 #[cfg(windows)]
 mod job;
 
@@ -312,6 +315,9 @@ pub struct Build {
     prerelease_version: Cell<Option<u32>>,
     tool_artifacts:
         RefCell<HashMap<TargetSelection, HashMap<String, (&'static str, PathBuf, Vec<String>)>>>,
+
+    #[cfg(feature = "build-metrics")]
+    metrics: metrics::BuildMetrics,
 }
 
 #[derive(Debug)]
@@ -501,6 +507,9 @@ impl Build {
             delayed_failures: RefCell::new(Vec::new()),
             prerelease_version: Cell::new(None),
             tool_artifacts: Default::default(),
+
+            #[cfg(feature = "build-metrics")]
+            metrics: metrics::BuildMetrics::init(),
         };
 
         build.verbose("finding compilers");
@@ -695,6 +704,9 @@ impl Build {
             }
             process::exit(1);
         }
+
+        #[cfg(feature = "build-metrics")]
+        self.metrics.persist(self);
     }
 
     /// Clear out `dir` if `input` is newer.

src/bootstrap/metrics.rs

@@ -0,0 +1,208 @@
+//! This module is responsible for collecting metrics profiling information for the current build
+//! and dumping it to disk as JSON, to aid investigations on build and CI performance.
+//!
+//! As this module requires additional dependencies not present during local builds, it's cfg'd
+//! away whenever the `build.metrics` config option is not set to `true`.
+
+use crate::builder::Step;
+use crate::util::t;
+use crate::Build;
+use serde::{Deserialize, Serialize};
+use std::cell::RefCell;
+use std::fs::File;
+use std::io::BufWriter;
+use std::time::{Duration, Instant};
+use sysinfo::{CpuExt, System, SystemExt};
+
+pub(crate) struct BuildMetrics {
+    state: RefCell<MetricsState>,
+}
+
+impl BuildMetrics {
+    pub(crate) fn init() -> Self {
+        let state = RefCell::new(MetricsState {
+            finished_steps: Vec::new(),
+            running_steps: Vec::new(),
+
+            system_info: System::new(),
+            timer_start: None,
+            invocation_timer_start: Instant::now(),
+        });
+
+        BuildMetrics { state }
+    }
+
+    pub(crate) fn enter_step<S: Step>(&self, step: &S) {
+        let mut state = self.state.borrow_mut();
+
+        // Consider all the stats gathered so far as the parent's.
+        if !state.running_steps.is_empty() {
+            self.collect_stats(&mut *state);
+        }
+
+        state.system_info.refresh_cpu();
+        state.timer_start = Some(Instant::now());
+
+        state.running_steps.push(StepMetrics {
+            type_: std::any::type_name::<S>().into(),
+            debug_repr: format!("{step:?}"),
+
+            cpu_usage_time_sec: 0.0,
+            duration_excluding_children_sec: Duration::ZERO,
+
+            children: Vec::new(),
+        });
+    }
+
+    pub(crate) fn exit_step(&self) {
+        let mut state = self.state.borrow_mut();
+
+        self.collect_stats(&mut *state);
+
+        let step = state.running_steps.pop().unwrap();
+        if state.running_steps.is_empty() {
+            state.finished_steps.push(step);
+            state.timer_start = None;
+        } else {
+            state.running_steps.last_mut().unwrap().children.push(step);
+
+            // Start collecting again for the parent step.
+            state.system_info.refresh_cpu();
+            state.timer_start = Some(Instant::now());
+        }
+    }
+
+    fn collect_stats(&self, state: &mut MetricsState) {
+        let step = state.running_steps.last_mut().unwrap();
+
+        let elapsed = state.timer_start.unwrap().elapsed();
+        step.duration_excluding_children_sec += elapsed;
+
+        state.system_info.refresh_cpu();
+        let cpu = state.system_info.cpus().iter().map(|p| p.cpu_usage()).sum::<f32>();
+        step.cpu_usage_time_sec += cpu as f64 / 100.0 * elapsed.as_secs_f64();
+    }
+
+    pub(crate) fn persist(&self, build: &Build) {
+        let mut state = self.state.borrow_mut();
+        assert!(state.running_steps.is_empty(), "steps are still executing");
+
+        let dest = build.out.join("metrics.json");
+
+        let mut system = System::new();
+        system.refresh_cpu();
+        system.refresh_memory();
+
+        let system_stats = JsonInvocationSystemStats {
+            cpu_threads_count: system.cpus().len(),
+            cpu_model: system.cpus()[0].brand().into(),
+
+            memory_total_bytes: system.total_memory() * 1024,
+        };
+        let steps = std::mem::take(&mut state.finished_steps);
+
+        // Some of our CI builds consist of multiple independent CI invocations. Ensure all the
+        // previous invocations are still present in the resulting file.
+        let mut invocations = match std::fs::read(&dest) {
+            Ok(contents) => t!(serde_json::from_slice::<JsonRoot>(&contents)).invocations,
+            Err(err) => {
+                if err.kind() != std::io::ErrorKind::NotFound {
+                    panic!("failed to open existing metrics file at {}: {err}", dest.display());
+                }
+                Vec::new()
+            }
+        };
+        invocations.push(JsonInvocation {
+            duration_including_children_sec: state.invocation_timer_start.elapsed().as_secs_f64(),
+            children: steps.into_iter().map(|step| self.prepare_json_step(step)).collect(),
+        });
+
+        let json = JsonRoot { system_stats, invocations };
+
+        t!(std::fs::create_dir_all(dest.parent().unwrap()));
+        let mut file = BufWriter::new(t!(File::create(&dest)));
+        t!(serde_json::to_writer(&mut file, &json));
+    }
+
+    fn prepare_json_step(&self, step: StepMetrics) -> JsonNode {
+        JsonNode::RustbuildStep {
+            type_: step.type_,
+            debug_repr: step.debug_repr,
+
+            duration_excluding_children_sec: step.duration_excluding_children_sec.as_secs_f64(),
+            system_stats: JsonStepSystemStats {
+                cpu_utilization_percent: step.cpu_usage_time_sec * 100.0
+                    / step.duration_excluding_children_sec.as_secs_f64(),
+            },
+
+            children: step
+                .children
+                .into_iter()
+                .map(|child| self.prepare_json_step(child))
+                .collect(),
+        }
+    }
+}
+
+struct MetricsState {
+    finished_steps: Vec<StepMetrics>,
+    running_steps: Vec<StepMetrics>,
+
+    system_info: System,
+    timer_start: Option<Instant>,
+    invocation_timer_start: Instant,
+}
+
+struct StepMetrics {
+    type_: String,
+    debug_repr: String,
+
+    cpu_usage_time_sec: f64,
+    duration_excluding_children_sec: Duration,
+
+    children: Vec<StepMetrics>,
+}
+
+#[derive(Serialize, Deserialize)]
+#[serde(rename_all = "snake_case")]
+struct JsonRoot {
+    system_stats: JsonInvocationSystemStats,
+    invocations: Vec<JsonInvocation>,
+}
+
+#[derive(Serialize, Deserialize)]
+#[serde(rename_all = "snake_case")]
+struct JsonInvocation {
+    duration_including_children_sec: f64,
+    children: Vec<JsonNode>,
+}
+
+#[derive(Serialize, Deserialize)]
+#[serde(tag = "kind", rename_all = "snake_case")]
+enum JsonNode {
+    RustbuildStep {
+        #[serde(rename = "type")]
+        type_: String,
+        debug_repr: String,
+
+        duration_excluding_children_sec: f64,
+        system_stats: JsonStepSystemStats,
+
+        children: Vec<JsonNode>,
+    },
+}
+
+#[derive(Serialize, Deserialize)]
+#[serde(rename_all = "snake_case")]
+struct JsonInvocationSystemStats {
+    cpu_threads_count: usize,
+    cpu_model: String,
+
+    memory_total_bytes: u64,
+}
+
+#[derive(Serialize, Deserialize)]
+#[serde(rename_all = "snake_case")]
+struct JsonStepSystemStats {
+    cpu_utilization_percent: f64,
+}

src/ci/run.sh

@@ -45,6 +45,7 @@ fi
 
 if ! isCI || isCiBranch auto || isCiBranch beta || isCiBranch try; then
     RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --set build.print-step-timings --enable-verbose-tests"
+    RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --set build.metrics"
 fi
 
 RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --enable-sccache"

src/ci/scripts/upload-artifacts.sh

@@ -10,19 +10,24 @@ source "$(cd "$(dirname "$0")" && pwd)/../shared.sh"
 
 upload_dir="$(mktemp -d)"
 
+build_dir=build
+if isLinux; then
+    build_dir=obj/build
+fi
+
 # Release tarballs produced by a dist builder.
 if [[ "${DEPLOY-0}" -eq "1" ]] || [[ "${DEPLOY_ALT-0}" -eq "1" ]]; then
-    dist_dir=build/dist
-    if isLinux; then
-        dist_dir=obj/build/dist
-    fi
+    dist_dir="${build_dir}/dist"
     rm -rf "${dist_dir}/doc"
     cp -r "${dist_dir}"/* "${upload_dir}"
 fi
 
 # CPU usage statistics.
 cp cpu-usage.csv "${upload_dir}/cpu-${CI_JOB_NAME}.csv"
 
+# Build metrics generated by x.py.
+cp "${build_dir}/metrics.json" "${upload_dir}/metrics-${CI_JOB_NAME}.json"
+
 # Toolstate data.
 if [[ -n "${DEPLOY_TOOLSTATES_JSON+x}" ]]; then
     cp /tmp/toolstate/toolstates.json "${upload_dir}/${DEPLOY_TOOLSTATES_JSON}"