Correctly show executed command name in Chrome trace

Author: Kobzol

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

@@ -2469,7 +2469,7 @@ pub fn stream_cargo(
     let mut cmd = cargo.into_cmd();
 
     #[cfg(feature = "tracing")]
-    let _run_span = crate::trace_cmd!(cmd);
+    let _run_span = crate::utils::tracing::trace_cmd(&cmd);
 
     // Instruct Cargo to give us json messages on stdout, critically leaving
     // stderr as piped so we can get those pretty colors.

src/bootstrap/src/core/builder/mod.rs

@@ -948,7 +948,7 @@ impl Step for Libdir {
 }
 
 #[cfg(feature = "tracing")]
-pub const STEP_NAME_TARGET: &str = "STEP";
+pub const STEP_SPAN_TARGET: &str = "STEP";
 
 impl<'a> Builder<'a> {
     fn get_step_descriptions(kind: Kind) -> Vec<StepDescription> {
@@ -1713,7 +1713,7 @@ You have to build a stage1 compiler for `{}` first, and then use it to build a s
             let _span = {
                 // Keep the target and field names synchronized with `setup_tracing`.
                 let span = tracing::info_span!(
-                    target: STEP_NAME_TARGET,
+                    target: STEP_SPAN_TARGET,
                     // We cannot use a dynamic name here, so instead we record the actual step name
                     // in the step_name field.
                     "step",

src/bootstrap/src/lib.rs

@@ -44,7 +44,7 @@ mod utils;
 
 pub use core::builder::PathSet;
 #[cfg(feature = "tracing")]
-pub use core::builder::STEP_NAME_TARGET;
+pub use core::builder::STEP_SPAN_TARGET;
 pub use core::config::flags::{Flags, Subcommand};
 pub use core::config::{ChangeId, Config};
 

src/bootstrap/src/utils/exec.rs

@@ -26,8 +26,6 @@ use build_helper::drop_bomb::DropBomb;
 use build_helper::exit;
 
 use crate::core::config::DryRun;
-#[cfg(feature = "tracing")]
-use crate::trace_cmd;
 use crate::{PathBuf, t};
 
 /// What should be done when the command fails.
@@ -76,9 +74,17 @@ pub struct CommandFingerprint {
 }
 
 impl CommandFingerprint {
+    #[cfg(feature = "tracing")]
+    pub(crate) fn program_name(&self) -> String {
+        Path::new(&self.program)
+            .file_name()
+            .map(|p| p.to_string_lossy().to_string())
+            .unwrap_or_else(|| "<unknown command>".to_string())
+    }
+
     /// Helper method to format both Command and BootstrapCommand as a short execution line,
     /// without all the other details (e.g. environment variables).
-    pub fn format_short_cmd(&self) -> String {
+    pub(crate) fn format_short_cmd(&self) -> String {
         use std::fmt::Write;
 
         let mut cmd = self.program.to_string_lossy().to_string();
@@ -676,7 +682,7 @@ impl ExecutionContext {
         let fingerprint = command.fingerprint();
 
         #[cfg(feature = "tracing")]
-        let span_guard = trace_cmd!(command);
+        let span_guard = crate::utils::tracing::trace_cmd(command);
 
         if let Some(cached_output) = self.command_cache.get(&fingerprint) {
             command.mark_as_executed();
@@ -768,7 +774,7 @@ impl ExecutionContext {
         }
 
         #[cfg(feature = "tracing")]
-        let span_guard = trace_cmd!(command);
+        let span_guard = crate::utils::tracing::trace_cmd(command);
 
         let start_time = Instant::now();
         let fingerprint = command.fingerprint();

src/bootstrap/src/utils/tracing.rs

@@ -48,19 +48,21 @@ macro_rules! error {
     }
 }
 
-#[macro_export]
-macro_rules! trace_cmd {
-    ($cmd:expr) => {
-        {
-            ::tracing::span!(
-                target: "COMMAND",
-                ::tracing::Level::TRACE,
-                "cmd",
-                cmd = $cmd.fingerprint().format_short_cmd(),
-                full_cmd = ?$cmd
-            ).entered()
-        }
-    };
+#[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();
+    tracing::span!(
+        target: COMMAND_SPAN_TARGET,
+        tracing::Level::TRACE,
+        "cmd",
+        cmd_name = fingerprint.program_name().to_string(),
+        cmd = fingerprint.format_short_cmd(),
+        full_cmd = ?command
+    )
+    .entered()
 }
 
 // # Note on `tracing` usage in bootstrap
@@ -87,7 +89,8 @@ mod inner {
     use tracing_subscriber::registry::{LookupSpan, SpanRef};
     use tracing_subscriber::{EnvFilter, Layer};
 
-    use crate::STEP_NAME_TARGET;
+    use crate::STEP_SPAN_TARGET;
+    use crate::utils::tracing::COMMAND_SPAN_TARGET;
 
     pub fn setup_tracing(profiling_enabled: bool) -> Option<TracingGuard> {
         let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");
@@ -110,10 +113,14 @@ mod inner {
                 .name_fn(Box::new(|event_or_span| match event_or_span {
                     tracing_chrome::EventOrSpan::Event(e) => e.metadata().name().to_string(),
                     tracing_chrome::EventOrSpan::Span(s) => {
-                        if s.metadata().target() == STEP_NAME_TARGET
+                        if s.metadata().target() == STEP_SPAN_TARGET
                             && let Some(extension) = s.extensions().get::<StepNameExtension>()
                         {
                             extension.0.clone()
+                        } else if s.metadata().target() == COMMAND_SPAN_TARGET
+                            && let Some(extension) = s.extensions().get::<CommandNameExtension>()
+                        {
+                            extension.0.clone()
                         } else {
                             s.metadata().name().to_string()
                         }
@@ -151,6 +158,8 @@ mod inner {
         message: Option<String>,
         /// Name of a recorded psna
         step_name: Option<String>,
+        /// Short name of an executed command
+        cmd_name: Option<String>,
         /// The rest of arbitrary event/span fields
         fields: Vec<(&'static str, String)>,
     }
@@ -163,6 +172,9 @@ mod inner {
                 "step_name" => {
                     self.step_name = Some(value.to_string());
                 }
+                "cmd_name" => {
+                    self.cmd_name = Some(value.to_string());
+                }
                 name => {
                     self.fields.push((name, value.to_string()));
                 }
@@ -187,9 +199,12 @@ mod inner {
         Enter,
     }
 
-    /// Holds the name of a step, stored in `tracing_subscriber`'s extensions.
+    /// Holds the name of a step span, stored in `tracing_subscriber`'s extensions.
     struct StepNameExtension(String);
 
+    /// Holds the name of a command span, stored in `tracing_subscriber`'s extensions.
+    struct CommandNameExtension(String);
+
     #[derive(Default)]
     struct TracingPrinter {
         indent: std::sync::atomic::AtomicU32,
@@ -264,7 +279,7 @@ mod inner {
             // 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.
-            if span.metadata().target() == STEP_NAME_TARGET {
+            if span.metadata().target() == STEP_SPAN_TARGET {
                 let name = field_values.and_then(|v| v.step_name.as_deref()).unwrap_or(span.name());
                 write!(writer, "{name}")?;
 
@@ -334,8 +349,14 @@ mod inner {
 
             // We need to propagate the actual name of the span to the Chrome layer below, because
             // it cannot access field values. We do that through extensions.
-            if let Some(step_name) = field_values.step_name.clone() {
+            if attrs.metadata().target() == STEP_SPAN_TARGET
+                && let Some(step_name) = field_values.step_name.clone()
+            {
                 ctx.span(id).unwrap().extensions_mut().insert(StepNameExtension(step_name));
+            } else if attrs.metadata().target() == COMMAND_SPAN_TARGET
+                && let Some(cmd_name) = field_values.cmd_name.clone()
+            {
+                ctx.span(id).unwrap().extensions_mut().insert(CommandNameExtension(cmd_name));
             }
             self.span_values.lock().unwrap().insert(id.clone(), field_values);
         }