Merge pull request #2185 from Kobzol/rustc-log

Stream bootstrap log when running the rustc benchmark

Author: Kobzol

collector/src/compile/execute/mod.rs

@@ -447,8 +447,6 @@ impl<'a> CargoProcess<'a> {
                 client.configure(&mut cmd);
             }
 
-            log::debug!("{:?}", cmd);
-
             let cmd = tokio::process::Command::from(cmd);
             let output = async_command_output(cmd).await?;
 

collector/src/compile/execute/rustc.rs

@@ -105,7 +105,7 @@ async fn record(
     .context("configuring")?;
     assert!(status.success(), "configure successful");
 
-    let output = crate::command_output(
+    let output = crate::command_output_stream(
         Command::new("python3")
             .arg(
                 checkout

collector/src/lib.rs

@@ -169,7 +169,12 @@ pub fn run_command(cmd: &mut Command) -> anyhow::Result<()> {
     Ok(())
 }
 
-fn run_command_with_output(cmd: &mut Command) -> anyhow::Result<process::Output> {
+/// If `stream_output` is true, stdout/stderr of `cmd` should be streamed to stdout/stderr of the
+/// current process, in addition to being captured.
+fn run_command_with_output(
+    cmd: &mut Command,
+    stream_output: bool,
+) -> anyhow::Result<process::Output> {
     use anyhow::Context;
     use utils::read2;
     let mut child = cmd
@@ -178,27 +183,28 @@ fn run_command_with_output(cmd: &mut Command) -> anyhow::Result<process::Output>
         .spawn()
         .with_context(|| format!("failed to spawn process for cmd: {cmd:?}"))?;
 
-    let mut stdout = Vec::new();
-    let mut stderr = Vec::new();
-    let mut stdout_writer = std::io::LineWriter::new(std::io::stdout());
-    let mut stderr_writer = std::io::LineWriter::new(std::io::stderr());
-    read2::read2(
+    let mut stdout_writer = std::io::LineWriter::new(std::io::stdout().lock());
+    let mut stderr_writer = std::io::LineWriter::new(std::io::stderr().lock());
+
+    let mut stdout_written = 0;
+    let mut stderr_written = 0;
+    let (stdout, stderr) = read2::read2(
         child.stdout.take().unwrap(),
         child.stderr.take().unwrap(),
         &mut |is_stdout, buffer, _is_done| {
             // Send output if trace logging is enabled
-            if log::log_enabled!(target: "raw_cargo_messages", log::Level::Trace) {
+            if stream_output || log::log_enabled!(target: "raw_cargo_messages", log::Level::Trace) {
                 use std::io::Write;
                 if is_stdout {
-                    stdout_writer.write_all(&buffer[stdout.len()..]).unwrap();
+                    stdout_writer.write_all(&buffer[stdout_written..]).unwrap();
                 } else {
-                    stderr_writer.write_all(&buffer[stderr.len()..]).unwrap();
+                    stderr_writer.write_all(&buffer[stderr_written..]).unwrap();
                 }
             }
             if is_stdout {
-                stdout = buffer.clone();
+                stdout_written = buffer.len();
             } else {
-                stderr = buffer.clone();
+                stderr_written = buffer.len();
             }
         },
     )?;
@@ -215,42 +221,47 @@ fn run_command_with_output(cmd: &mut Command) -> anyhow::Result<process::Output>
 }
 
 pub fn command_output(cmd: &mut Command) -> anyhow::Result<process::Output> {
-    let output = run_command_with_output(cmd)?;
+    let output = run_command_with_output(cmd, false)?;
+    check_command_output(&output)?;
+    Ok(output)
+}
 
+pub fn command_output_stream(cmd: &mut Command) -> anyhow::Result<process::Output> {
+    let output = run_command_with_output(cmd, true)?;
+    check_command_output(&output)?;
+    Ok(output)
+}
+
+fn check_command_output(output: &process::Output) -> anyhow::Result<()> {
     if !output.status.success() {
-        return Err(anyhow::anyhow!(
+        Err(anyhow::anyhow!(
             "expected success, got {}\n\nstderr={}\n\n stdout={}\n",
             output.status,
             String::from_utf8_lossy(&output.stderr),
             String::from_utf8_lossy(&output.stdout)
-        ));
+        ))
+    } else {
+        Ok(())
     }
-
-    Ok(output)
 }
 
 pub async fn async_command_output(
     mut cmd: tokio::process::Command,
 ) -> anyhow::Result<process::Output> {
     use anyhow::Context;
 
+    log::debug!("Executing {:?}", cmd);
+
     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());
+    log::trace!("Command took {} ms", start.elapsed().as_millis());
 
-    if !output.status.success() {
-        return Err(anyhow::anyhow!(
-            "expected success, got {}\n\nstderr={}\n\n stdout={}\n",
-            output.status,
-            String::from_utf8_lossy(&output.stderr),
-            String::from_utf8_lossy(&output.stdout)
-        ));
-    }
+    check_command_output(&output)?;
 
     Ok(output)
 }

collector/src/runtime/mod.rs

@@ -15,7 +15,7 @@ pub use benchmark::{
 use database::{ArtifactIdNumber, CollectionId, Connection};
 
 use crate::utils::git::get_rustc_perf_commit;
-use crate::{run_command_with_output, CollectorCtx};
+use crate::{command_output, CollectorCtx};
 
 mod benchmark;
 mod profile;
@@ -214,15 +214,7 @@ fn execute_runtime_benchmark_binary(
         command.args(["--include", &filter.include.join(",")]);
     }
 
-    let output = run_command_with_output(&mut command)?;
-    if !output.status.success() {
-        return Err(anyhow::anyhow!(
-            "Process finished with exit code {}\n{}",
-            output.status.code().unwrap_or(-1),
-            String::from_utf8_lossy(&output.stderr)
-        ));
-    }
-
+    let output = command_output(&mut command)?;
     let reader = BufReader::new(Cursor::new(output.stdout));
     Ok(reader.lines().map(|line| {
         Ok(line.and_then(|line| Ok(serde_json::from_str::<BenchmarkMessage>(&line)?))?)

collector/src/utils/fs.rs

@@ -129,7 +129,7 @@ pub fn robocopy(
         cmd.arg(arg.as_ref());
     }
 
-    let output = run_command_with_output(&mut cmd)?;
+    let output = run_command_with_output(&mut cmd, false)?;
 
     if output.status.code() >= Some(8) {
         // robocopy returns 0-7 on success

collector/src/utils/read2.rs

@@ -31,11 +31,12 @@ mod imp {
     use std::os::unix::prelude::*;
     use std::process::{ChildStderr, ChildStdout};
 
+    /// Returns (stdout, stderr).
     pub fn read2(
         mut out_pipe: ChildStdout,
         mut err_pipe: ChildStderr,
         data: &mut dyn FnMut(bool, &mut Vec<u8>, bool),
-    ) -> io::Result<()> {
+    ) -> io::Result<(Vec<u8>, Vec<u8>)> {
         unsafe {
             libc::fcntl(out_pipe.as_raw_fd(), libc::F_SETFL, libc::O_NONBLOCK);
             libc::fcntl(err_pipe.as_raw_fd(), libc::F_SETFL, libc::O_NONBLOCK);
@@ -93,7 +94,7 @@ mod imp {
             }
             data(true, &mut out, out_done);
         }
-        Ok(())
+        Ok((out, err))
     }
 }
 
@@ -120,7 +121,7 @@ mod imp {
         out_pipe: ChildStdout,
         err_pipe: ChildStderr,
         data: &mut dyn FnMut(bool, &mut Vec<u8>, bool),
-    ) -> io::Result<()> {
+    ) -> io::Result<(Vec<u8>, Vec<u8>)> {
         let mut out = Vec::new();
         let mut err = Vec::new();
 
@@ -151,7 +152,7 @@ mod imp {
                 }
             }
 
-            Ok(())
+            Ok((out, err))
         }
     }