fix(cli): Trace core cargo operations

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...

Author: epage

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,