Trace (most) installation disk operations

Adds a new environment variable to control tracing. Tracing is
manual and can be expanded. We can probably get better systemic
tracing from a suite of platform specific tools over time, but for
now this was low hanging fruit that allows pretty good insight
without too much code intrusion. Runtime overhead when disabled
is extremely low (I can unpack rust-docs on Linux in 1s).

Cargo.toml

@@ -59,6 +59,10 @@ xz2 = "0.1.3"
 version = "0.5"
 default-features = false
 
+[dependencies.rs_tracing]
+version = "1.0.1"
+features = ["rs_tracing"]
+
 [target."cfg(windows)".dependencies]
 cc = "1"
 winreg = "0.6"

README.md

@@ -616,6 +616,13 @@ Command                                                     | Description
   single-threaded IO for troubleshooting, or an arbitrary number to
   override automatic detection.
 
+- `RUSTUP_TRACE_DIR` (default: no tracing)
+  Enables tracing and determines the directory that traces will be
+  written too. Traces are of the form PID.trace. Traces can be read
+  by the Catapult project [tracing viewer][tv].
+
+  [tv]: (https://github.com/catapult-project/catapult/blob/master/tracing/README.md)
+
 ## Other installation methods
 
 The primary installation method, as described at https://rustup.rs, differs by platform:

src/cli/main.rs

@@ -30,9 +30,12 @@ mod term2;
 
 use crate::errors::*;
 use rustup::env_var::RUST_RECURSION_COUNT_MAX;
+
 use std::env;
 use std::path::PathBuf;
 
+use rs_tracing::*;
+
 fn main() {
     if let Err(ref e) = run_rustup() {
         common::report_error(e);
@@ -41,6 +44,17 @@ fn main() {
 }
 
 fn run_rustup() -> Result<()> {
+    if let Ok(dir) = env::var("RUSTUP_TRACE_DIR") {
+        open_trace_file!(dir)?;
+    }
+    let result = run_rustup_inner();
+    if let Ok(_) = env::var("RUSTUP_TRACE_DIR") {
+        close_trace_file!();
+    }
+    result
+}
+
+fn run_rustup_inner() -> Result<()> {
     // Guard against infinite proxy recursion. This mostly happens due to
     // bugs in rustup.
     do_recursion_guard()?;

src/diskio/mod.rs

@@ -166,15 +166,30 @@ pub fn write_file<P: AsRef<Path>, C: AsRef<[u8]>>(
         use std::os::unix::fs::OpenOptionsExt;
         opts.mode(mode);
     }
-    opts.write(true)
-        .create(true)
-        .truncate(true)
-        .open(path.as_ref())?
-        .write_all(contents.as_ref())
+    let path = path.as_ref();
+    let path_display = format!("{}", path.display());
+    let mut f = {
+        trace_scoped!("creat", "name": path_display);
+        opts.write(true).create(true).truncate(true).open(path)?
+    };
+    let contents = contents.as_ref();
+    let len = contents.len();
+    {
+        trace_scoped!("write", "name": path_display, "len": len);
+        f.write_all(contents)?;
+    }
+    {
+        trace_scoped!("close", "name:": path_display);
+        drop(f);
+    }
+    Ok(())
 }
 
 pub fn create_dir<P: AsRef<Path>>(path: P) -> io::Result<()> {
-    std::fs::create_dir(path.as_ref())
+    let path = path.as_ref();
+    let path_display = format!("{}", path.display());
+    trace_scoped!("create_dir", "name": path_display);
+    std::fs::create_dir(path)
 }
 
 /// Get the executor for disk IO.

src/dist/component/package.rs

@@ -297,6 +297,8 @@ fn unpack_without_first_dir<'a, R: Read>(
                 // leave till later.
 
                 if !parent.exists() {
+                    let path_display = format!("{}", parent.display());
+                    trace_scoped!("create_dir_all", "name": path_display);
                     std::fs::create_dir_all(&parent).chain_err(|| ErrorKind::ExtractingPackage)?
                 }
             }

src/lib.rs

@@ -7,6 +7,9 @@ pub use crate::notifications::*;
 pub use crate::toolchain::*;
 pub use crate::utils::{notify, toml_utils};
 
+#[macro_use]
+extern crate rs_tracing;
+
 // A list of all binaries which Rustup will proxy.
 pub static TOOLS: &[&str] = &[
     "rustc",