improve CommandProfiler API and add summary_report

Author: Shourya742

src/bootstrap/src/utils/exec.rs

@@ -75,7 +75,7 @@ pub struct CommandCacheKey {
 
 #[derive(Default, Clone)]
 pub struct CommandProfile {
-    pub exec_traces: Vec<ExecutionTrace>,
+    pub traces: Vec<ExecutionTrace>,
 }
 
 #[derive(Default)]
@@ -84,10 +84,57 @@ pub struct CommandProfiler {
 }
 
 impl CommandProfiler {
-    pub fn record(&self, key: CommandCacheKey, exec_trace: ExecutionTrace) {
+    pub fn record_execution(&self, key: CommandCacheKey, start_time: Instant) {
         let mut stats = self.stats.lock().unwrap();
         let entry = stats.entry(key).or_default();
-        entry.exec_traces.push(exec_trace);
+        entry.traces.push(ExecutionTrace::Executed {
+            timestamp: start_time,
+            duration: start_time.elapsed(),
+        });
+    }
+
+    pub fn record_cache_hit(&self, key: CommandCacheKey) {
+        let mut stats = self.stats.lock().unwrap();
+        let entry = stats.entry(key).or_default();
+        entry.traces.push(ExecutionTrace::CacheHit { timestamp: Instant::now() });
+    }
+
+    pub fn report_summary(&self) {
+        let stats = self.stats.lock().unwrap();
+
+        for (key, profile) in stats.iter() {
+            println!("\nCommand: {:?}", key.program);
+
+            let mut hits = 0;
+            let mut runs = 0;
+            let mut max_duration: Option<Duration> = None;
+
+            for trace in &profile.traces {
+                match trace {
+                    ExecutionTrace::CacheHit { timestamp } => {
+                        hits += 1;
+                        println!("  - Cache hit at:   {:?}", timestamp);
+                    }
+                    ExecutionTrace::Executed { duration, timestamp } => {
+                        runs += 1;
+                        if max_duration.map_or(true, |d| *duration > d) {
+                            max_duration = Some(*duration);
+                        }
+                        println!("  - Executed at:    {:?}, duration: {:.2?}", timestamp, duration);
+                    }
+                }
+            }
+
+            let duration_str = match max_duration {
+                Some(d) => format!("{:.2?}", d),
+                None => "-".into(),
+            };
+
+            println!(
+                "  => Summary: {} run(s), {} hit(s), max_duration={}",
+                runs, hits, duration_str
+            );
+        }
     }
 }
 
@@ -572,7 +619,7 @@ impl ExecutionContext {
         if let Some(cached_output) = self.command_cache.get(&cache_key) {
             command.mark_as_executed();
             self.verbose(|| println!("Cache hit: {command:?}"));
-            self.profiler.record(cache_key, ExecutionTrace::CacheHit { timestamp: Instant::now() });
+            self.profiler.record_cache_hit(cache_key);
             return DeferredCommand { state: CommandState::Cached(cached_output) };
         }
 
@@ -720,13 +767,7 @@ impl<'a> DeferredCommand<'a> {
                     && command.should_cache
                 {
                     exec_ctx.command_cache.insert(cache_key.clone(), output.clone());
-                    exec_ctx.profiler.record(
-                        cache_key.clone(),
-                        ExecutionTrace::Executed {
-                            timestamp: start_time,
-                            duration: start_time.elapsed(),
-                        },
-                    );
+                    exec_ctx.profiler.record_execution(cache_key.clone(), start_time);
                 }
 
                 output