improve summary report, remove timestamp

Author: Shourya742

src/bootstrap/src/bin/main.rs

@@ -8,6 +8,7 @@
 use std::fs::{self, OpenOptions};
 use std::io::{self, BufRead, BufReader, IsTerminal, Write};
 use std::str::FromStr;
+use std::time::Instant;
 use std::{env, process};
 
 use bootstrap::{
@@ -22,6 +23,8 @@ fn main() {
     #[cfg(feature = "tracing")]
     let _guard = setup_tracing();
 
+    let start_time = Instant::now();
+
     let args = env::args().skip(1).collect::<Vec<_>>();
 
     if Flags::try_parse_verbose_help(&args) {
@@ -150,7 +153,7 @@ fn main() {
     }
 
     if env::var("BOOTSTRAP_PROFILE").is_ok_and(|v| v == "1") {
-        build.report_summary();
+        build.report_summary(start_time);
     }
 }
 

src/bootstrap/src/lib.rs

@@ -22,7 +22,7 @@ use std::collections::{BTreeSet, HashMap, HashSet};
 use std::fmt::Display;
 use std::path::{Path, PathBuf};
 use std::sync::OnceLock;
-use std::time::SystemTime;
+use std::time::{Instant, SystemTime};
 use std::{env, fs, io, str};
 
 use build_helper::ci::gha;
@@ -1929,8 +1929,8 @@ to download LLVM rather than building it.
         &self.config.exec_ctx
     }
 
-    pub fn report_summary(&self) {
-        self.config.exec_ctx.profiler().report_summary();
+    pub fn report_summary(&self, start_time: Instant) {
+        self.config.exec_ctx.profiler().report_summary(start_time);
     }
 }
 

src/bootstrap/src/utils/exec.rs

@@ -20,7 +20,7 @@ use std::process::{
     Child, ChildStderr, ChildStdout, Command, CommandArgs, CommandEnvs, ExitStatus, Output, Stdio,
 };
 use std::sync::{Arc, Mutex};
-use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
+use std::time::{Duration, Instant};
 
 use build_helper::ci::CiEnv;
 use build_helper::drop_bomb::DropBomb;
@@ -100,19 +100,16 @@ impl CommandProfiler {
     pub fn record_execution(&self, key: CommandFingerprint, start_time: Instant) {
         let mut stats = self.stats.lock().unwrap();
         let entry = stats.entry(key).or_default();
-        entry.traces.push(ExecutionTrace::Executed {
-            timestamp: SystemTime::now(),
-            duration: start_time.elapsed(),
-        });
+        entry.traces.push(ExecutionTrace::Executed { duration: start_time.elapsed() });
     }
 
     pub fn record_cache_hit(&self, key: CommandFingerprint) {
         let mut stats = self.stats.lock().unwrap();
         let entry = stats.entry(key).or_default();
-        entry.traces.push(ExecutionTrace::CacheHit { timestamp: SystemTime::now() });
+        entry.traces.push(ExecutionTrace::CacheHit);
     }
 
-    pub fn report_summary(&self) {
+    pub fn report_summary(&self, start_time: Instant) {
         let pid = process::id();
         let filename = format!("bootstrap-profile-{pid}.txt");
 
@@ -145,28 +142,35 @@ impl CommandProfiler {
 
         entries.sort_by(|a, b| b.2.cmp(&a.2));
 
-        for (key, profile, max_duration) in entries {
+        let mut total_fingerprints = 0;
+        let mut total_cache_hits = 0;
+        let mut total_execution_duration = Duration::ZERO;
+        let mut total_saved_duration = Duration::ZERO;
+
+        for (key, profile, max_duration) in &entries {
             writeln!(writer, "Command: {:?}", key.format_short_cmd()).unwrap();
 
             let mut hits = 0;
             let mut runs = 0;
+            let mut command_total_duration = Duration::ZERO;
 
             for trace in &profile.traces {
                 match trace {
-                    ExecutionTrace::CacheHit { timestamp } => {
+                    ExecutionTrace::CacheHit => {
                         hits += 1;
-                        let time = timestamp.duration_since(UNIX_EPOCH).unwrap();
-                        writeln!(writer, "  - Cache hit at:   {time:?}").unwrap();
                     }
-                    ExecutionTrace::Executed { duration, timestamp } => {
+                    ExecutionTrace::Executed { duration, .. } => {
                         runs += 1;
-                        let time = timestamp.duration_since(UNIX_EPOCH).unwrap();
-                        writeln!(writer, "  - Executed at:    {time:?}, duration: {duration:.2?}")
-                            .unwrap();
+                        command_total_duration += *duration;
                     }
                 }
             }
 
+            total_fingerprints += 1;
+            total_cache_hits += hits;
+            total_execution_duration += command_total_duration;
+            total_saved_duration += command_total_duration * hits as u32;
+
             let duration_str = match max_duration {
                 Some(d) => format!("{d:.2?}"),
                 None => "-".into(),
@@ -179,14 +183,29 @@ impl CommandProfiler {
             .unwrap();
         }
 
+        // Add aggregated summary
+        let total_bootstrap_time = start_time.elapsed();
+        let overhead_time =
+            total_bootstrap_time.checked_sub(total_execution_duration).unwrap_or(Duration::ZERO);
+
+        writeln!(writer, "\n=== Aggregated Summary ===").unwrap();
+        writeln!(writer, "Total unique commands (fingerprints): {total_fingerprints}").unwrap();
+        writeln!(writer, "Total time spent in command executions: {total_execution_duration:.2?}")
+            .unwrap();
+        writeln!(writer, "Total bootstrap time: {total_bootstrap_time:.2?}").unwrap();
+        writeln!(writer, "Time spent outside command executions: {overhead_time:.2?}").unwrap();
+        writeln!(writer, "Total cache hits: {total_cache_hits}").unwrap();
+        writeln!(writer, "Estimated time saved due to cache hits: {total_saved_duration:.2?}")
+            .unwrap();
+
         println!("Command profiler report saved to {filename}");
     }
 }
 
 #[derive(Clone)]
 pub enum ExecutionTrace {
-    CacheHit { timestamp: SystemTime },
-    Executed { timestamp: SystemTime, duration: Duration },
+    CacheHit,
+    Executed { duration: Duration },
 }
 
 /// Wrapper around `std::process::Command`.