diff --git a/collector/src/compile/benchmark/mod.rs b/collector/src/compile/benchmark/mod.rs index 09ef084cd..3a4799861 100644 --- a/collector/src/compile/benchmark/mod.rs +++ b/collector/src/compile/benchmark/mod.rs @@ -330,6 +330,7 @@ impl Benchmark { preparation_start.elapsed().as_secs() ); + let benchmark_start = std::time::Instant::now(); for &backend in backends { for (profile, prep_dir) in &profile_dirs { let profile = *profile; @@ -414,6 +415,11 @@ impl Benchmark { } } } + log::trace!( + "benchmarking {} took {} seconds", + self.name, + benchmark_start.elapsed().as_secs() + ); Ok(()) } diff --git a/collector/src/compile/execute/mod.rs b/collector/src/compile/execute/mod.rs index 4f9c2c63e..c30e12ec0 100644 --- a/collector/src/compile/execute/mod.rs +++ b/collector/src/compile/execute/mod.rs @@ -198,12 +198,13 @@ impl<'a> CargoProcess<'a> { // really. pub async fn run_rustc(&mut self, needs_final: bool) -> anyhow::Result<()> { log::info!( - "run_rustc with incremental={}, profile={:?}, scenario={:?}, patch={:?}, backend={:?}", + "run_rustc with incremental={}, profile={:?}, scenario={:?}, patch={:?}, backend={:?}, phase={}", self.incremental, self.profile, self.processor_etc.as_ref().map(|v| v.1), self.processor_etc.as_ref().and_then(|v| v.3), - self.backend + self.backend, + if needs_final { "benchmark" } else { "dependencies" } ); loop { diff --git a/collector/src/lib.rs b/collector/src/lib.rs index 602aad45a..982fa0ca0 100644 --- a/collector/src/lib.rs +++ b/collector/src/lib.rs @@ -16,7 +16,7 @@ use crate::compile::benchmark::{Benchmark, BenchmarkName}; use crate::runtime::{BenchmarkGroup, BenchmarkSuite}; use database::{ArtifactId, ArtifactIdNumber, Connection}; use process::Stdio; -use std::time::Duration; +use std::time::{Duration, Instant}; #[derive(Debug, Copy, Clone, PartialEq, PartialOrd, Deserialize)] pub struct DeltaTime(#[serde(with = "round_float")] pub f64); @@ -228,12 +228,14 @@ pub async fn async_command_output( ) -> anyhow::Result { use anyhow::Context; + let start = Instant::now(); let child = cmd .stdout(Stdio::piped()) .stderr(Stdio::piped()) .spawn() .with_context(|| format!("failed to spawn process for cmd: {:?}", cmd))?; let output = child.wait_with_output().await?; + log::trace!("command {cmd:?} took {} ms", start.elapsed().as_millis()); if !output.status.success() { return Err(anyhow::anyhow!(