Auto merge of #13399 - epage:timing, r=weihanglo

feat(cli): Allow logging to chrome traces

### What does this PR try to resolve?

> The time from executing cargo to executing rustc is 230 ms. I wonder if there’s scope for caching whatever expensive computations cargo is doing here.

*Source: https://davidlattimore.github.io/working-on-rust-iteration-time.html*

This made me curious where the time was going.  I've been meaning to try out `tracing-chrome` for a while and this gave me the opportunity.

This adds `CARGO_LOG_PROFILE=<bool>` and `CARGO_LOG_PROFILE_CAPTURE_ARGS=<bool>` for enabling and controlling these trace files.  These are perma-unstable env variables.

Traces can be viewed at https://ui.perfetto.dev or `chrome://tracing`.

Example: no-op `cargo check` run on `cargo-nextest`:

![image](https://github.com/rust-lang/cargo/assets/60961/f21e9c2d-86f6-41b9-8887-562d4fedb4e8)

TODO
- [ ] Find a place to document this, see https://doc.crates.io/contrib/tests/profiling.html#internal-profiler

### How should we test and review this PR?

I looked in `config/` and didn't see a env variable parser to reuse (`get_cv_with_env` is too specialized).

### Additional information

In past projects, I've been able to use features like this to better understand code bases, bugs, etc.  Hopefully this can evolve to help on-board people one day.

Most of the implementation was inspired by https://github.com/arxanas/git-branchless/blob/2923924dfbff07faa61d50771b6604cb18e64bc8/git-branchless-invoke/src/lib.rs#L55

`tracing-chrome` hasn't received updates recently, but it is also fairly quiet on Issues and PRs, so this might just be "maturity".  It does have over a million downloads.  It also is only enabled if explicitly opted into.

rustup added trace visualization in rust-lang/rustup#3287 using [open telemetry](https://crates.io/crates/tracing-opentelemetry) but it is behind a feature flag and and requires running a server to receive the traces.

Author: bors

Cargo.lock

@@ -99,6 +99,7 @@ time = { version = "0.3", features = ["parsing", "formatting", "serde"] }
 toml = "0.8.10"
 toml_edit = { version = "0.22.6", features = ["serde"] }
 tracing = "0.1.40" # be compatible with rustc_log: https://github.com/rust-lang/rust/blob/e51e98dde6a/compiler/rustc_log/Cargo.toml#L9
+tracing-chrome = "0.7.1"
 tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
 unicase = "2.7.0"
 unicode-width = "0.1.11"
@@ -198,6 +199,7 @@ time.workspace = true
 toml.workspace = true
 toml_edit.workspace = true
 tracing.workspace = true
+tracing-chrome.workspace = true
 tracing-subscriber.workspace = true
 unicase.workspace = true
 unicode-width.workspace = true

Cargo.toml

@@ -18,7 +18,7 @@ mod commands;
 use crate::command_prelude::*;
 
 fn main() {
-    setup_logger();
+    let _guard = setup_logger();
 
     let mut gctx = match GlobalContext::default() {
         Ok(gctx) => gctx,
@@ -41,16 +41,43 @@ fn main() {
     }
 }
 
-fn setup_logger() {
-    let env = tracing_subscriber::EnvFilter::from_env("CARGO_LOG");
+fn setup_logger() -> Option<tracing_chrome::FlushGuard> {
+    #![allow(clippy::disallowed_methods)]
+
+    use tracing_subscriber::prelude::*;
 
-    tracing_subscriber::fmt()
+    let env = tracing_subscriber::EnvFilter::from_env("CARGO_LOG");
+    let fmt_layer = tracing_subscriber::fmt::layer()
         .with_timer(tracing_subscriber::fmt::time::Uptime::default())
         .with_ansi(std::io::IsTerminal::is_terminal(&std::io::stderr()))
         .with_writer(std::io::stderr)
-        .with_env_filter(env)
-        .init();
+        .with_filter(env);
+
+    let (profile_layer, profile_guard) =
+        if env_to_bool(std::env::var_os("CARGO_LOG_PROFILE").as_deref()) {
+            let capture_args =
+                env_to_bool(std::env::var_os("CARGO_LOG_PROFILE_CAPTURE_ARGS").as_deref());
+            let (layer, guard) = tracing_chrome::ChromeLayerBuilder::new()
+                .include_args(capture_args)
+                .build();
+            (Some(layer), Some(guard))
+        } else {
+            (None, None)
+        };
+
+    let registry = tracing_subscriber::registry()
+        .with(fmt_layer)
+        .with(profile_layer);
+    registry.init();
     tracing::trace!(start = humantime::format_rfc3339(std::time::SystemTime::now()).to_string());
+    profile_guard
+}
+
+fn env_to_bool(os: Option<&OsStr>) -> bool {
+    match os.and_then(|os| os.to_str()) {
+        Some("1") | Some("true") => true,
+        _ => false,
+    }
 }
 
 /// Table for defining the aliases which come builtin in `Cargo`.

src/bin/cargo/main.rs

@@ -9,7 +9,6 @@ use crate::core::compiler::{self, artifact, Unit};
 use crate::core::PackageId;
 use crate::util::cache_lock::CacheLockMode;
 use crate::util::errors::CargoResult;
-use crate::util::profile;
 use anyhow::{bail, Context as _};
 use filetime::FileTime;
 use itertools::Itertools;
@@ -353,8 +352,6 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
     /// place.
     #[tracing::instrument(skip_all)]
     pub fn prepare(&mut self) -> CargoResult<()> {
-        let _p = profile::start("preparing layout");
-
         self.files
             .as_mut()
             .unwrap()

src/cargo/core/compiler/build_runner/mod.rs

@@ -38,8 +38,8 @@ use crate::core::compiler::fingerprint::DirtyReason;
 use crate::core::compiler::job_queue::JobState;
 use crate::core::{profiles::ProfileRoot, PackageId, Target};
 use crate::util::errors::CargoResult;
+use crate::util::internal;
 use crate::util::machine_message::{self, Message};
-use crate::util::{internal, profile};
 use anyhow::{bail, Context as _};
 use cargo_platform::Cfg;
 use cargo_util::paths;
@@ -196,12 +196,6 @@ impl LinkArgTarget {
 /// Prepares a `Work` that executes the target as a custom build script.
 #[tracing::instrument(skip_all)]
 pub fn prepare(build_runner: &mut BuildRunner<'_, '_>, unit: &Unit) -> CargoResult<Job> {
-    let _p = profile::start(format!(
-        "build script prepare: {}/{}",
-        unit.pkg,
-        unit.target.name()
-    ));
-
     let metadata = build_runner.get_run_build_script_metadata(unit);
     if build_runner
         .build_script_outputs

src/cargo/core/compiler/custom_build.rs

@@ -377,7 +377,7 @@ use crate::core::Package;
 use crate::util::errors::CargoResult;
 use crate::util::interning::InternedString;
 use crate::util::{self, try_canonicalize};
-use crate::util::{internal, path_args, profile, StableHasher};
+use crate::util::{internal, path_args, StableHasher};
 use crate::{GlobalContext, CARGO_ENV};
 
 use super::custom_build::BuildDeps;
@@ -408,11 +408,6 @@ pub fn prepare_target(
     unit: &Unit,
     force: bool,
 ) -> CargoResult<Job> {
-    let _p = profile::start(format!(
-        "fingerprint: {} / {}",
-        unit.pkg.package_id(),
-        unit.target.name()
-    ));
     let bcx = build_runner.bcx;
     let loc = build_runner.files().fingerprint_file_path(unit, "");
 

src/cargo/core/compiler/fingerprint/mod.rs

@@ -144,7 +144,7 @@ use crate::util::diagnostic_server::{self, DiagnosticPrinter};
 use crate::util::errors::AlreadyPrintedError;
 use crate::util::machine_message::{self, Message as _};
 use crate::util::CargoResult;
-use crate::util::{self, internal, profile};
+use crate::util::{self, internal};
 use crate::util::{DependencyQueue, GlobalContext, Progress, ProgressStyle, Queue};
 
 /// This structure is backed by the `DependencyQueue` type and manages the
@@ -473,7 +473,6 @@ impl<'gctx> JobQueue<'gctx> {
         build_runner: &mut BuildRunner<'_, '_>,
         plan: &mut BuildPlan,
     ) -> CargoResult<()> {
-        let _p = profile::start("executing the job graph");
         self.queue.queue_finished();
 
         let progress =

src/cargo/core/compiler/job_queue/mod.rs

@@ -93,7 +93,7 @@ use crate::core::{Feature, PackageId, Target, Verbosity};
 use crate::util::errors::{CargoResult, VerboseError};
 use crate::util::interning::InternedString;
 use crate::util::machine_message::{self, Message};
-use crate::util::{add_path_args, internal, profile};
+use crate::util::{add_path_args, internal};
 use cargo_util::{paths, ProcessBuilder, ProcessError};
 use cargo_util_schemas::manifest::TomlDebugInfo;
 use cargo_util_schemas::manifest::TomlTrimPaths;
@@ -175,7 +175,6 @@ fn compile<'gctx>(
 
     // Build up the work to be done to compile this unit, enqueuing it once
     // we've got everything constructed.
-    let p = profile::start(format!("preparing: {}/{}", unit.pkg, unit.target.name()));
     fingerprint::prepare_init(build_runner, unit)?;
 
     let job = if unit.mode.is_run_custom_build() {
@@ -216,7 +215,6 @@ fn compile<'gctx>(
         job
     };
     jobs.enqueue(build_runner, unit, job)?;
-    drop(p);
 
     // Be sure to compile all dependencies of this target as well.
     let deps = Vec::from(build_runner.unit_deps(unit)); // Create vec due to mutable borrow.

src/cargo/core/compiler/mod.rs

@@ -552,7 +552,6 @@ impl GlobalCacheTracker {
         clean_ctx: &mut CleanContext<'_>,
         gc_opts: &GcOpts,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start("cleaning global cache files");
         let gctx = clean_ctx.gctx;
         let base = BasePaths {
             index: gctx.registry_index_path().into_path_unlocked(),
@@ -706,7 +705,6 @@ impl GlobalCacheTracker {
         sync_size: bool,
         delete_paths: &mut Vec<PathBuf>,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start("global cache db sync");
         debug!(target: "gc", "starting db sync");
         // For registry_index and git_db, add anything that is missing in the db.
         Self::update_parent_for_missing_from_db(conn, now, REGISTRY_INDEX_TABLE, &base.index)?;
@@ -804,9 +802,6 @@ impl GlobalCacheTracker {
         parent_table_name: &str,
         base_path: &Path,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start(format!(
-            "update parent db for missing from db {parent_table_name}"
-        ));
         trace!(target: "gc", "checking for untracked parent to add to {parent_table_name}");
         let names = Self::names_from(base_path)?;
 
@@ -833,7 +828,6 @@ impl GlobalCacheTracker {
         table_name: &str,
         base_path: &Path,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start(format!("update db for removed {table_name}"));
         trace!(target: "gc", "checking for db entries to remove from {table_name}");
         let mut select_stmt = conn.prepare_cached(&format!(
             "SELECT {table_name}.rowid, {parent_table_name}.name, {table_name}.name
@@ -863,9 +857,6 @@ impl GlobalCacheTracker {
         child_base_paths: &[&Path],
         delete_paths: &mut Vec<PathBuf>,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start(format!(
-            "update db parent for removed from disk {parent_table_name}"
-        ));
         trace!(target: "gc", "checking for db entries to remove from {parent_table_name}");
         let mut select_stmt =
             conn.prepare_cached(&format!("SELECT rowid, name FROM {parent_table_name}"))?;
@@ -899,7 +890,6 @@ impl GlobalCacheTracker {
         now: Timestamp,
         base_path: &Path,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start("populate untracked crate");
         trace!(target: "gc", "populating untracked crate files");
         let mut insert_stmt = conn.prepare_cached(
             "INSERT INTO registry_crate (registry_id, name, size, timestamp)
@@ -939,7 +929,6 @@ impl GlobalCacheTracker {
         base_path: &Path,
         populate_size: bool,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start(format!("populate untracked {table_name}"));
         trace!(target: "gc", "populating untracked files for {table_name}");
         // Gather names (and make sure they are in the database).
         let id_names = Self::names_from(&base_path)?;
@@ -1003,7 +992,6 @@ impl GlobalCacheTracker {
         table_name: &str,
         base_path: &Path,
     ) -> CargoResult<()> {
-        let _p = crate::util::profile::start(format!("update NULL sizes {table_name}"));
         trace!(target: "gc", "updating NULL size information in {table_name}");
         let mut null_stmt = conn.prepare_cached(&format!(
             "SELECT {table_name}.rowid, {table_name}.name, {parent_table_name}.name
@@ -1570,7 +1558,6 @@ impl DeferredGlobalLastUse {
     /// This will also clear the state of `self`.
     #[tracing::instrument(skip_all)]
     pub fn save(&mut self, tracker: &mut GlobalCacheTracker) -> CargoResult<()> {
-        let _p = crate::util::profile::start("saving last-use data");
         trace!(target: "gc", "saving last-use data");
         if self.is_empty() {
             return Ok(());

src/cargo/core/global_cache_tracker.rs

@@ -455,8 +455,6 @@ impl<'a, 'gctx> FeatureResolver<'a, 'gctx> {
         requested_targets: &[CompileKind],
         opts: FeatureOpts,
     ) -> CargoResult<ResolvedFeatures> {
-        use crate::util::profile;
-        let _p = profile::start("resolve features");
         let track_for_host = opts.decouple_host_deps || opts.ignore_inactive_targets;
         let mut r = FeatureResolver {
             ws,

src/cargo/core/resolver/features.rs

@@ -70,7 +70,6 @@ use crate::core::{Dependency, PackageId, Registry, Summary};
 use crate::util::context::GlobalContext;
 use crate::util::errors::CargoResult;
 use crate::util::network::PollExt;
-use crate::util::profile;
 
 use self::context::ResolverContext;
 use self::dep_cache::RegistryQueryer;
@@ -131,7 +130,6 @@ pub fn resolve(
     resolve_version: ResolveVersion,
     gctx: Option<&GlobalContext>,
 ) -> CargoResult<Resolve> {
-    let _p = profile::start("resolving");
     let first_version = match gctx {
         Some(config) if config.cli_unstable().direct_minimal_versions => {
             Some(VersionOrdering::MinimumVersionsFirst)

src/cargo/core/resolver/mod.rs

@@ -54,7 +54,7 @@ use crate::ops;
 use crate::ops::resolve::WorkspaceResolve;
 use crate::util::context::GlobalContext;
 use crate::util::interning::InternedString;
-use crate::util::{profile, CargoResult, StableHasher};
+use crate::util::{CargoResult, StableHasher};
 
 mod compile_filter;
 pub use compile_filter::{CompileFilter, FilterRule, LibRule};
@@ -155,7 +155,6 @@ pub fn compile_ws<'a>(
         return Compilation::new(&bcx);
     }
     crate::core::gc::auto_gc(bcx.gctx);
-    let _p = profile::start("compiling");
     let build_runner = BuildRunner::new(&bcx)?;
     build_runner.compile(exec)
 }

src/cargo/ops/cargo_compile/mod.rs

@@ -71,7 +71,7 @@ use crate::ops;
 use crate::sources::PathSource;
 use crate::util::cache_lock::CacheLockMode;
 use crate::util::errors::CargoResult;
-use crate::util::{profile, CanonicalUrl};
+use crate::util::CanonicalUrl;
 use anyhow::Context as _;
 use std::collections::{HashMap, HashSet};
 use tracing::{debug, trace};
@@ -147,8 +147,6 @@ pub fn resolve_ws_with_opts<'gctx>(
         // Second, resolve with precisely what we're doing. Filter out
         // transitive dependencies if necessary, specify features, handle
         // overrides, etc.
-        let _p = profile::start("resolving with overrides...");
-
         add_overrides(&mut registry, ws)?;
 
         for (replace_spec, dep) in ws.root_replace() {

src/cargo/ops/resolve.rs

@@ -54,7 +54,6 @@ pub mod job;
 mod lockserver;
 pub mod machine_message;
 pub mod network;
-pub mod profile;
 mod progress;
 mod queue;
 pub mod restricted_names;