Merge pull request #1753 from Kobzol/collector-log

Add a few more logs to collector

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(())
     }

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 {

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<process::Output> {
     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!(