feat: add optional tracing performance spans

Cargo.toml

@@ -19,6 +19,7 @@ default = ["alternate-registries"]
 alternate-registries = ["dep:git2"]
 unstable = []
 unstable-toolchain-ci = []
+tracing = ["dep:tracing"]
 
 [dependencies]
 http = "1.1.0"
@@ -43,6 +44,7 @@ base64 = "0.22.0"
 getrandom = { version = "0.4.1", features = ["std"] }
 thiserror = "2.0.17"
 git2 = { version = "0.20.2", optional = true }
+tracing = { version = "0.1.41", optional = true }
 
 [target.'cfg(unix)'.dependencies]
 nix = { version = "0.30.0", features = ["signal", "user"]}

src/build.rs

@@ -180,6 +180,18 @@ impl BuildDirectory {
         }
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(
+            skip_all,
+            fields(
+                build_dir = %self.name,
+                krate = %krate,
+                toolchain = %toolchain,
+                patches = patches.len(),
+            )
+        )
+    )]
     pub(crate) fn run<R, F: FnOnce(&Build) -> anyhow::Result<R>>(
         &mut self,
         toolchain: &Toolchain,
@@ -203,11 +215,15 @@ impl BuildDirectory {
         })?;
 
         std::fs::create_dir_all(self.target_dir())?;
-        let res = f(&Build {
-            dir: self,
-            toolchain,
-            sandbox,
-        })?;
+        let res = {
+            #[cfg(feature = "tracing")]
+            let _entered = tracing::info_span!("build.user_callback").entered();
+            f(&Build {
+                dir: self,
+                toolchain,
+                sandbox,
+            })
+        }?;
 
         crate::utils::remove_dir_all(&source_dir)?;
         Ok(res)

src/cmd/mod.rs

@@ -16,6 +16,7 @@ use log::{error, info};
 use process_lines_actions::InnerState;
 use std::env::consts::EXE_SUFFIX;
 use std::ffi::{OsStr, OsString};
+use std::fmt;
 use std::mem;
 use std::path::{Path, PathBuf};
 use std::process::{ExitStatus, Stdio};
@@ -142,6 +143,7 @@ impl KillFailedError {
 
 /// Name and kind of a binary executed by [`Command`](struct.Command.html).
 #[non_exhaustive]
+#[derive(Debug)]
 pub enum Binary {
     /// Global binary, available in `$PATH`. Rustwide doesn't apply any tweaks to its execution
     /// environment.
@@ -213,6 +215,27 @@ pub struct Command<'w, 'pl> {
     source_dir_mount_kind: MountKind,
 }
 
+// Custom Debug keeps command output focused: environment variables are shown as keys only,
+// since values often contain secrets, and `sandbox`/`process_lines` are summarized as presence
+// flags.
+impl fmt::Debug for Command<'_, '_> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.debug_struct("Command")
+            .field("is_sandboxed", &self.sandbox.is_some())
+            .field("binary", &self.binary)
+            .field("args", &self.args)
+            .field("env", &self.env.iter().map(|(k, _)| k).collect::<Vec<_>>())
+            .field("has_process_lines", &self.process_lines.is_some())
+            .field("cd", &self.cd)
+            .field("timeout", &self.timeout)
+            .field("no_output_timeout", &self.no_output_timeout)
+            .field("log_command", &self.log_command)
+            .field("log_output", &self.log_output)
+            .field("source_dir_mount_kind", &self.source_dir_mount_kind)
+            .finish()
+    }
+}
+
 impl<'w> Command<'w, '_> {
     /// Create a new, unsandboxed command.
     pub fn new<R: Runnable>(workspace: &'w Workspace, binary: R) -> Self {
@@ -391,6 +414,10 @@ impl<'w> Command<'w, '_> {
         self.run_inner(true)
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(self = ?self, capture))
+    )]
     fn run_inner(self, capture: bool) -> Result<ProcessOutput, CommandError> {
         if let Some(mut builder) = self.sandbox {
             let workspace = self

src/cmd/sandbox.rs

@@ -11,6 +11,7 @@ use std::{
 };
 
 /// The Docker image used for sandboxing.
+#[derive(Debug)]
 pub struct SandboxImage {
     name: String,
 }
@@ -76,7 +77,7 @@ impl SandboxImage {
 }
 
 /// Whether to mount a path in the sandbox with write permissions or not.
-#[derive(Copy, Clone, PartialEq, Eq)]
+#[derive(Debug, Copy, Clone, PartialEq, Eq)]
 #[non_exhaustive]
 pub enum MountKind {
     /// Allow the sandboxed code to change the mounted data.
@@ -240,6 +241,22 @@ impl SandboxBuilder {
         self
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(
+            skip_all,
+            fields(
+                image = %workspace.sandbox_image().name,
+                mounts = self.mounts.len(),
+                env = self.env.len(),
+                memory_limit = ?self.memory_limit,
+                cpu_limit = ?self.cpu_limit,
+                cpuset_cpus = ?self.cpuset_cpus,
+                enable_networking = self.enable_networking,
+                command = ?self.cmd,
+            )
+        )
+    )]
     fn create(self, workspace: &Workspace) -> Result<Container<'_>, CommandError> {
         let mut args: Vec<String> = vec!["create".into()];
 
@@ -306,6 +323,25 @@ impl SandboxBuilder {
 
     #[allow(clippy::too_many_arguments)]
     #[allow(clippy::type_complexity)]
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(
+            skip_all,
+            fields(
+                image = %workspace.sandbox_image().name,
+                mounts = self.mounts.len(),
+                env = self.env.len(),
+                memory_limit = ?self.memory_limit,
+                cpu_limit = ?self.cpu_limit,
+                cpuset_cpus = ?self.cpuset_cpus,
+                enable_networking = self.enable_networking,
+                command = ?self.cmd,
+                capture,
+                timeout_secs = ?timeout.map(|timeout| timeout.as_secs()),
+                no_output_timeout_secs = ?no_output_timeout.map(|timeout| timeout.as_secs()),
+            )
+        )
+    )]
     pub(super) fn run(
         self,
         workspace: &Workspace,
@@ -373,6 +409,7 @@ impl fmt::Display for Container<'_> {
 }
 
 impl Container<'_> {
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn inspect(&self) -> Result<InspectContainer, CommandError> {
         let output = Command::new(self.workspace, "docker")
             .args(&["inspect", &self.id])
@@ -387,6 +424,7 @@ impl Container<'_> {
     }
 
     /// Start the container in detached mode (without `-a`).
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn start(&self) -> Result<(), CommandError> {
         Command::new(self.workspace, "docker")
             .args(&["start", &self.id])
@@ -396,6 +434,7 @@ impl Container<'_> {
     }
 
     /// Stop a running container. Uses `-t 1` to give `sleep infinity` a short grace period.
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn stop(&self) -> Result<(), CommandError> {
         Command::new(self.workspace, "docker")
             .args(&["stop", "-t", "1", &self.id])
@@ -405,6 +444,7 @@ impl Container<'_> {
     }
 
     /// Helper to `docker exec cat <path>` and return stdout lines on success.
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn exec_cat_file(&self, path: &str) -> Option<Vec<String>> {
         Command::new(self.workspace, "docker")
             .args(&["exec", &self.id, "cat", path])
@@ -417,6 +457,7 @@ impl Container<'_> {
 
     /// Best-effort read of peak memory usage from the still-running container.
     /// Tries cgroups v2 first, then falls back to cgroups v1.
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn read_memory_peak(&self) -> Option<u64> {
         let paths = [
             "/sys/fs/cgroup/memory.peak",                      // v2
@@ -439,6 +480,7 @@ impl Container<'_> {
     /// while `sleep infinity` (PID 1) survives. In that case `docker inspect` won't
     /// report `OOMKilled`, so we check the cgroup events directly.
     /// Tries cgroups v2 first, then falls back to cgroups v1.
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn check_cgroup_oom(&self) -> bool {
         // Both v1 and v2 expose `oom_kill <count>` — just in different files.
         let paths = [
@@ -463,6 +505,10 @@ impl Container<'_> {
     }
 
     #[allow(clippy::type_complexity)]
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(container_id = %self.id, capture))
+    )]
     fn run(
         &self,
         timeout: Option<Duration>,
@@ -536,6 +582,7 @@ impl Container<'_> {
         }
     }
 
+    #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     fn delete(&self) -> Result<(), CommandError> {
         Command::new(self.workspace, "docker")
             .args(&["rm", "-f", &self.id])

src/crates/git.rs

@@ -63,7 +63,22 @@ impl GitRepo {
 }
 
 impl CrateTrait for GitRepo {
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(
+            skip_all,
+            fields(url = %self.url, cache_hit = tracing::field::Empty, path = tracing::field::Empty)
+        )
+    )]
     fn fetch(&self, workspace: &Workspace) -> anyhow::Result<()> {
+        let path = self.cached_path(workspace);
+        let cache_hit = path.join("HEAD").is_file();
+        #[cfg(feature = "tracing")]
+        {
+            tracing::Span::current().record("cache_hit", cache_hit);
+            tracing::Span::current().record("path", path.display().to_string());
+        }
+
         // The credential helper that suppresses the password prompt shows this message when a
         // repository requires authentication:
         //
@@ -76,8 +91,7 @@ impl CrateTrait for GitRepo {
             }
         };
 
-        let path = self.cached_path(workspace);
-        let res = if path.join("HEAD").is_file() {
+        let res = if cache_hit {
             info!("updating cached repository {}", self.url);
             Command::new(workspace, "git")
                 .args(&self.suppress_password_prompt_args(workspace))
@@ -113,6 +127,10 @@ impl CrateTrait for GitRepo {
         Ok(())
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(url = %self.url, dest = %dest.display()))
+    )]
     fn copy_source_to(&self, workspace: &Workspace, dest: &Path) -> anyhow::Result<()> {
         Command::new(workspace, "git")
             .args(&["clone"])

src/crates/local.rs

@@ -25,6 +25,13 @@ impl CrateTrait for Local {
         Ok(())
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(
+            skip_all,
+            fields(source = %self.path.display(), dest = %dest.display())
+        )
+    )]
     fn copy_source_to(&self, _workspace: &Workspace, dest: &Path) -> anyhow::Result<()> {
         info!(
             "copying local crate from {} to {}",

src/crates/mod.rs

@@ -57,11 +57,19 @@ impl Crate {
 
     /// Fetch the crate's source code and cache it in the workspace. This method will reach out to
     /// the network for some crate types.
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(krate = %self))
+    )]
     pub fn fetch(&self, workspace: &Workspace) -> anyhow::Result<()> {
         self.as_trait().fetch(workspace)
     }
 
     /// Remove the cached copy of this crate. The method will do nothing if the crate isn't cached.
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(krate = %self))
+    )]
     pub fn purge_from_cache(&self, workspace: &Workspace) -> anyhow::Result<()> {
         self.as_trait().purge_from_cache(workspace)
     }
@@ -79,6 +87,10 @@ impl Crate {
     /// copy the source of this crate to the specified destination path.
     ///
     /// Will delete the target directory if it already exists.
+    #[cfg_attr(
+        feature = "tracing",
+        tracing::instrument(skip_all, fields(krate = %self, dest = %dest.display()))
+    )]
     pub fn copy_source_to(&self, workspace: &Workspace, dest: &Path) -> anyhow::Result<()> {
         if dest.exists() {
             info!(