-use crate::session::config::Options;
-
+use std::collections::{BTreeMap, HashMap};
use std::fs;
-use std::io::{self, StderrLock, Write};
+use std::io::{self, Write};
+use std::thread::ThreadId;
use std::time::Instant;
-macro_rules! define_categories {
- ($($name:ident,)*) => {
- #[derive(Clone, Copy, Debug, PartialEq, Eq)]
- pub enum ProfileCategory {
- $($name),*
+use crate::session::config::{Options, OptLevel};
+
+#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
+pub enum ProfileCategory {
+ Parsing,
+ Expansion,
+ TypeChecking,
+ BorrowChecking,
+ Codegen,
+ Linking,
+ Other,
+}
+
+#[derive(Clone, Copy, Debug, Eq, PartialEq)]
+pub enum ProfilerEvent {
+ QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant },
+ QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
+ GenericActivityStart { category: ProfileCategory, time: Instant },
+ GenericActivityEnd { category: ProfileCategory, time: Instant },
+ QueryCacheHit { query_name: &'static str, category: ProfileCategory },
+ QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
+}
+
+impl ProfilerEvent {
+ fn is_start_event(&self) -> bool {
+ use self::ProfilerEvent::*;
+
+ match self {
+ QueryStart { .. } | GenericActivityStart { .. } => true,
+ QueryEnd { .. } | GenericActivityEnd { .. } |
+ QueryCacheHit { .. } | QueryCount { .. } => false,
}
+ }
+}
- #[allow(nonstandard_style)]
- struct Categories<T> {
- $($name: T),*
+pub struct SelfProfiler {
+ events: HashMap<ThreadId, Vec<ProfilerEvent>>,
+}
+
+struct CategoryResultData {
+ query_times: BTreeMap<&'static str, u64>,
+ query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total)
+}
+
+impl CategoryResultData {
+ fn new() -> CategoryResultData {
+ CategoryResultData {
+ query_times: BTreeMap::new(),
+ query_cache_stats: BTreeMap::new(),
}
+ }
- impl<T: Default> Categories<T> {
- fn new() -> Categories<T> {
- Categories {
- $($name: T::default()),*
- }
- }
+ fn total_time(&self) -> u64 {
+ let mut total = 0;
+ for (_, time) in &self.query_times {
+ total += time;
}
- impl<T> Categories<T> {
- fn get(&self, category: ProfileCategory) -> &T {
- match category {
- $(ProfileCategory::$name => &self.$name),*
- }
- }
+ total
+ }
- fn set(&mut self, category: ProfileCategory, value: T) {
- match category {
- $(ProfileCategory::$name => self.$name = value),*
- }
- }
- }
+ fn total_cache_data(&self) -> (u64, u64) {
+ let (mut hits, mut total) = (0, 0);
- struct CategoryData {
- times: Categories<u64>,
- query_counts: Categories<(u64, u64)>,
+ for (_, (h, t)) in &self.query_cache_stats {
+ hits += h;
+ total += t;
}
- impl CategoryData {
- fn new() -> CategoryData {
- CategoryData {
- times: Categories::new(),
- query_counts: Categories::new(),
- }
- }
+ (hits, total)
+ }
+}
- 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())
- };
+impl Default for CategoryResultData {
+ fn default() -> CategoryResultData {
+ CategoryResultData::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();
- )*
- }
+struct CalculatedResults {
+ categories: BTreeMap<ProfileCategory, CategoryResultData>,
+ crate_name: Option<String>,
+ optimization_level: OptLevel,
+ incremental: bool,
+ verbose: bool,
+}
- 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)
- ));
- )*
+impl CalculatedResults {
+ fn new() -> CalculatedResults {
+ CalculatedResults {
+ categories: BTreeMap::new(),
+ crate_name: None,
+ optimization_level: OptLevel::No,
+ incremental: false,
+ verbose: false,
+ }
+ }
- //remove the trailing ',' character
- json.pop();
+ fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults {
+ for (category, data) in cr2.categories {
+ let cr1_data = cr1.categories.entry(category).or_default();
- json.push(']');
+ for (query, time) in data.query_times {
+ *cr1_data.query_times.entry(query).or_default() += time;
+ }
- json
+ for (query, (hits, total)) in data.query_cache_stats {
+ let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0));
+ *h += hits;
+ *t += total;
}
}
+
+ cr1
+ }
+
+ fn total_time(&self) -> u64 {
+ let mut total = 0;
+
+ for (_, data) in &self.categories {
+ total += data.total_time();
+ }
+
+ total
+ }
+
+ fn with_options(mut self, opts: &Options) -> CalculatedResults {
+ self.crate_name = opts.crate_name.clone();
+ self.optimization_level = opts.optimize;
+ self.incremental = opts.incremental.is_some();
+ self.verbose = opts.debugging_opts.verbose;
+
+ self
}
}
-define_categories! {
- Parsing,
- Expansion,
- TypeChecking,
- BorrowChecking,
- Codegen,
- Linking,
- Other,
+fn time_between_ns(start: Instant, end: Instant) -> u64 {
+ if start < end {
+ let time = end - start;
+ (time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64)
+ } else {
+ debug!("time_between_ns: ignorning instance of end < start");
+ 0
+ }
}
-pub struct SelfProfiler {
- timer_stack: Vec<ProfileCategory>,
- data: CategoryData,
- current_timer: Instant,
+fn calculate_percent(numerator: u64, denominator: u64) -> f32 {
+ if denominator > 0 {
+ ((numerator as f32) / (denominator as f32)) * 100.0
+ } else {
+ 0.0
+ }
}
impl SelfProfiler {
pub fn new() -> SelfProfiler {
let mut profiler = SelfProfiler {
- timer_stack: Vec::new(),
- data: CategoryData::new(),
- current_timer: Instant::now(),
+ events: HashMap::new(),
};
profiler.start_activity(ProfileCategory::Other);
}
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();
+ self.record(ProfilerEvent::GenericActivityStart {
+ category,
+ time: Instant::now(),
+ })
+ }
- //record the current category's time
- let new_time = self.data.times.get(current_category) + elapsed;
- self.data.times.set(current_category, new_time);
- }
- }
+ pub fn end_activity(&mut self, category: ProfileCategory) {
+ self.record(ProfilerEvent::GenericActivityEnd {
+ category,
+ time: Instant::now(),
+ })
+ }
- //push the new category
- self.timer_stack.push(category);
+ pub fn record_computed_queries(
+ &mut self,
+ query_name: &'static str,
+ category: ProfileCategory,
+ count: usize)
+ {
+ self.record(ProfilerEvent::QueryCount {
+ query_name,
+ category,
+ count,
+ })
}
- 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, query_name: &'static str, category: ProfileCategory) {
+ self.record(ProfilerEvent::QueryCacheHit {
+ query_name,
+ category,
+ })
}
- 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 start_query(&mut self, query_name: &'static str, category: ProfileCategory) {
+ self.record(ProfilerEvent::QueryStart {
+ query_name,
+ category,
+ time: Instant::now(),
+ });
}
- 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"),
+ pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) {
+ self.record(ProfilerEvent::QueryEnd {
+ query_name,
+ category,
+ time: Instant::now(),
+ })
+ }
+
+ fn record(&mut self, event: ProfilerEvent) {
+ let thread_id = std::thread::current().id();
+ let events = self.events.entry(thread_id).or_default();
+
+ events.push(event);
+ }
+
+ fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
+ use self::ProfilerEvent::*;
+
+ assert!(
+ events.last().map(|e| !e.is_start_event()).unwrap_or(true),
+ "there was an event running when calculate_reslts() was called"
+ );
+
+ let mut results = CalculatedResults::new();
+
+ let mut query_stack = Vec::new();
+
+ for event in events {
+ match event {
+ QueryStart { .. } | GenericActivityStart { .. } => {
+ query_stack.push(event);
+ },
+ QueryEnd { query_name, category, time: end_time } => {
+ let previous_query = query_stack.pop();
+ if let Some(QueryStart {
+ query_name: p_query_name,
+ time: start_time,
+ category: _ }) = previous_query {
+ assert_eq!(
+ p_query_name,
+ query_name,
+ "Saw a query end but the previous query wasn't the corresponding start"
+ );
+
+ let time_ns = time_between_ns(*start_time, *end_time);
+ let result_data = results.categories.entry(*category).or_default();
+
+ *result_data.query_times.entry(query_name).or_default() += time_ns;
+ } else {
+ bug!("Saw a query end but the previous event wasn't a query start");
+ }
+ }
+ GenericActivityEnd { category, time: end_time } => {
+ let previous_event = query_stack.pop();
+ if let Some(GenericActivityStart {
+ category: previous_category,
+ time: start_time }) = previous_event {
+ assert_eq!(
+ previous_category,
+ category,
+ "Saw an end but the previous event wasn't the corresponding start"
+ );
+
+ let time_ns = time_between_ns(*start_time, *end_time);
+ let result_data = results.categories.entry(*category).or_default();
+
+ *result_data.query_times
+ .entry("{time spent not running queries}")
+ .or_default() += time_ns;
+ } else {
+ bug!("Saw an activity end but the previous event wasn't an activity start");
+ }
+ },
+ QueryCacheHit { category, query_name } => {
+ let result_data = results.categories.entry(*category).or_default();
+
+ let (hits, total) =
+ result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
+ *hits += 1;
+ *total += 1;
+ },
+ QueryCount { category, query_name, count } => {
+ let result_data = results.categories.entry(*category).or_default();
+
+ let (_, totals) =
+ result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
+ *totals += *count as u64;
+ },
+ }
}
- //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;
+ //normalize the times to ms
+ for (_, data) in &mut results.categories {
+ for (_, time) in &mut data.query_times {
+ *time = *time / 1_000_000;
}
}
- //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);
+ results
}
- 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)
+ fn get_results(&self, opts: &Options) -> CalculatedResults {
+ self.events
+ .iter()
+ .map(|(_, r)| SelfProfiler::calculate_thread_results(r))
+ .fold(CalculatedResults::new(), CalculatedResults::consolidate)
+ .with_options(opts)
}
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 results = self.get_results(opts);
+
+ let total_time = results.total_time() as f32;
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();
+ let crate_name = results.crate_name.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, "| Phase | Time (ms) \
+ | Time (%) | Queries | Hits (%)")
+ .unwrap();
+ writeln!(lock, "| ----------------------------------------- | -------------- \
+ | -------- | -------------- | --------")
+ .unwrap();
+
+ let mut categories: Vec<_> = results.categories.iter().collect();
+ categories.sort_by(|(_, data1), (_, data2)| data2.total_time().cmp(&data1.total_time()));
+
+ for (category, data) in categories {
+ let (category_hits, category_total) = data.total_cache_data();
+ let category_hit_percent = calculate_percent(category_hits, category_total);
+
+ writeln!(
+ lock,
+ "| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
+ format!("{:?}", category),
+ data.total_time(),
+ ((data.total_time() as f32) / total_time) * 100.0,
+ category_total,
+ format!("{:.2}", category_hit_percent),
+ ).unwrap();
+
+ //in verbose mode, show individual query data
+ if results.verbose {
+ //don't show queries that took less than 1ms
+ let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect();
+ times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1));
+
+ for (query, time) in times {
+ let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0));
+ let hit_percent = calculate_percent(*hits, *total);
+
+ writeln!(
+ lock,
+ "| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
+ query,
+ time,
+ ((*time as f32) / total_time) * 100.0,
+ total,
+ format!("{:.2}", hit_percent),
+ ).unwrap();
+ }
+ }
+ }
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();
+ writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap();
}
pub fn save_results(&self, opts: &Options) {
- let category_data = self.data.json();
+ let results = self.get_results(opts);
+
let compilation_options =
format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
- opts.optimize,
- if opts.incremental.is_some() { "true" } else { "false" });
+ results.optimization_level,
+ if results.incremental { "true" } else { "false" });
+
+ let mut category_data = String::new();
+
+ for (category, data) in &results.categories {
+ let (hits, total) = data.total_cache_data();
+ let hit_percent = calculate_percent(hits, total);
+
+ category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \
+ \"query_count\": {}, \"query_hits\": {} }}",
+ category,
+ data.total_time(),
+ total,
+ format!("{:.2}", hit_percent)));
+ }
let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
category_data,
projects / rust.git / commitdiff