integration profiler to command execution

Author: Shourya742

src/bootstrap/src/utils/exec.rs

@@ -16,8 +16,8 @@ use std::path::Path;
 use std::process::{
     Child, ChildStderr, ChildStdout, Command, CommandArgs, CommandEnvs, ExitStatus, Output, Stdio,
 };
-use std::time::{Duration, Instant};
 use std::sync::{Arc, Mutex};
+use std::time::{Duration, Instant};
 
 use build_helper::ci::CiEnv;
 use build_helper::drop_bomb::DropBomb;
@@ -84,7 +84,6 @@ pub struct CommandProfiler {
     stats: Mutex<HashMap<CommandCacheKey, CommandProfile>>,
 }
 
-
 impl CommandProfiler {
     pub fn record(&self, key: CommandCacheKey, duration: Duration) {
         let mut stats = self.stats.lock().unwrap();
@@ -102,9 +101,7 @@ impl CommandProfiler {
         for (key, profile) in entries.into_iter().take(top_n) {
             println!(
                 "- {:?} (count: {}, max_duration: {:.2?})",
-                key.program,
-                profile.count,
-                profile.max_duration,
+                key.program, profile.count, profile.max_duration,
             );
         }
     }
@@ -507,6 +504,7 @@ enum CommandState<'a> {
         stderr: OutputMode,
         executed_at: &'a Location<'a>,
         cache_key: Option<CommandCacheKey>,
+        start_time: Instant,
     },
 }
 
@@ -543,6 +541,10 @@ impl ExecutionContext {
         }
     }
 
+    pub fn profiler(&self) -> &CommandProfiler {
+        &self.profiler
+    }
+
     pub fn get_dry_run(&self) -> &DryRun {
         &self.dry_run
     }
@@ -605,6 +607,7 @@ impl ExecutionContext {
         {
             command.mark_as_executed();
             self.verbose(|| println!("Cache hit: {command:?}"));
+            self.profiler.record(cache_key.unwrap(), Duration::from_secs(0));
             return DeferredCommand { state: CommandState::Cached(cached_output) };
         }
 
@@ -620,6 +623,7 @@ impl ExecutionContext {
                     stderr,
                     executed_at,
                     cache_key,
+                    start_time: Instant::now(),
                 },
             };
         }
@@ -635,6 +639,8 @@ impl ExecutionContext {
         cmd.stdout(stdout.stdio());
         cmd.stderr(stderr.stdio());
 
+        let start_time = Instant::now();
+
         let child = cmd.spawn();
 
         DeferredCommand {
@@ -645,6 +651,7 @@ impl ExecutionContext {
                 stderr,
                 executed_at,
                 cache_key,
+                start_time,
             },
         }
     }
@@ -729,7 +736,15 @@ impl<'a> DeferredCommand<'a> {
     pub fn wait_for_output(self, exec_ctx: impl AsRef<ExecutionContext>) -> CommandOutput {
         match self.state {
             CommandState::Cached(output) => output,
-            CommandState::Deferred { process, command, stdout, stderr, executed_at, cache_key } => {
+            CommandState::Deferred {
+                process,
+                command,
+                stdout,
+                stderr,
+                executed_at,
+                cache_key,
+                start_time,
+            } => {
                 let exec_ctx = exec_ctx.as_ref();
 
                 let output =
@@ -739,6 +754,8 @@ impl<'a> DeferredCommand<'a> {
                     && let (Some(cache_key), Some(_)) = (&cache_key, output.status())
                 {
                     exec_ctx.command_cache.insert(cache_key.clone(), output.clone());
+                    let duration = start_time.elapsed();
+                    exec_ctx.profiler.record(cache_key.clone(), duration);
                 }
 
                 output