use crate::session::config::Options; use std::fs; use std::io::{self, StderrLock, Write}; use std::time::Instant; macro_rules! define_categories { ($($name:ident,)*) => { #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub enum ProfileCategory { $($name),* } #[allow(nonstandard_style)] struct Categories { $($name: T),* } impl Categories { fn new() -> Categories { Categories { $($name: T::default()),* } } } impl Categories { fn get(&self, category: ProfileCategory) -> &T { match category { $(ProfileCategory::$name => &self.$name),* } } fn set(&mut self, category: ProfileCategory, value: T) { match category { $(ProfileCategory::$name => self.$name = value),* } } } struct CategoryData { times: Categories, query_counts: Categories<(u64, u64)>, } impl CategoryData { fn new() -> CategoryData { CategoryData { times: Categories::new(), query_counts: Categories::new(), } } fn print(&self, lock: &mut StderrLock<'_>) { writeln!(lock, "| Phase | Time (ms) \ | Time (%) | Queries | Hits (%)") .unwrap(); writeln!(lock, "| ---------------- | -------------- \ | -------- | -------------- | --------") .unwrap(); let total_time = ($(self.times.$name + )* 0) as f32; $( let (hits, computed) = self.query_counts.$name; let total = hits + computed; let (hits, total) = if total > 0 { (format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) } else { (String::new(), String::new()) }; writeln!( lock, "| {0: <16} | {1: <14} | {2: <8.2} | {3: <14} | {4: <8}", stringify!($name), self.times.$name / 1_000_000, ((self.times.$name as f32) / total_time) * 100.0, total, hits, ).unwrap(); )* } fn json(&self) -> String { let mut json = String::from("["); $( let (hits, computed) = self.query_counts.$name; let total = hits + computed; //normalize hits to 0% let hit_percent = if total > 0 { ((hits as f32) / (total as f32)) * 100.0 } else { 0.0 }; json.push_str(&format!( "{{ \"category\": \"{}\", \"time_ms\": {},\ \"query_count\": {}, \"query_hits\": {} }},", stringify!($name), self.times.$name / 1_000_000, total, format!("{:.2}", hit_percent) )); )* //remove the trailing ',' character json.pop(); json.push(']'); json } } } } define_categories! { Parsing, Expansion, TypeChecking, BorrowChecking, Codegen, Linking, Other, } pub struct SelfProfiler { timer_stack: Vec, data: CategoryData, current_timer: Instant, } impl SelfProfiler { pub fn new() -> SelfProfiler { let mut profiler = SelfProfiler { timer_stack: Vec::new(), data: CategoryData::new(), current_timer: Instant::now(), }; profiler.start_activity(ProfileCategory::Other); profiler } pub fn start_activity(&mut self, category: ProfileCategory) { match self.timer_stack.last().cloned() { None => { self.current_timer = Instant::now(); }, Some(current_category) if current_category == category => { //since the current category is the same as the new activity's category, //we don't need to do anything with the timer, we just need to push it on the stack } Some(current_category) => { let elapsed = self.stop_timer(); //record the current category's time let new_time = self.data.times.get(current_category) + elapsed; self.data.times.set(current_category, new_time); } } //push the new category self.timer_stack.push(category); } pub fn record_computed_queries(&mut self, category: ProfileCategory, count: usize) { let (hits, computed) = *self.data.query_counts.get(category); self.data.query_counts.set(category, (hits, computed + count as u64)); } pub fn record_query_hit(&mut self, category: ProfileCategory) { let (hits, computed) = *self.data.query_counts.get(category); self.data.query_counts.set(category, (hits + 1, computed)); } pub fn end_activity(&mut self, category: ProfileCategory) { match self.timer_stack.pop() { None => bug!("end_activity() was called but there was no running activity"), Some(c) => assert!( c == category, "end_activity() was called but a different activity was running"), } //check if the new running timer is in the same category as this one //if it is, we don't need to do anything if let Some(c) = self.timer_stack.last() { if *c == category { return; } } //the new timer is different than the previous, //so record the elapsed time and start a new timer let elapsed = self.stop_timer(); let new_time = self.data.times.get(category) + elapsed; self.data.times.set(category, new_time); } fn stop_timer(&mut self) -> u64 { let elapsed = self.current_timer.elapsed(); self.current_timer = Instant::now(); (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64) } pub fn print_results(&mut self, opts: &Options) { self.end_activity(ProfileCategory::Other); assert!( self.timer_stack.is_empty(), "there were timers running when print_results() was called"); let out = io::stderr(); let mut lock = out.lock(); let crate_name = opts.crate_name .as_ref() .map(|n| format!(" for {}", n)) .unwrap_or_default(); writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); writeln!(lock).unwrap(); self.data.print(&mut lock); writeln!(lock).unwrap(); writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap(); let incremental = if opts.incremental.is_some() { "on" } else { "off" }; writeln!(lock, "Incremental: {}", incremental).unwrap(); } pub fn save_results(&self, opts: &Options) { let category_data = self.data.json(); let compilation_options = format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}", opts.optimize, if opts.incremental.is_some() { "true" } else { "false" }); let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}", category_data, compilation_options); fs::write("self_profiler_results.json", json).unwrap(); } }