Merge pull request #726 from nnethercote/wrap-eprintln

Avoid collecting extraneous stuff on `eprintln` runs.

Author: Mark-Simulacrum

ci/check-profiling.sh

@@ -76,16 +76,17 @@ RUST_BACKTRACE=1 RUST_LOG=raw_cargo_messages=trace,collector=debug,rust_sysroot=
 test -f results/msout-Test-helloworld-Check-Full
 grep -q "snapshot=0" results/msout-Test-helloworld-Check-Full
 
-# eprintln.
+# eprintln. The output file is empty because a vanilla rustc doesn't print
+# anything to stderr.
 RUST_BACKTRACE=1 RUST_LOG=raw_cargo_messages=trace,collector=debug,rust_sysroot=debug \
     cargo run -p collector --bin collector -- \
     profile_local eprintln $bindir/rustc Test \
         --builds Check \
         --cargo $bindir/cargo \
         --include helloworld \
         --runs Full
-test -f results/eprintln-Test-helloworld-Check-Full
-grep -q "Checking helloworld" results/eprintln-Test-helloworld-Check-Full
+test   -f results/eprintln-Test-helloworld-Check-Full
+test ! -s results/eprintln-Test-helloworld-Check-Full
 
 # llvm-lines. `Debug` not `Check` because it doesn't support `Check` builds.
 RUST_BACKTRACE=1 RUST_LOG=raw_cargo_messages=trace,collector=debug,rust_sysroot=debug \

collector/src/execute.rs

@@ -661,7 +661,7 @@ impl<'a> Processor for ProfileProcessor<'a> {
             }
 
             // -Zself-profile produces (via rustc-fake) a data directory called
-            // 'Zsp' containing three files with names of the form
+            // `Zsp` containing three files with names of the form
             // `$BENCHMARK-$PID.{events,string_data,string_index}`. We copy it
             // from the temp dir to the output dir, renaming the files within
             // as `Zsp.{events,string_data,string_index}` in the process, then
@@ -703,8 +703,7 @@ impl<'a> Processor for ProfileProcessor<'a> {
                 // Run `summarize`.
                 let mut summarize_cmd = Command::new("summarize");
                 summarize_cmd.arg("summarize").arg(&zsp_files_prefix);
-                let output = summarize_cmd.output()?;
-                fs::write(&summarize_file, &output.stdout)?;
+                fs::write(&summarize_file, &summarize_cmd.output()?.stdout)?;
 
                 // Run `flamegraph`.
                 let mut flamegraph_cmd = Command::new("flamegraph");
@@ -719,15 +718,16 @@ impl<'a> Processor for ProfileProcessor<'a> {
                 fs::rename("chrome_profiler.json", crox_file)?;
             }
 
-            // -Ztime-passes writes its output to stdout. We copy that output
-            // into a file in the output dir.
+            // `-Ztime-passes` output is redirected (via rustc-fake) to a file
+            // called `Ztp`. We copy that output into a file in the output dir.
             Profiler::TimePasses => {
+                let tmp_ztp_file = filepath(data.cwd.as_ref(), "Ztp");
                 let ztp_file = filepath(self.output_dir, &out_file("Ztp"));
 
-                fs::write(ztp_file, &output.stdout)?;
+                fs::copy(&tmp_ztp_file, &ztp_file)?;
             }
 
-            // perf-record produces (via rustc-fake) a data file called 'perf'.
+            // perf-record produces (via rustc-fake) a data file called `perf`.
             // We copy it from the temp dir to the output dir, giving it a new
             // name in the process.
             Profiler::PerfRecord => {
@@ -738,7 +738,7 @@ impl<'a> Processor for ProfileProcessor<'a> {
             }
 
             // OProfile produces (via rustc-fake) a data directory called
-            // 'oprofile_data'. We copy it from the temp dir to the output dir,
+            // `oprofile_data`. We copy it from the temp dir to the output dir,
             // giving it a new name in the process, and then post-process it
             // twice to produce another two data files in the output dir.
             Profiler::OProfile => {
@@ -765,8 +765,7 @@ impl<'a> Processor for ProfileProcessor<'a> {
                     .arg("--threshold")
                     .arg("0.5")
                     .arg(&session_dir_arg);
-                let output = op_report_cmd.output()?;
-                fs::write(oprep_file, &output.stdout)?;
+                fs::write(oprep_file, &op_report_cmd.output()?.stdout)?;
 
                 let mut op_annotate_cmd = Command::new("opannotate");
                 // Other possibly useful args: --assembly
@@ -775,11 +774,10 @@ impl<'a> Processor for ProfileProcessor<'a> {
                     .arg("--threshold")
                     .arg("0.5")
                     .arg(&session_dir_arg);
-                let output = op_annotate_cmd.output()?;
-                fs::write(opann_file, &output.stdout)?;
+                fs::write(opann_file, &op_annotate_cmd.output()?.stdout)?;
             }
 
-            // Cachegrind produces (via rustc-fake) a data file called 'cgout'.
+            // Cachegrind produces (via rustc-fake) a data file called `cgout`.
             // We copy it from the temp dir to the output dir, giving it a new
             // name in the process, and then post-process it to produce another
             // data file in the output dir.
@@ -795,11 +793,10 @@ impl<'a> Processor for ProfileProcessor<'a> {
                     .arg("--auto=yes")
                     .arg("--show-percs=yes")
                     .arg(&cgout_file);
-                let output = cg_annotate_cmd.output()?;
-                fs::write(cgann_file, &output.stdout)?;
+                fs::write(cgann_file, &cg_annotate_cmd.output()?.stdout)?;
             }
 
-            // Callgrind produces (via rustc-fake) a data file called 'clgout'.
+            // Callgrind produces (via rustc-fake) a data file called `clgout`.
             // We copy it from the temp dir to the output dir, giving it a new
             // name in the process, and then post-process it to produce another
             // data file in the output dir.
@@ -815,11 +812,10 @@ impl<'a> Processor for ProfileProcessor<'a> {
                     .arg("--auto=yes")
                     .arg("--show-percs=yes")
                     .arg(&clgout_file);
-                let output = clg_annotate_cmd.output()?;
-                fs::write(clgann_file, &output.stdout)?;
+                fs::write(clgann_file, &clg_annotate_cmd.output()?.stdout)?;
             }
 
-            // DHAT produces (via rustc-fake) a data file called 'dhout'. We
+            // DHAT produces (via rustc-fake) a data file called `dhout`. We
             // copy it from the temp dir to the output dir, giving it a new
             // name in the process.
             Profiler::DHAT => {
@@ -829,7 +825,7 @@ impl<'a> Processor for ProfileProcessor<'a> {
                 fs::copy(&tmp_dhout_file, &dhout_file)?;
             }
 
-            // Massif produces (via rustc-fake) a data file called 'msout'. We
+            // Massif produces (via rustc-fake) a data file called `msout`. We
             // copy it from the temp dir to the output dir, giving it a new
             // name in the process.
             Profiler::Massif => {
@@ -839,12 +835,14 @@ impl<'a> Processor for ProfileProcessor<'a> {
                 fs::copy(&tmp_msout_file, &msout_file)?;
             }
 
-            // `eprintln!` statements writes their output to stderr. We copy
-            // that output into a file in the output dir.
+            // `eprintln!` statements are redirected (via rustc-fake) to a file
+            // called `eprintln`. We copy it from the temp dir to the output
+            // dir, giving it a new name in the process.
             Profiler::Eprintln => {
+                let tmp_eprintln_file = filepath(data.cwd.as_ref(), "eprintln");
                 let eprintln_file = filepath(self.output_dir, &out_file("eprintln"));
 
-                fs::write(eprintln_file, &output.stderr)?;
+                fs::copy(&tmp_eprintln_file, &eprintln_file)?;
             }
 
             // `cargo llvm-lines` writes its output to stdout. We copy that

collector/src/rustc-fake.rs

@@ -1,4 +1,6 @@
 use std::env;
+use std::ffi::OsString;
+use std::fs;
 use std::path::Path;
 use std::process::Command;
 use std::time::{Duration, Instant};
@@ -21,11 +23,11 @@ fn main() {
         .ok()
         .and_then(|v| v.parse::<u32>().ok())
     {
-        args.push(std::ffi::OsString::from(format!("-Zthreads={}", count)));
+        args.push(OsString::from(format!("-Zthreads={}", count)));
     }
 
-    args.push(std::ffi::OsString::from("-Adeprecated"));
-    args.push(std::ffi::OsString::from("-Aunknown-lints"));
+    args.push(OsString::from("-Adeprecated"));
+    args.push(OsString::from("-Aunknown-lints"));
 
     if let Some(pos) = args.iter().position(|arg| arg == "--wrap-rustc-with") {
         // Strip out the flag and its argument, and run rustc under the wrapper
@@ -56,8 +58,8 @@ fn main() {
                         "-Zself-profile={}",
                         prof_out_dir.to_str().unwrap()
                     ));
-                    let _ = std::fs::remove_dir_all(&prof_out_dir);
-                    let _ = std::fs::create_dir_all(&prof_out_dir);
+                    let _ = fs::remove_dir_all(&prof_out_dir);
+                    let _ = fs::create_dir_all(&prof_out_dir);
                 }
 
                 let start = Instant::now();
@@ -75,7 +77,7 @@ fn main() {
                     let mut prefix = None;
                     // We don't know the pid of rustc, and can't easily get it -- we only know the
                     // `perf` pid. So just blindly look in the directory to hopefully find it.
-                    for entry in std::fs::read_dir(&prof_out_dir).unwrap() {
+                    for entry in fs::read_dir(&prof_out_dir).unwrap() {
                         let entry = entry.unwrap();
                         if entry
                             .file_name()
@@ -109,8 +111,8 @@ fn main() {
             }
 
             "time-passes" => {
-                let mut cmd = Command::new(&tool);
-                cmd.arg("-Ztime-passes").args(&args);
+                args.insert(0, "-Ztime-passes".into());
+                let mut cmd = bash_command(tool, args, "> Ztp");
 
                 assert!(cmd.status().expect("failed to spawn").success());
             }
@@ -203,7 +205,20 @@ fn main() {
                 assert!(cmd.status().expect("failed to spawn").success());
             }
 
-            "eprintln" | "llvm-lines" => {
+            "eprintln" => {
+                let mut cmd = bash_command(tool, args, "2> eprintln");
+
+                assert!(cmd.status().expect("failed to spawn").success());
+            }
+
+            "llvm-lines" => {
+                // `cargo llvm-lines` writes its output to stdout. But we can't
+                // redirect it to a file here like we do for "time-passes" and
+                // "eprintln". This is because `cargo llvm-lines` invokes rustc
+                // as part of its processing and then it does some analysis of
+                // its output and then it prints out some results. Because
+                // `rustc` (which this file wraps) doesn't produce the output,
+                // this file can't redirect that output.
                 let mut cmd = Command::new(&tool);
                 cmd.args(&args);
 
@@ -227,6 +242,24 @@ fn main() {
     }
 }
 
+/// Run a command via bash, in order to redirect its output to a file.
+/// `redirect` should be something like "> out" or "2> out".
+fn bash_command(tool: OsString, args: Vec<OsString>, redirect: &str) -> Command {
+    let mut bash_cmd = String::new();
+    bash_cmd.push_str(&format!("{} ", tool.to_str().unwrap()));
+    for arg in args {
+        // Args with double quotes (e.g. `--cfg feature="foo"`)
+        // will be munged by bash if we don't protect them. So we
+        // wrap every arg in single quotes.
+        bash_cmd.push_str(&format!("'{}' ", arg.to_str().unwrap()));
+    }
+    bash_cmd.push_str(redirect);
+
+    let mut cmd = Command::new("bash");
+    cmd.args(&["-c", &bash_cmd]);
+    cmd
+}
+
 #[cfg(unix)]
 fn exec(cmd: &mut Command) -> ! {
     use std::os::unix::prelude::*;
@@ -289,7 +322,7 @@ fn run_summarize(name: &str, prof_out_dir: &Path, prefix: &str) -> std::io::Resu
             "Failed to run successfully",
         ));
     }
-    std::fs::read_to_string(prof_out_dir.join(&format!("{}.json", prefix)))
+    fs::read_to_string(prof_out_dir.join(&format!("{}.json", prefix)))
 }
 
 #[cfg(windows)]