diff options
| -rw-r--r-- | src/librustc/ty/query/plumbing.rs | 19 | ||||
| -rw-r--r-- | src/librustc/util/profiling.rs | 508 |
2 files changed, 345 insertions, 182 deletions
diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index a26b21a1059..8e80f95aba1 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -113,7 +113,7 @@ impl<'a, 'tcx, Q: QueryDescription<'tcx>> JobOwner<'a, 'tcx, Q> { let mut lock = cache.borrow_mut(); if let Some(value) = lock.results.get(key) { profq_msg!(tcx, ProfileQueriesMsg::CacheHit); - tcx.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + tcx.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); let result = Ok((value.value.clone(), value.index)); #[cfg(debug_assertions)] { @@ -375,7 +375,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { if dep_node.kind.is_anon() { profq_msg!(self, ProfileQueriesMsg::ProviderBegin); - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { job.start(self, diagnostics, |tcx| { @@ -385,7 +385,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); self.dep_graph.read_index(dep_node_index); @@ -452,14 +452,14 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { let result = if let Some(result) = result { profq_msg!(self, ProfileQueriesMsg::CacheHit); - self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); result } else { // We could not load a result from the on-disk cache, so // recompute. - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); // The diagnostics for this query have already been // promoted to the current session during @@ -472,7 +472,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); result }; @@ -541,7 +541,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { key, dep_node); profq_msg!(self, ProfileQueriesMsg::ProviderBegin); - self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY)); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { job.start(self, diagnostics, |tcx| { @@ -559,7 +559,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); - self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); + self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); if unlikely!(self.sess.opts.debugging_opts.query_dep_graph) { @@ -602,7 +602,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { let _ = self.get_query::<Q>(DUMMY_SP, key); } else { profq_msg!(self, ProfileQueriesMsg::CacheHit); - self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY)); } } @@ -729,6 +729,7 @@ macro_rules! define_queries_inner { sess.profiler(|p| { $( p.record_computed_queries( + <queries::$name<'_> as QueryConfig<'_>>::NAME, <queries::$name<'_> as QueryConfig<'_>>::CATEGORY, self.$name.lock().results.len() ); diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 0e03946f82a..2cec7ec65af 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -1,146 +1,167 @@ -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); @@ -149,103 +170,244 @@ impl SelfProfiler { } 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, |