From abecf68112acfae06f4bff07c2b5200d71009e17 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Ber=C3=A1nek?= Date: Sat, 16 Aug 2025 13:45:50 +0200 Subject: [PATCH] Trace some basic I/O operations in bootstrap --- src/bootstrap/src/core/build_steps/compile.rs | 1 + src/bootstrap/src/lib.rs | 19 ++++ src/bootstrap/src/utils/tracing.rs | 93 +++++++++++++------ .../bootstrapping/debugging-bootstrap.md | 8 +- 4 files changed, 91 insertions(+), 30 deletions(-) diff --git a/src/bootstrap/src/core/build_steps/compile.rs b/src/bootstrap/src/core/build_steps/compile.rs index 997a152a31fcb..c58772158cf1a 100644 --- a/src/bootstrap/src/core/build_steps/compile.rs +++ b/src/bootstrap/src/core/build_steps/compile.rs @@ -2286,6 +2286,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, diff --git a/src/bootstrap/src/lib.rs b/src/bootstrap/src/lib.rs index 706a3cbb2109b..14ebad3af9793 100644 --- a/src/bootstrap/src/lib.rs +++ b/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, @@ -1904,10 +1914,15 @@ 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)) } @@ -1915,6 +1930,10 @@ impl Build { if self.config.dry_run() { return; } + + #[cfg(feature = "tracing")] + let _span = trace_io!("dir-remove", ?dir); + t!(fs::remove_dir_all(dir)) } diff --git a/src/bootstrap/src/utils/tracing.rs b/src/bootstrap/src/utils/tracing.rs index 428ba013c985f..472781ffa73aa 100644 --- a/src/bootstrap/src/utils/tracing.rs +++ b/src/bootstrap/src/utils/tracing.rs @@ -48,6 +48,29 @@ 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"; @@ -55,7 +78,7 @@ const COMMAND_SPAN_TARGET: &str = "COMMAND"; 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::>() - .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::>() + .into_iter() + .rev() + .collect::() + .display() + .to_string() + } + impl Layer for TracingPrinter where S: Subscriber, diff --git a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md b/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md index fb90c0fdb4353..93b11c0690a92 100644 --- a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md +++ b/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):