Auto merge of #13532 - epage:t, r=weihanglo

fix(cli): Trace core cargo operations

### What does this PR try to resolve?

This is preparation for #13339 and covers hot spots I found as well as areas currently covered by `profile::start(...)`.

This is split out to avoid conflicts while working through the remaining issues for #13339.
Maybe it will also serve to help debugging...

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

### Additional information

```console
$ rg profile::start src/
src/cargo/ops/cargo_compile/mod.rs:    let _p = profile::start("compiling");
src/cargo/ops/resolve.rs:        let _p = profile::start("resolving with overrides...");
src/cargo/util/rustc.rs:        let _p = profile::start("Rustc::new");
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start("cleaning global cache files");
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start("global cache db sync");
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start(format!(
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start(format!("update db for removed {table_name}"));
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start(format!(
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start("populate untracked crate");
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start(format!("populate untracked {table_name}"));
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start(format!("update NULL sizes {table_name}"));
src/cargo/core/global_cache_tracker.rs:        let _p = crate::util::profile::start("saving last-use data");
src/cargo/core/resolver/features.rs:        let _p = profile::start("resolve features");
src/cargo/core/resolver/mod.rs:    let _p = profile::start("resolving");
src/cargo/core/compiler/fingerprint/mod.rs:    let _p = profile::start(format!(
src/cargo/core/compiler/mod.rs:    let p = profile::start(format!("preparing: {}/{}", unit.pkg, unit.target.name()));
src/cargo/core/compiler/build_runner/mod.rs:        let _p = profile::start("preparing layout");
src/cargo/core/compiler/custom_build.rs:    let _p = profile::start(format!(
src/cargo/core/compiler/job_queue/mod.rs:        let _p = profile::start("executing the job graph");

```

Author: bors

src/bin/cargo/cli.rs

@@ -16,6 +16,7 @@ use crate::util::is_rustup;
 use cargo::core::shell::ColorChoice;
 use cargo::util::style;
 
+#[tracing::instrument(skip_all)]
 pub fn main(gctx: &mut GlobalContext) -> CliResult {
     // CAUTION: Be careful with using `config` until it is configured below.
     // In general, try to avoid loading config values unless necessary (like
@@ -272,6 +273,7 @@ fn add_ssl(version_string: &mut String) {
 /// [`GlobalArgs`] need to be extracted before expanding aliases because the
 /// clap code for extracting a subcommand discards global options
 /// (appearing before the subcommand).
+#[tracing::instrument(skip_all)]
 fn expand_aliases(
     gctx: &mut GlobalContext,
     args: ArgMatches,
@@ -377,6 +379,7 @@ For more information, see issue #12207 <https://github.com/rust-lang/cargo/issue
     Ok((args, GlobalArgs::default()))
 }
 
+#[tracing::instrument(skip_all)]
 fn configure_gctx(
     gctx: &mut GlobalContext,
     args: &ArgMatches,
@@ -459,6 +462,7 @@ impl Exec {
         }
     }
 
+    #[tracing::instrument(skip_all)]
     fn exec(self, gctx: &mut GlobalContext, subcommand_args: &ArgMatches) -> CliResult {
         match self {
             Self::Builtin(exec) => exec(gctx, subcommand_args),
@@ -530,6 +534,7 @@ impl GlobalArgs {
     }
 }
 
+#[tracing::instrument(skip_all)]
 pub fn cli(gctx: &GlobalContext) -> Command {
     // Don't let config errors get in the way of parsing arguments
     let term = gctx.get::<TermConfig>("term").unwrap_or_default();

src/bin/cargo/main.rs

@@ -287,6 +287,7 @@ fn search_directories(gctx: &GlobalContext) -> Vec<PathBuf> {
 }
 
 /// Initialize libgit2.
+#[tracing::instrument(skip_all)]
 fn init_git(gctx: &GlobalContext) {
     // Disabling the owner validation in git can, in theory, lead to code execution
     // vulnerabilities. However, libgit2 does not launch executables, which is the foundation of
@@ -318,6 +319,7 @@ fn init_git(gctx: &GlobalContext) {
 /// If the user has a non-default network configuration, then libgit2 will be
 /// configured to use libcurl instead of the built-in networking support so
 /// that those configuration settings can be used.
+#[tracing::instrument(skip_all)]
 fn init_git_transports(gctx: &GlobalContext) {
     match needs_custom_http_transport(gctx) {
         Ok(true) => {}

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

@@ -133,6 +133,7 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
     /// See [`ops::cargo_compile`] for a higher-level view of the compile process.
     ///
     /// [`ops::cargo_compile`]: ../../../ops/cargo_compile/index.html
+    #[tracing::instrument(skip_all)]
     pub fn compile(mut self, exec: &Arc<dyn Executor>) -> CargoResult<Compilation<'gctx>> {
         // A shared lock is held during the duration of the build since rustc
         // needs to read from the `src` cache, and we don't want other
@@ -324,6 +325,7 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
             .map(|output| output.bin_dst().clone()))
     }
 
+    #[tracing::instrument(skip_all)]
     pub fn prepare_units(&mut self) -> CargoResult<()> {
         let dest = self.bcx.profiles.get_dir_name();
         let host_layout = Layout::new(self.bcx.ws, None, &dest)?;
@@ -349,6 +351,7 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
 
     /// Prepare this context, ensuring that all filesystem directories are in
     /// place.
+    #[tracing::instrument(skip_all)]
     pub fn prepare(&mut self) -> CargoResult<()> {
         let _p = profile::start("preparing layout");
 
@@ -451,6 +454,7 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
 
     /// Check if any output file name collision happens.
     /// See <https://github.com/rust-lang/cargo/issues/6313> for more.
+    #[tracing::instrument(skip_all)]
     fn check_collisions(&self) -> CargoResult<()> {
         let mut output_collisions = HashMap::new();
         let describe_collision = |unit: &Unit, other_unit: &Unit, path: &PathBuf| -> String {
@@ -633,6 +637,7 @@ impl<'a, 'gctx> BuildRunner<'a, 'gctx> {
     /// If the current crate has reverse-dependencies, such a Check unit should exist, and so
     /// we use that crate's metadata. If not, we use the crate's Doc unit so at least examples
     /// scraped from the current crate can be used when documenting the current crate.
+    #[tracing::instrument(skip_all)]
     pub fn compute_metadata_for_doc_units(&mut self) {
         for unit in self.bcx.unit_graph.keys() {
             if !unit.mode.is_doc() && !unit.mode.is_doc_scrape() {

src/cargo/core/compiler/custom_build.rs

@@ -194,6 +194,7 @@ 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: {}/{}",

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

@@ -399,6 +399,7 @@ pub use dirty_reason::DirtyReason;
 /// transitively propagate throughout the dependency graph, it only forces this
 /// one unit which is very unlikely to be what you want unless you're
 /// exclusively talking about top-level units.
+#[tracing::instrument(skip(build_runner, unit))]
 pub fn prepare_target(
     build_runner: &mut BuildRunner<'_, '_>,
     unit: &Unit,

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

@@ -467,6 +467,7 @@ impl<'gctx> JobQueue<'gctx> {
     /// This function will spawn off `config.jobs()` workers to build all of the
     /// necessary dependencies, in order. Freshness is propagated as far as
     /// possible along each dependency chain.
+    #[tracing::instrument(skip_all)]
     pub fn execute(
         mut self,
         build_runner: &mut BuildRunner<'_, '_>,

src/cargo/core/compiler/mod.rs

@@ -158,6 +158,7 @@ impl Executor for DefaultExecutor {
 /// Note that **no actual work is executed as part of this**, that's all done
 /// next as part of [`JobQueue::execute`] function which will run everything
 /// in order with proper parallelism.
+#[tracing::instrument(skip(build_runner, jobs, plan, exec))]
 fn compile<'gctx>(
     build_runner: &mut BuildRunner<'_, 'gctx>,
     jobs: &mut JobQueue<'gctx>,

src/cargo/core/compiler/unit_dependencies.rs

@@ -81,6 +81,7 @@ impl IsArtifact {
 /// Then entry point for building a dependency graph of compilation units.
 ///
 /// You can find some information for arguments from doc of [`State`].
+#[tracing::instrument(skip_all)]
 pub fn build_unit_dependencies<'a, 'gctx>(
     ws: &'a Workspace<'gctx>,
     package_set: &'a PackageSet<'gctx>,

src/cargo/core/global_cache_tracker.rs

@@ -546,6 +546,7 @@ impl GlobalCacheTracker {
             .with_context(|| "failed to clean entries from the global cache")
     }
 
+    #[tracing::instrument(skip_all)]
     fn clean_inner(
         &mut self,
         clean_ctx: &mut CleanContext<'_>,
@@ -696,6 +697,7 @@ impl GlobalCacheTracker {
     ///
     ///    These orphaned files will be added to `delete_paths` so that the
     ///    caller can delete them.
+    #[tracing::instrument(skip_all)]
     fn sync_db_with_files(
         conn: &Connection,
         now: Timestamp,
@@ -795,6 +797,7 @@ impl GlobalCacheTracker {
     }
 
     /// For parent tables, add any entries that are on disk but aren't tracked in the db.
+    #[tracing::instrument(skip_all)]
     fn update_parent_for_missing_from_db(
         conn: &Connection,
         now: Timestamp,
@@ -822,6 +825,7 @@ impl GlobalCacheTracker {
     ///
     /// This could happen for example if the user manually deleted the file or
     /// any such scenario where the filesystem and db are out of sync.
+    #[tracing::instrument(skip_all)]
     fn update_db_for_removed(
         conn: &Connection,
         parent_table_name: &str,
@@ -851,6 +855,7 @@ impl GlobalCacheTracker {
     }
 
     /// Removes database entries for any files that are not on disk for the parent tables.
+    #[tracing::instrument(skip_all)]
     fn update_db_parent_for_removed_from_disk(
         conn: &Connection,
         parent_table_name: &str,
@@ -888,6 +893,7 @@ impl GlobalCacheTracker {
     /// Updates the database to add any `.crate` files that are currently
     /// not tracked (such as when they are downloaded by an older version of
     /// cargo).
+    #[tracing::instrument(skip_all)]
     fn populate_untracked_crate(
         conn: &Connection,
         now: Timestamp,
@@ -922,6 +928,7 @@ impl GlobalCacheTracker {
 
     /// Updates the database to add any files that are currently not tracked
     /// (such as when they are downloaded by an older version of cargo).
+    #[tracing::instrument(skip_all)]
     fn populate_untracked(
         conn: &Connection,
         now: Timestamp,
@@ -987,6 +994,7 @@ impl GlobalCacheTracker {
     /// size.
     ///
     /// `update_db_for_removed` should be called before this is called.
+    #[tracing::instrument(skip_all)]
     fn update_null_sizes(
         conn: &Connection,
         gctx: &GlobalContext,
@@ -1560,6 +1568,7 @@ impl DeferredGlobalLastUse {
     /// Saves all of the deferred information to the database.
     ///
     /// 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");

src/cargo/core/package.rs

@@ -497,6 +497,7 @@ impl<'gctx> PackageSet<'gctx> {
     }
 
     /// Downloads any packages accessible from the give root ids.
+    #[tracing::instrument(skip_all)]
     pub fn download_accessible(
         &self,
         resolve: &Resolve,

src/cargo/core/resolver/features.rs

@@ -444,6 +444,7 @@ pub struct FeatureResolver<'a, 'gctx> {
 impl<'a, 'gctx> FeatureResolver<'a, 'gctx> {
     /// Runs the resolution algorithm and returns a new [`ResolvedFeatures`]
     /// with the result.
+    #[tracing::instrument(skip_all)]
     pub fn resolve(
         ws: &Workspace<'gctx>,
         target_data: &'a mut RustcTargetData<'gctx>,

src/cargo/core/resolver/mod.rs

@@ -122,6 +122,7 @@ mod version_prefs;
 ///
 /// * `config` - a location to print warnings and such, or `None` if no warnings
 ///   should be printed
+#[tracing::instrument(skip_all)]
 pub fn resolve(
     summaries: &[(Summary, ResolveOpts)],
     replacements: &[(PackageIdSpec, Dependency)],

src/cargo/ops/cargo_compile/mod.rs

@@ -142,6 +142,7 @@ pub fn compile_with_exec<'a>(
 }
 
 /// Like [`compile_with_exec`] but without warnings from manifest parsing.
+#[tracing::instrument(skip_all)]
 pub fn compile_ws<'a>(
     ws: &Workspace<'a>,
     options: &CompileOptions,
@@ -197,6 +198,7 @@ pub fn print<'a>(
 ///
 /// For how it works and what data it collects,
 /// please see the [module-level documentation](self).
+#[tracing::instrument(skip_all)]
 pub fn create_bcx<'a, 'gctx>(
     ws: &'a Workspace<'gctx>,
     options: &'a CompileOptions,

src/cargo/ops/lockfile.rs

@@ -6,6 +6,7 @@ use crate::util::Filesystem;
 
 use anyhow::Context as _;
 
+#[tracing::instrument(skip_all)]
 pub fn load_pkg_lockfile(ws: &Workspace<'_>) -> CargoResult<Option<Resolve>> {
     let lock_root = lock_root(ws);
     if !lock_root.as_path_unlocked().join("Cargo.lock").exists() {
@@ -32,6 +33,7 @@ pub fn resolve_to_string(ws: &Workspace<'_>, resolve: &mut Resolve) -> CargoResu
     Ok(out)
 }
 
+#[tracing::instrument(skip_all)]
 pub fn write_pkg_lockfile(ws: &Workspace<'_>, resolve: &mut Resolve) -> CargoResult<()> {
     let (orig, mut out, lock_root) = resolve_to_string_orig(ws, resolve);
 

src/cargo/ops/resolve.rs

@@ -234,6 +234,7 @@ pub fn resolve_ws_with_opts<'gctx>(
     })
 }
 
+#[tracing::instrument(skip_all)]
 fn resolve_with_registry<'gctx>(
     ws: &Workspace<'gctx>,
     registry: &mut PackageRegistry<'gctx>,
@@ -271,6 +272,7 @@ fn resolve_with_registry<'gctx>(
 ///
 /// If `register_patches` is true, then entries from the `[patch]` table in
 /// the manifest will be added to the given `PackageRegistry`.
+#[tracing::instrument(skip_all)]
 pub fn resolve_with_previous<'gctx>(
     registry: &mut PackageRegistry<'gctx>,
     ws: &Workspace<'gctx>,
@@ -529,6 +531,7 @@ pub fn resolve_with_previous<'gctx>(
 
 /// Read the `paths` configuration variable to discover all path overrides that
 /// have been configured.
+#[tracing::instrument(skip_all)]
 pub fn add_overrides<'a>(
     registry: &mut PackageRegistry<'a>,
     ws: &Workspace<'a>,

src/cargo/util/command_prelude.rs

@@ -500,6 +500,7 @@ pub trait ArgMatchesExt {
         root_manifest(self._value_of("manifest-path").map(Path::new), gctx)
     }
 
+    #[tracing::instrument(skip_all)]
     fn workspace<'a>(&self, gctx: &'a GlobalContext) -> CargoResult<Workspace<'a>> {
         let root = self.root_manifest(gctx)?;
         let mut ws = Workspace::new(&root, gctx)?;

src/cargo/util/context/mod.rs

@@ -1945,6 +1945,7 @@ impl GlobalContext {
     /// Locks are usually acquired via [`GlobalContext::acquire_package_cache_lock`]
     /// or [`GlobalContext::try_acquire_package_cache_lock`].
     #[track_caller]
+    #[tracing::instrument(skip_all)]
     pub fn assert_package_cache_locked<'a>(
         &self,
         mode: CacheLockMode,
@@ -1965,6 +1966,7 @@ impl GlobalContext {
     ///
     /// See [`crate::util::cache_lock`] for an in-depth discussion of locking
     /// and lock modes.
+    #[tracing::instrument(skip_all)]
     pub fn acquire_package_cache_lock(&self, mode: CacheLockMode) -> CargoResult<CacheLock<'_>> {
         self.package_cache_lock.lock(self, mode)
     }
@@ -1974,6 +1976,7 @@ impl GlobalContext {
     ///
     /// See [`crate::util::cache_lock`] for an in-depth discussion of locking
     /// and lock modes.
+    #[tracing::instrument(skip_all)]
     pub fn try_acquire_package_cache_lock(
         &self,
         mode: CacheLockMode,

src/cargo/util/rustc.rs

@@ -39,6 +39,7 @@ impl Rustc {
     ///
     /// If successful this function returns a description of the compiler along
     /// with a list of its capabilities.
+    #[tracing::instrument(skip(gctx))]
     pub fn new(
         path: PathBuf,
         wrapper: Option<PathBuf>,

src/cargo/util/toml/mod.rs

@@ -44,6 +44,7 @@ use self::targets::targets;
 /// within the manifest. For virtual manifests, these paths can only
 /// come from patched or replaced dependencies. These paths are not
 /// canonicalized.
+#[tracing::instrument(skip(gctx))]
 pub fn read_manifest(
     path: &Path,
     source_id: SourceId,