Skip to content

Commit c101a26

Browse files
committed
This commit adds:
1. Adds total command execution duration to total duration percentage. 2. Adds explanation about hits*command_execution_time 3. Rename cache_key to fingerprint 4. Rename `check_bootstrap_profile_flag` to `is_bootstrap_profiling_enabled`
1 parent 1382ecc commit c101a26

File tree

2 files changed

+37
-24
lines changed

2 files changed

+37
-24
lines changed

src/bootstrap/src/bin/main.rs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@ use bootstrap::{
1818
#[cfg(feature = "tracing")]
1919
use tracing::instrument;
2020

21-
fn check_bootstrap_profile_flag() -> bool {
21+
fn is_bootstrap_profiling_enabled() -> bool {
2222
env::var("BOOTSTRAP_PROFILE").is_ok_and(|v| v == "1")
2323
}
2424

@@ -156,7 +156,7 @@ fn main() {
156156
}
157157
}
158158

159-
if check_bootstrap_profile_flag() {
159+
if is_bootstrap_profiling_enabled() {
160160
build.report_summary(start_time);
161161
}
162162
}
@@ -238,7 +238,7 @@ fn setup_tracing() -> impl Drop {
238238
let mut chrome_layer = tracing_chrome::ChromeLayerBuilder::new().include_args(true);
239239

240240
// Writes the Chrome profile to trace-<unix-timestamp>.json if enabled
241-
if !check_bootstrap_profile_flag() {
241+
if !is_bootstrap_profiling_enabled() {
242242
chrome_layer = chrome_layer.writer(io::sink());
243243
}
244244

src/bootstrap/src/utils/exec.rs

Lines changed: 34 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -142,7 +142,9 @@ impl CommandProfiler {
142142

143143
entries.sort_by(|a, b| b.2.cmp(&a.2));
144144

145-
let mut total_fingerprints = 0;
145+
let total_bootstrap_duration = start_time.elapsed();
146+
147+
let total_fingerprints = entries.len();
146148
let mut total_cache_hits = 0;
147149
let mut total_execution_duration = Duration::ZERO;
148150
let mut total_saved_duration = Duration::ZERO;
@@ -166,32 +168,43 @@ impl CommandProfiler {
166168
}
167169
}
168170

169-
total_fingerprints += 1;
170171
total_cache_hits += hits;
171172
total_execution_duration += command_total_duration;
173+
// This makes sense only in our current setup, where:
174+
// - If caching is enabled, we record the timing for the initial execution,
175+
// and all subsequent runs will be cache hits.
176+
// - If caching is disabled or unused, there will be no cache hits,
177+
// and we'll record timings for all executions.
172178
total_saved_duration += command_total_duration * hits as u32;
173179

180+
let command_vs_bootstrap = if total_bootstrap_duration.as_secs_f64() > 0.0 {
181+
100.0 * command_total_duration.as_secs_f64()
182+
/ total_bootstrap_duration.as_secs_f64()
183+
} else {
184+
0.0
185+
};
186+
174187
let duration_str = match max_duration {
175188
Some(d) => format!("{d:.2?}"),
176189
None => "-".into(),
177190
};
178191

179192
writeln!(
180193
writer,
181-
"Summary: {runs} run(s), {hits} hit(s), max_duration={duration_str}\n"
194+
"Summary: {runs} run(s), {hits} hit(s), max_duration={duration_str} total_duration: {command_total_duration:.2?} ({command_vs_bootstrap:.2?}% of total)\n"
182195
)
183196
.unwrap();
184197
}
185198

186-
let total_bootstrap_time = start_time.elapsed();
187-
let overhead_time =
188-
total_bootstrap_time.checked_sub(total_execution_duration).unwrap_or(Duration::ZERO);
199+
let overhead_time = total_bootstrap_duration
200+
.checked_sub(total_execution_duration)
201+
.unwrap_or(Duration::ZERO);
189202

190203
writeln!(writer, "\n=== Aggregated Summary ===").unwrap();
191204
writeln!(writer, "Total unique commands (fingerprints): {total_fingerprints}").unwrap();
192205
writeln!(writer, "Total time spent in command executions: {total_execution_duration:.2?}")
193206
.unwrap();
194-
writeln!(writer, "Total bootstrap time: {total_bootstrap_time:.2?}").unwrap();
207+
writeln!(writer, "Total bootstrap time: {total_bootstrap_duration:.2?}").unwrap();
195208
writeln!(writer, "Time spent outside command executions: {overhead_time:.2?}").unwrap();
196209
writeln!(writer, "Total cache hits: {total_cache_hits}").unwrap();
197210
writeln!(writer, "Estimated time saved due to cache hits: {total_saved_duration:.2?}")
@@ -379,7 +392,7 @@ impl<'a> BootstrapCommand {
379392
}
380393
}
381394

382-
pub fn cache_key(&self) -> CommandFingerprint {
395+
pub fn fingerprint(&self) -> CommandFingerprint {
383396
let command = &self.command;
384397
CommandFingerprint {
385398
program: command.get_program().into(),
@@ -578,7 +591,7 @@ enum CommandState<'a> {
578591
stdout: OutputMode,
579592
stderr: OutputMode,
580593
executed_at: &'a Location<'a>,
581-
cache_key: CommandFingerprint,
594+
fingerprint: CommandFingerprint,
582595
start_time: Instant,
583596
},
584597
}
@@ -587,7 +600,7 @@ pub struct StreamingCommand {
587600
child: Child,
588601
pub stdout: Option<ChildStdout>,
589602
pub stderr: Option<ChildStderr>,
590-
cache_key: CommandFingerprint,
603+
fingerprint: CommandFingerprint,
591604
start_time: Instant,
592605
}
593606

@@ -678,12 +691,12 @@ impl ExecutionContext {
678691
stdout: OutputMode,
679692
stderr: OutputMode,
680693
) -> DeferredCommand<'a> {
681-
let cache_key = command.cache_key();
694+
let fingerprint = command.fingerprint();
682695

683-
if let Some(cached_output) = self.command_cache.get(&cache_key) {
696+
if let Some(cached_output) = self.command_cache.get(&fingerprint) {
684697
command.mark_as_executed();
685698
self.verbose(|| println!("Cache hit: {command:?}"));
686-
self.profiler.record_cache_hit(cache_key);
699+
self.profiler.record_cache_hit(fingerprint);
687700
return DeferredCommand { state: CommandState::Cached(cached_output) };
688701
}
689702

@@ -698,7 +711,7 @@ impl ExecutionContext {
698711
stdout,
699712
stderr,
700713
executed_at,
701-
cache_key,
714+
fingerprint,
702715
start_time: Instant::now(),
703716
},
704717
};
@@ -726,7 +739,7 @@ impl ExecutionContext {
726739
stdout,
727740
stderr,
728741
executed_at,
729-
cache_key,
742+
fingerprint,
730743
start_time,
731744
},
732745
}
@@ -782,7 +795,7 @@ impl ExecutionContext {
782795
return None;
783796
}
784797
let start_time = Instant::now();
785-
let cache_key = command.cache_key();
798+
let fingerprint = command.fingerprint();
786799
let cmd = &mut command.command;
787800
cmd.stdout(stdout.stdio());
788801
cmd.stderr(stderr.stdio());
@@ -794,7 +807,7 @@ impl ExecutionContext {
794807

795808
let stdout = child.stdout.take();
796809
let stderr = child.stderr.take();
797-
Some(StreamingCommand { child, stdout, stderr, cache_key, start_time })
810+
Some(StreamingCommand { child, stdout, stderr, fingerprint, start_time })
798811
}
799812
}
800813

@@ -811,7 +824,7 @@ impl StreamingCommand {
811824
) -> Result<ExitStatus, std::io::Error> {
812825
let exec_ctx = exec_ctx.as_ref();
813826
let output = self.child.wait();
814-
exec_ctx.profiler().record_execution(self.cache_key, self.start_time);
827+
exec_ctx.profiler().record_execution(self.fingerprint, self.start_time);
815828
output
816829
}
817830
}
@@ -826,7 +839,7 @@ impl<'a> DeferredCommand<'a> {
826839
stdout,
827840
stderr,
828841
executed_at,
829-
cache_key,
842+
fingerprint,
830843
start_time,
831844
} => {
832845
let exec_ctx = exec_ctx.as_ref();
@@ -838,8 +851,8 @@ impl<'a> DeferredCommand<'a> {
838851
&& output.status().is_some()
839852
&& command.should_cache
840853
{
841-
exec_ctx.command_cache.insert(cache_key.clone(), output.clone());
842-
exec_ctx.profiler.record_execution(cache_key.clone(), start_time);
854+
exec_ctx.command_cache.insert(fingerprint.clone(), output.clone());
855+
exec_ctx.profiler.record_execution(fingerprint.clone(), start_time);
843856
}
844857

845858
output

0 commit comments

Comments
 (0)