Skip to content

Commit a8046bb

Browse files
committed
improve CommandProfiler API and add summary_report
1 parent 2178c0e commit a8046bb

File tree

1 file changed

+52
-11
lines changed

1 file changed

+52
-11
lines changed

src/bootstrap/src/utils/exec.rs

Lines changed: 52 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,7 @@ pub struct CommandCacheKey {
7575

7676
#[derive(Default, Clone)]
7777
pub struct CommandProfile {
78-
pub exec_traces: Vec<ExecutionTrace>,
78+
pub traces: Vec<ExecutionTrace>,
7979
}
8080

8181
#[derive(Default)]
@@ -84,10 +84,57 @@ pub struct CommandProfiler {
8484
}
8585

8686
impl CommandProfiler {
87-
pub fn record(&self, key: CommandCacheKey, exec_trace: ExecutionTrace) {
87+
pub fn record_execution(&self, key: CommandCacheKey, start_time: Instant) {
8888
let mut stats = self.stats.lock().unwrap();
8989
let entry = stats.entry(key).or_default();
90-
entry.exec_traces.push(exec_trace);
90+
entry.traces.push(ExecutionTrace::Executed {
91+
timestamp: start_time,
92+
duration: start_time.elapsed(),
93+
});
94+
}
95+
96+
pub fn record_cache_hit(&self, key: CommandCacheKey) {
97+
let mut stats = self.stats.lock().unwrap();
98+
let entry = stats.entry(key).or_default();
99+
entry.traces.push(ExecutionTrace::CacheHit { timestamp: Instant::now() });
100+
}
101+
102+
pub fn report_summary(&self) {
103+
let stats = self.stats.lock().unwrap();
104+
105+
for (key, profile) in stats.iter() {
106+
println!("\nCommand: {:?}", key.program);
107+
108+
let mut hits = 0;
109+
let mut runs = 0;
110+
let mut max_duration: Option<Duration> = None;
111+
112+
for trace in &profile.traces {
113+
match trace {
114+
ExecutionTrace::CacheHit { timestamp } => {
115+
hits += 1;
116+
println!(" - Cache hit at: {:?}", timestamp);
117+
}
118+
ExecutionTrace::Executed { duration, timestamp } => {
119+
runs += 1;
120+
if max_duration.map_or(true, |d| *duration > d) {
121+
max_duration = Some(*duration);
122+
}
123+
println!(" - Executed at: {:?}, duration: {:.2?}", timestamp, duration);
124+
}
125+
}
126+
}
127+
128+
let duration_str = match max_duration {
129+
Some(d) => format!("{:.2?}", d),
130+
None => "-".into(),
131+
};
132+
133+
println!(
134+
" => Summary: {} run(s), {} hit(s), max_duration={}",
135+
runs, hits, duration_str
136+
);
137+
}
91138
}
92139
}
93140

@@ -572,7 +619,7 @@ impl ExecutionContext {
572619
if let Some(cached_output) = self.command_cache.get(&cache_key) {
573620
command.mark_as_executed();
574621
self.verbose(|| println!("Cache hit: {command:?}"));
575-
self.profiler.record(cache_key, ExecutionTrace::CacheHit { timestamp: Instant::now() });
622+
self.profiler.record_cache_hit(cache_key);
576623
return DeferredCommand { state: CommandState::Cached(cached_output) };
577624
}
578625

@@ -720,13 +767,7 @@ impl<'a> DeferredCommand<'a> {
720767
&& command.should_cache
721768
{
722769
exec_ctx.command_cache.insert(cache_key.clone(), output.clone());
723-
exec_ctx.profiler.record(
724-
cache_key.clone(),
725-
ExecutionTrace::Executed {
726-
timestamp: start_time,
727-
duration: start_time.elapsed(),
728-
},
729-
);
770+
exec_ctx.profiler.record_execution(cache_key.clone(), start_time);
730771
}
731772

732773
output

0 commit comments

Comments
 (0)