]>
Commit | Line | Data |
---|---|---|
9fa01778 | 1 | use std::collections::{BTreeMap, HashMap}; |
b7449926 | 2 | use std::fs; |
9fa01778 XL |
3 | use std::io::{self, Write}; |
4 | use std::thread::ThreadId; | |
0731742a | 5 | use std::time::Instant; |
b7449926 | 6 | |
9fa01778 | 7 | use crate::session::config::{Options, OptLevel}; |
b7449926 | 8 | |
9fa01778 XL |
9 | #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)] |
10 | pub enum ProfileCategory { | |
11 | Parsing, | |
12 | Expansion, | |
13 | TypeChecking, | |
14 | BorrowChecking, | |
15 | Codegen, | |
16 | Linking, | |
17 | Other, | |
18 | } | |
b7449926 | 19 | |
9fa01778 XL |
20 | #[derive(Clone, Copy, Debug, Eq, PartialEq)] |
21 | pub enum ProfilerEvent { | |
22 | QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant }, | |
23 | QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, | |
24 | GenericActivityStart { category: ProfileCategory, time: Instant }, | |
25 | GenericActivityEnd { category: ProfileCategory, time: Instant }, | |
26 | QueryCacheHit { query_name: &'static str, category: ProfileCategory }, | |
27 | QueryCount { query_name: &'static str, category: ProfileCategory, count: usize }, | |
28 | IncrementalLoadResultStart { query_name: &'static str, time: Instant }, | |
29 | IncrementalLoadResultEnd { query_name: &'static str, time: Instant }, | |
30 | QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant }, | |
31 | QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, | |
32 | } | |
33 | ||
34 | impl ProfilerEvent { | |
35 | fn is_start_event(&self) -> bool { | |
36 | use self::ProfilerEvent::*; | |
37 | ||
38 | match self { | |
39 | QueryStart { .. } | | |
40 | GenericActivityStart { .. } | | |
41 | IncrementalLoadResultStart { .. } | | |
42 | QueryBlockedStart { .. } => true, | |
43 | ||
44 | QueryEnd { .. } | | |
45 | GenericActivityEnd { .. } | | |
46 | QueryCacheHit { .. } | | |
47 | QueryCount { .. } | | |
48 | IncrementalLoadResultEnd { .. } | | |
49 | QueryBlockedEnd { .. } => false, | |
b7449926 | 50 | } |
9fa01778 XL |
51 | } |
52 | } | |
b7449926 | 53 | |
9fa01778 XL |
54 | pub struct SelfProfiler { |
55 | events: HashMap<ThreadId, Vec<ProfilerEvent>>, | |
56 | } | |
b7449926 | 57 | |
9fa01778 XL |
58 | struct CategoryResultData { |
59 | query_times: BTreeMap<&'static str, u64>, | |
60 | query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total) | |
61 | } | |
62 | ||
63 | impl CategoryResultData { | |
64 | fn new() -> CategoryResultData { | |
65 | CategoryResultData { | |
66 | query_times: BTreeMap::new(), | |
67 | query_cache_stats: BTreeMap::new(), | |
b7449926 | 68 | } |
9fa01778 | 69 | } |
b7449926 | 70 | |
9fa01778 XL |
71 | fn total_time(&self) -> u64 { |
72 | self.query_times.iter().map(|(_, time)| time).sum() | |
73 | } | |
74 | ||
75 | fn total_cache_data(&self) -> (u64, u64) { | |
76 | let (mut hits, mut total) = (0, 0); | |
77 | ||
78 | for (_, (h, t)) in &self.query_cache_stats { | |
79 | hits += h; | |
80 | total += t; | |
b7449926 XL |
81 | } |
82 | ||
9fa01778 XL |
83 | (hits, total) |
84 | } | |
85 | } | |
b7449926 | 86 | |
9fa01778 XL |
87 | impl Default for CategoryResultData { |
88 | fn default() -> CategoryResultData { | |
89 | CategoryResultData::new() | |
90 | } | |
91 | } | |
b7449926 | 92 | |
9fa01778 XL |
93 | struct CalculatedResults { |
94 | categories: BTreeMap<ProfileCategory, CategoryResultData>, | |
95 | crate_name: Option<String>, | |
96 | optimization_level: OptLevel, | |
97 | incremental: bool, | |
98 | verbose: bool, | |
99 | } | |
b7449926 | 100 | |
9fa01778 XL |
101 | impl CalculatedResults { |
102 | fn new() -> CalculatedResults { | |
103 | CalculatedResults { | |
104 | categories: BTreeMap::new(), | |
105 | crate_name: None, | |
106 | optimization_level: OptLevel::No, | |
107 | incremental: false, | |
108 | verbose: false, | |
109 | } | |
110 | } | |
b7449926 | 111 | |
9fa01778 XL |
112 | fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults { |
113 | for (category, data) in cr2.categories { | |
114 | let cr1_data = cr1.categories.entry(category).or_default(); | |
a1dfa0c6 | 115 | |
9fa01778 XL |
116 | for (query, time) in data.query_times { |
117 | *cr1_data.query_times.entry(query).or_default() += time; | |
118 | } | |
b7449926 | 119 | |
9fa01778 XL |
120 | for (query, (hits, total)) in data.query_cache_stats { |
121 | let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0)); | |
122 | *h += hits; | |
123 | *t += total; | |
b7449926 XL |
124 | } |
125 | } | |
9fa01778 XL |
126 | |
127 | cr1 | |
128 | } | |
129 | ||
130 | fn total_time(&self) -> u64 { | |
131 | self.categories.iter().map(|(_, data)| data.total_time()).sum() | |
132 | } | |
133 | ||
134 | fn with_options(mut self, opts: &Options) -> CalculatedResults { | |
135 | self.crate_name = opts.crate_name.clone(); | |
136 | self.optimization_level = opts.optimize; | |
137 | self.incremental = opts.incremental.is_some(); | |
138 | self.verbose = opts.debugging_opts.verbose; | |
139 | ||
140 | self | |
b7449926 XL |
141 | } |
142 | } | |
143 | ||
9fa01778 XL |
144 | fn time_between_ns(start: Instant, end: Instant) -> u64 { |
145 | if start < end { | |
146 | let time = end - start; | |
147 | (time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64) | |
148 | } else { | |
149 | debug!("time_between_ns: ignorning instance of end < start"); | |
150 | 0 | |
151 | } | |
b7449926 XL |
152 | } |
153 | ||
9fa01778 XL |
154 | fn calculate_percent(numerator: u64, denominator: u64) -> f32 { |
155 | if denominator > 0 { | |
156 | ((numerator as f32) / (denominator as f32)) * 100.0 | |
157 | } else { | |
158 | 0.0 | |
159 | } | |
b7449926 XL |
160 | } |
161 | ||
162 | impl SelfProfiler { | |
163 | pub fn new() -> SelfProfiler { | |
164 | let mut profiler = SelfProfiler { | |
9fa01778 | 165 | events: HashMap::new(), |
b7449926 XL |
166 | }; |
167 | ||
168 | profiler.start_activity(ProfileCategory::Other); | |
169 | ||
170 | profiler | |
171 | } | |
172 | ||
9fa01778 | 173 | #[inline] |
b7449926 | 174 | pub fn start_activity(&mut self, category: ProfileCategory) { |
9fa01778 XL |
175 | self.record(ProfilerEvent::GenericActivityStart { |
176 | category, | |
177 | time: Instant::now(), | |
178 | }) | |
179 | } | |
b7449926 | 180 | |
9fa01778 XL |
181 | #[inline] |
182 | pub fn end_activity(&mut self, category: ProfileCategory) { | |
183 | self.record(ProfilerEvent::GenericActivityEnd { | |
184 | category, | |
185 | time: Instant::now(), | |
186 | }) | |
187 | } | |
b7449926 | 188 | |
9fa01778 XL |
189 | #[inline] |
190 | pub fn record_computed_queries( | |
191 | &mut self, | |
192 | query_name: &'static str, | |
193 | category: ProfileCategory, | |
194 | count: usize) | |
195 | { | |
196 | self.record(ProfilerEvent::QueryCount { | |
197 | query_name, | |
198 | category, | |
199 | count, | |
200 | }) | |
b7449926 XL |
201 | } |
202 | ||
9fa01778 XL |
203 | #[inline] |
204 | pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) { | |
205 | self.record(ProfilerEvent::QueryCacheHit { | |
206 | query_name, | |
207 | category, | |
208 | }) | |
b7449926 XL |
209 | } |
210 | ||
9fa01778 XL |
211 | #[inline] |
212 | pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) { | |
213 | self.record(ProfilerEvent::QueryStart { | |
214 | query_name, | |
215 | category, | |
216 | time: Instant::now(), | |
217 | }); | |
b7449926 XL |
218 | } |
219 | ||
9fa01778 XL |
220 | #[inline] |
221 | pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) { | |
222 | self.record(ProfilerEvent::QueryEnd { | |
223 | query_name, | |
224 | category, | |
225 | time: Instant::now(), | |
226 | }) | |
227 | } | |
228 | ||
229 | #[inline] | |
230 | pub fn incremental_load_result_start(&mut self, query_name: &'static str) { | |
231 | self.record(ProfilerEvent::IncrementalLoadResultStart { | |
232 | query_name, | |
233 | time: Instant::now(), | |
234 | }) | |
235 | } | |
236 | ||
237 | #[inline] | |
238 | pub fn incremental_load_result_end(&mut self, query_name: &'static str) { | |
239 | self.record(ProfilerEvent::IncrementalLoadResultEnd { | |
240 | query_name, | |
241 | time: Instant::now(), | |
242 | }) | |
243 | } | |
244 | ||
245 | #[inline] | |
246 | pub fn query_blocked_start(&mut self, query_name: &'static str, category: ProfileCategory) { | |
247 | self.record(ProfilerEvent::QueryBlockedStart { | |
248 | query_name, | |
249 | category, | |
250 | time: Instant::now(), | |
251 | }) | |
252 | } | |
253 | ||
254 | #[inline] | |
255 | pub fn query_blocked_end(&mut self, query_name: &'static str, category: ProfileCategory) { | |
256 | self.record(ProfilerEvent::QueryBlockedEnd { | |
257 | query_name, | |
258 | category, | |
259 | time: Instant::now(), | |
260 | }) | |
261 | } | |
262 | ||
263 | #[inline] | |
264 | fn record(&mut self, event: ProfilerEvent) { | |
265 | let thread_id = std::thread::current().id(); | |
266 | let events = self.events.entry(thread_id).or_default(); | |
267 | ||
268 | events.push(event); | |
269 | } | |
270 | ||
271 | fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults { | |
272 | use self::ProfilerEvent::*; | |
273 | ||
274 | assert!( | |
275 | events.last().map(|e| !e.is_start_event()).unwrap_or(true), | |
276 | "there was an event running when calculate_reslts() was called" | |
277 | ); | |
278 | ||
279 | let mut results = CalculatedResults::new(); | |
280 | ||
281 | //(event, child time to subtract) | |
282 | let mut query_stack = Vec::new(); | |
283 | ||
284 | for event in events { | |
285 | match event { | |
286 | QueryStart { .. } | GenericActivityStart { .. } => { | |
287 | query_stack.push((event, 0)); | |
288 | }, | |
289 | QueryEnd { query_name, category, time: end_time } => { | |
290 | let previous_query = query_stack.pop(); | |
291 | if let Some((QueryStart { | |
292 | query_name: p_query_name, | |
293 | time: start_time, | |
294 | category: _ }, child_time_to_subtract)) = previous_query { | |
295 | assert_eq!( | |
296 | p_query_name, | |
297 | query_name, | |
298 | "Saw a query end but the previous query wasn't the corresponding start" | |
299 | ); | |
300 | ||
301 | let time_ns = time_between_ns(*start_time, *end_time); | |
302 | let self_time_ns = time_ns - child_time_to_subtract; | |
303 | let result_data = results.categories.entry(*category).or_default(); | |
304 | ||
305 | *result_data.query_times.entry(query_name).or_default() += self_time_ns; | |
306 | ||
307 | if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { | |
308 | *child_time_to_subtract += time_ns; | |
309 | } | |
310 | } else { | |
311 | bug!("Saw a query end but the previous event wasn't a query start"); | |
312 | } | |
313 | } | |
314 | GenericActivityEnd { category, time: end_time } => { | |
315 | let previous_event = query_stack.pop(); | |
316 | if let Some((GenericActivityStart { | |
317 | category: previous_category, | |
318 | time: start_time }, child_time_to_subtract)) = previous_event { | |
319 | assert_eq!( | |
320 | previous_category, | |
321 | category, | |
322 | "Saw an end but the previous event wasn't the corresponding start" | |
323 | ); | |
324 | ||
325 | let time_ns = time_between_ns(*start_time, *end_time); | |
326 | let self_time_ns = time_ns - child_time_to_subtract; | |
327 | let result_data = results.categories.entry(*category).or_default(); | |
328 | ||
329 | *result_data.query_times | |
330 | .entry("{time spent not running queries}") | |
331 | .or_default() += self_time_ns; | |
332 | ||
333 | if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { | |
334 | *child_time_to_subtract += time_ns; | |
335 | } | |
336 | } else { | |
337 | bug!("Saw an activity end but the previous event wasn't an activity start"); | |
338 | } | |
339 | }, | |
340 | QueryCacheHit { category, query_name } => { | |
341 | let result_data = results.categories.entry(*category).or_default(); | |
342 | ||
343 | let (hits, total) = | |
344 | result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); | |
345 | *hits += 1; | |
346 | *total += 1; | |
347 | }, | |
348 | QueryCount { category, query_name, count } => { | |
349 | let result_data = results.categories.entry(*category).or_default(); | |
350 | ||
351 | let (_, totals) = | |
352 | result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); | |
353 | *totals += *count as u64; | |
354 | }, | |
355 | //we don't summarize incremental load result events in the simple output mode | |
356 | IncrementalLoadResultStart { .. } | IncrementalLoadResultEnd { .. } => { }, | |
357 | //we don't summarize parallel query blocking in the simple output mode | |
358 | QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { }, | |
359 | } | |
b7449926 XL |
360 | } |
361 | ||
9fa01778 XL |
362 | //normalize the times to ms |
363 | for (_, data) in &mut results.categories { | |
364 | for (_, time) in &mut data.query_times { | |
365 | *time = *time / 1_000_000; | |
b7449926 XL |
366 | } |
367 | } | |
368 | ||
9fa01778 | 369 | results |
b7449926 XL |
370 | } |
371 | ||
9fa01778 XL |
372 | fn get_results(&self, opts: &Options) -> CalculatedResults { |
373 | self.events | |
374 | .iter() | |
375 | .map(|(_, r)| SelfProfiler::calculate_thread_results(r)) | |
376 | .fold(CalculatedResults::new(), CalculatedResults::consolidate) | |
377 | .with_options(opts) | |
b7449926 XL |
378 | } |
379 | ||
380 | pub fn print_results(&mut self, opts: &Options) { | |
381 | self.end_activity(ProfileCategory::Other); | |
382 | ||
9fa01778 XL |
383 | let results = self.get_results(opts); |
384 | ||
385 | let total_time = results.total_time() as f32; | |
b7449926 | 386 | |
0731742a | 387 | let out = io::stderr(); |
b7449926 XL |
388 | let mut lock = out.lock(); |
389 | ||
9fa01778 | 390 | let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default(); |
b7449926 XL |
391 | |
392 | writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); | |
393 | writeln!(lock).unwrap(); | |
394 | ||
9fa01778 XL |
395 | writeln!(lock, "| Phase | Time (ms) \ |
396 | | Time (%) | Queries | Hits (%)") | |
397 | .unwrap(); | |
398 | writeln!(lock, "| ----------------------------------------- | -------------- \ | |
399 | | -------- | -------------- | --------") | |
400 | .unwrap(); | |
401 | ||
402 | let mut categories: Vec<_> = results.categories.iter().collect(); | |
403 | categories.sort_by_cached_key(|(_, d)| d.total_time()); | |
404 | ||
405 | for (category, data) in categories.iter().rev() { | |
406 | let (category_hits, category_total) = data.total_cache_data(); | |
407 | let category_hit_percent = calculate_percent(category_hits, category_total); | |
408 | ||
409 | writeln!( | |
410 | lock, | |
411 | "| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", | |
412 | format!("{:?}", category), | |
413 | data.total_time(), | |
414 | ((data.total_time() as f32) / total_time) * 100.0, | |
415 | category_total, | |
416 | format!("{:.2}", category_hit_percent), | |
417 | ).unwrap(); | |
418 | ||
419 | //in verbose mode, show individual query data | |
420 | if results.verbose { | |
421 | //don't show queries that took less than 1ms | |
422 | let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect(); | |
423 | times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1)); | |
424 | ||
425 | for (query, time) in times { | |
426 | let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0)); | |
427 | let hit_percent = calculate_percent(*hits, *total); | |
428 | ||
429 | writeln!( | |
430 | lock, | |
431 | "| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", | |
432 | query, | |
433 | time, | |
434 | ((*time as f32) / total_time) * 100.0, | |
435 | total, | |
436 | format!("{:.2}", hit_percent), | |
437 | ).unwrap(); | |
438 | } | |
439 | } | |
440 | } | |
b7449926 XL |
441 | |
442 | writeln!(lock).unwrap(); | |
443 | writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap(); | |
9fa01778 | 444 | writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap(); |
b7449926 XL |
445 | } |
446 | ||
447 | pub fn save_results(&self, opts: &Options) { | |
9fa01778 XL |
448 | let results = self.get_results(opts); |
449 | ||
b7449926 XL |
450 | let compilation_options = |
451 | format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}", | |
9fa01778 XL |
452 | results.optimization_level, |
453 | if results.incremental { "true" } else { "false" }); | |
454 | ||
455 | let mut category_data = String::new(); | |
456 | ||
457 | for (category, data) in &results.categories { | |
458 | let (hits, total) = data.total_cache_data(); | |
459 | let hit_percent = calculate_percent(hits, total); | |
460 | ||
461 | category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \ | |
462 | \"query_count\": {}, \"query_hits\": {} }}", | |
463 | category, | |
464 | data.total_time(), | |
465 | total, | |
466 | format!("{:.2}", hit_percent))); | |
467 | } | |
b7449926 XL |
468 | |
469 | let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}", | |
470 | category_data, | |
471 | compilation_options); | |
472 | ||
473 | fs::write("self_profiler_results.json", json).unwrap(); | |
474 | } | |
475 | } |