worker: add more fine-grained logging for Git index syncs (#12282)

This should be reverted once we have the data we need, but in the short
term, this will be useful to decide our next step with #12281.

Author: LawnGnome

crates/crates_io_index/repo.rs

@@ -5,6 +5,7 @@ use crates_io_env_vars::{required_var, required_var_parsed, var};
 use secrecy::{ExposeSecret, SecretString};
 use std::path::{Path, PathBuf};
 use std::process::Command;
+use std::time::Instant;
 use tempfile::TempDir;
 use url::Url;
 
@@ -282,8 +283,13 @@ impl Repository {
     pub fn reset_head(&self) -> anyhow::Result<()> {
         let original_head = self.head_oid()?;
 
+        let fetch_start = Instant::now();
         self.run_command(Command::new("git").args(["fetch", "origin", "master"]))?;
+        info!(duration = fetch_start.elapsed().as_nanos(), "Index fetched");
+
+        let reset_start = Instant::now();
         self.run_command(Command::new("git").args(["reset", "--hard", "origin/master"]))?;
+        info!(duration = reset_start.elapsed().as_nanos(), "Index reset");
 
         let head = self.head_oid()?;
         if head != original_head {

src/worker/environment.rs

@@ -47,7 +47,9 @@ pub struct Environment {
 impl Environment {
     #[instrument(skip_all)]
     pub fn lock_index(&self) -> anyhow::Result<RepositoryLock<'_>> {
+        let lock_start = Instant::now();
         let mut repo = self.repository.lock();
+        info!(duration = lock_start.elapsed().as_nanos(), "Index locked");
 
         if repo.is_none() {
             info!("Cloning index");

src/worker/jobs/index/sync.rs

@@ -11,6 +11,7 @@ use std::fs;
 use std::fs::File;
 use std::io::{ErrorKind, Write};
 use std::sync::Arc;
+use std::time::Instant;
 use tracing::{debug, info, instrument};
 
 #[derive(Serialize, Deserialize)]
@@ -56,6 +57,7 @@ impl BackgroundJob for SyncToGitIndex {
                 Err(error) => return Err(error.into()),
             };
 
+            let commit_and_push_start = Instant::now();
             match (old, new) {
                 (None, Some(new)) => {
                     fs::create_dir_all(dst.parent().unwrap())?;
@@ -74,6 +76,10 @@ impl BackgroundJob for SyncToGitIndex {
                 }
                 _ => debug!("Skipping sync because index is up-to-date"),
             }
+            info!(
+                duration = commit_and_push_start.elapsed().as_nanos(),
+                "Committed and pushed"
+            );
 
             Ok(())
         })