Rollup merge of rust-lang#145490 - Kobzol:bootstrap-io-tracing, r=jieyouxu

Trace some basic I/O operations in bootstrap

When working on removing the rmeta sysroot copies, it is quite difficult to figure out *why* was did a certain file appear in a given directory. This should help with that a bit.

r? `@jieyouxu`

Author: jieyouxu

src/bootstrap/src/core/build_steps/compile.rs

@@ -2331,6 +2331,7 @@ impl Step for Assemble {
 ///
 /// For a particular stage this will link the file listed in `stamp` into the
 /// `sysroot_dst` provided.
+#[track_caller]
 pub fn add_to_sysroot(
     builder: &Builder<'_>,
     sysroot_dst: &Path,

src/bootstrap/src/lib.rs

@@ -1743,6 +1743,7 @@ impl Build {
     ///
     /// If `src` is a symlink, `src` will be resolved to the actual path
     /// and copied to `dst` instead of the symlink itself.
+    #[track_caller]
     pub fn resolve_symlink_and_copy(&self, src: &Path, dst: &Path) {
         self.copy_link_internal(src, dst, true);
     }
@@ -1751,6 +1752,7 @@ impl Build {
     /// Attempts to use hard links if possible, falling back to copying.
     /// You can neither rely on this being a copy nor it being a link,
     /// so do not write to dst.
+    #[track_caller]
     pub fn copy_link(&self, src: &Path, dst: &Path, file_type: FileType) {
         self.copy_link_internal(src, dst, false);
 
@@ -1765,6 +1767,7 @@ impl Build {
         }
     }
 
+    #[track_caller]
     fn copy_link_internal(&self, src: &Path, dst: &Path, dereference_symlinks: bool) {
         if self.config.dry_run() {
             return;
@@ -1773,6 +1776,10 @@ impl Build {
         if src == dst {
             return;
         }
+
+        #[cfg(feature = "tracing")]
+        let _span = trace_io!("file-copy-link", ?src, ?dst);
+
         if let Err(e) = fs::remove_file(dst)
             && cfg!(windows)
             && e.kind() != io::ErrorKind::NotFound
@@ -1815,6 +1822,7 @@ impl Build {
     /// Links the `src` directory recursively to `dst`. Both are assumed to exist
     /// when this function is called.
     /// Will attempt to use hard links if possible and fall back to copying.
+    #[track_caller]
     pub fn cp_link_r(&self, src: &Path, dst: &Path) {
         if self.config.dry_run() {
             return;
@@ -1837,12 +1845,14 @@ impl Build {
     /// Will attempt to use hard links if possible and fall back to copying.
     /// Unwanted files or directories can be skipped
     /// by returning `false` from the filter function.
+    #[track_caller]
     pub fn cp_link_filtered(&self, src: &Path, dst: &Path, filter: &dyn Fn(&Path) -> bool) {
         // Immediately recurse with an empty relative path
         self.cp_link_filtered_recurse(src, dst, Path::new(""), filter)
     }
 
     // Inner function does the actual work
+    #[track_caller]
     fn cp_link_filtered_recurse(
         &self,
         src: &Path,
@@ -1903,17 +1913,26 @@ impl Build {
         t!(fs::read_to_string(path))
     }
 
+    #[track_caller]
     fn create_dir(&self, dir: &Path) {
         if self.config.dry_run() {
             return;
         }
+
+        #[cfg(feature = "tracing")]
+        let _span = trace_io!("dir-create", ?dir);
+
         t!(fs::create_dir_all(dir))
     }
 
     fn remove_dir(&self, dir: &Path) {
         if self.config.dry_run() {
             return;
         }
+
+        #[cfg(feature = "tracing")]
+        let _span = trace_io!("dir-remove", ?dir);
+
         t!(fs::remove_dir_all(dir))
     }
 

src/bootstrap/src/utils/tracing.rs

@@ -48,14 +48,37 @@ macro_rules! error {
     }
 }
 
+#[cfg(feature = "tracing")]
+pub const IO_SPAN_TARGET: &str = "IO";
+
+/// Create a tracing span around an I/O operation, if tracing is enabled.
+/// Note that at least one tracing value field has to be passed to this macro, otherwise it will not
+/// compile.
+#[macro_export]
+macro_rules! trace_io {
+    ($name:expr, $($args:tt)*) => {
+        ::tracing::trace_span!(
+            target: $crate::utils::tracing::IO_SPAN_TARGET,
+            $name,
+            $($args)*,
+            location = $crate::utils::tracing::format_location(*::std::panic::Location::caller())
+        ).entered()
+    }
+}
+
+#[cfg(feature = "tracing")]
+pub fn format_location(location: std::panic::Location<'static>) -> String {
+    format!("{}:{}", location.file(), location.line())
+}
+
 #[cfg(feature = "tracing")]
 const COMMAND_SPAN_TARGET: &str = "COMMAND";
 
 #[cfg(feature = "tracing")]
 pub fn trace_cmd(command: &crate::BootstrapCommand) -> tracing::span::EnteredSpan {
     let fingerprint = command.fingerprint();
     let location = command.get_created_location();
-    let location = format!("{}:{}", location.file(), location.line());
+    let location = format_location(location);
 
     tracing::span!(
         target: COMMAND_SPAN_TARGET,
@@ -84,6 +107,7 @@ mod inner {
     use std::fmt::Debug;
     use std::fs::File;
     use std::io::Write;
+    use std::path::{Path, PathBuf};
     use std::sync::atomic::Ordering;
 
     use chrono::{DateTime, Utc};
@@ -93,8 +117,8 @@ mod inner {
     use tracing_subscriber::registry::{LookupSpan, SpanRef};
     use tracing_subscriber::{EnvFilter, Layer};
 
+    use super::{COMMAND_SPAN_TARGET, IO_SPAN_TARGET};
     use crate::STEP_SPAN_TARGET;
-    use crate::utils::tracing::COMMAND_SPAN_TARGET;
 
     pub fn setup_tracing(env_name: &str) -> TracingGuard {
         let filter = EnvFilter::from_env(env_name);
@@ -291,6 +315,23 @@ mod inner {
                 Ok(())
             }
 
+            // Write fields while treating the "location" field specially, and assuming that it
+            // contains the source file location relevant to the span.
+            let write_with_location = |writer: &mut W| -> std::io::Result<()> {
+                if let Some(values) = field_values {
+                    write_fields(
+                        writer,
+                        values.fields.iter().filter(|(name, _)| *name != "location"),
+                    )?;
+                    let location =
+                        &values.fields.iter().find(|(name, _)| *name == "location").unwrap().1;
+                    let (filename, line) = location.rsplit_once(':').unwrap();
+                    let filename = shorten_filename(filename);
+                    write!(writer, " ({filename}:{line})",)?;
+                }
+                Ok(())
+            };
+
             // We handle steps specially. We instrument them dynamically in `Builder::ensure`,
             // and we want to have custom name for each step span. But tracing doesn't allow setting
             // dynamic span names. So we detect step spans here and override their name.
@@ -311,17 +352,11 @@ mod inner {
                 // Executed command
                 COMMAND_SPAN_TARGET => {
                     write!(writer, "{}", span.name())?;
-                    if let Some(values) = field_values {
-                        write_fields(
-                            writer,
-                            values.fields.iter().filter(|(name, _)| *name != "location"),
-                        )?;
-                        write!(
-                            writer,
-                            " ({})",
-                            values.fields.iter().find(|(name, _)| *name == "location").unwrap().1
-                        )?;
-                    }
+                    write_with_location(writer)?;
+                }
+                IO_SPAN_TARGET => {
+                    write!(writer, "{}", span.name())?;
+                    write_with_location(writer)?;
                 }
                 // Other span
                 _ => {
@@ -342,21 +377,10 @@ mod inner {
         writer: &mut W,
         metadata: &'static tracing::Metadata<'static>,
     ) -> std::io::Result<()> {
-        use std::path::{Path, PathBuf};
-
         if let Some(filename) = metadata.file() {
-            // Keep only the module name and file name to make it shorter
-            let filename: PathBuf = Path::new(filename)
-                .components()
-                // Take last two path components
-                .rev()
-                .take(2)
-                .collect::<Vec<_>>()
-                .into_iter()
-                .rev()
-                .collect();
-
-            write!(writer, " ({}", filename.display())?;
+            let filename = shorten_filename(filename);
+
+            write!(writer, " ({filename}")?;
             if let Some(line) = metadata.line() {
                 write!(writer, ":{line}")?;
             }
@@ -365,6 +389,21 @@ mod inner {
         Ok(())
     }
 
+    /// Keep only the module name and file name to make it shorter
+    fn shorten_filename(filename: &str) -> String {
+        Path::new(filename)
+            .components()
+            // Take last two path components
+            .rev()
+            .take(2)
+            .collect::<Vec<_>>()
+            .into_iter()
+            .rev()
+            .collect::<PathBuf>()
+            .display()
+            .to_string()
+    }
+
     impl<S> Layer<S> for TracingPrinter
     where
         S: Subscriber,

src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md

@@ -81,9 +81,11 @@ There are two orthogonal ways to control which kind of tracing logs you want:
    - If you select a level, all events/spans with an equal or higher priority level will be shown.
 2. You can also control the log **target**, e.g. `bootstrap` or `bootstrap::core::config` or a custom target like `CONFIG_HANDLING` or `STEP`.
     - Custom targets are used to limit what kinds of spans you are interested in, as the `BOOTSTRAP_TRACING=trace` output can be quite verbose. Currently, you can use the following custom targets:
-        - `CONFIG_HANDLING`: show spans related to config handling
-        - `STEP`: show all executed steps. Note that executed commands have `info` event level.
-        - `COMMAND`: show all executed commands. Note that executed commands have `trace` event level.
+        - `CONFIG_HANDLING`: show spans related to config handling.
+        - `STEP`: show all executed steps. Executed commands have `info` event level.
+        - `COMMAND`: show all executed commands. Executed commands have `trace` event level.
+        - `IO`: show performed I/O operations. Executed commands have `trace` event level.
+            - Note that many I/O are currently not being traced.
 
 You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally):