diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index 99eee4b559a5c..774ab0333db54 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -1405,9 +1405,7 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options, crate_attr: Vec = (Vec::new(), parse_string_push, [TRACKED], "inject the given attribute in the crate"), self_profile: bool = (false, parse_bool, [UNTRACKED], - "run the self profiler"), - profile_json: bool = (false, parse_bool, [UNTRACKED], - "output a json file with profiler results"), + "run the self profiler and output the raw event data"), emit_stack_sizes: bool = (false, parse_bool, [UNTRACKED], "emits a section containing stack size metadata"), plt: Option = (None, parse_opt_bool, [TRACKED], diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index d873a72ed4d77..774bc8b450b59 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -1131,11 +1131,8 @@ pub fn build_session_( source_map: Lrc, driver_lint_caps: FxHashMap, ) -> Session { - let self_profiling_active = sopts.debugging_opts.self_profile || - sopts.debugging_opts.profile_json; - let self_profiler = - if self_profiling_active { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) } + if sopts.debugging_opts.self_profile { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) } else { None }; let host_triple = TargetTriple::from_triple(config::host_triple()); diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index c90bd12a3100f..bd40566065b6b 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -1,10 +1,12 @@ -use std::collections::{BTreeMap, HashMap}; +use std::collections::HashMap; use std::fs; -use std::io::{self, Write}; +use std::io::{BufWriter, Write}; +use std::mem; +use std::process; use std::thread::ThreadId; use std::time::Instant; -use crate::session::config::{Options, OptLevel}; +use crate::session::config::Options; #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)] pub enum ProfileCategory { @@ -23,140 +25,39 @@ pub enum ProfilerEvent { 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 }, IncrementalLoadResultStart { query_name: &'static str, time: Instant }, IncrementalLoadResultEnd { query_name: &'static str, time: Instant }, + QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: Instant }, + QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: Instant }, QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant }, QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, } impl ProfilerEvent { - fn is_start_event(&self) -> bool { + fn timestamp(&self) -> Instant { use self::ProfilerEvent::*; match self { - QueryStart { .. } | - GenericActivityStart { .. } | - IncrementalLoadResultStart { .. } | - QueryBlockedStart { .. } => true, - - QueryEnd { .. } | - GenericActivityEnd { .. } | - QueryCacheHit { .. } | - QueryCount { .. } | - IncrementalLoadResultEnd { .. } | - QueryBlockedEnd { .. } => false, + QueryStart { time, .. } | + QueryEnd { time, .. } | + GenericActivityStart { time, .. } | + GenericActivityEnd { time, .. } | + QueryCacheHit { time, .. } | + QueryCount { time, .. } | + IncrementalLoadResultStart { time, .. } | + IncrementalLoadResultEnd { time, .. } | + QueryBlockedStart { time, .. } | + QueryBlockedEnd { time, .. } => *time } } } -pub struct SelfProfiler { - events: HashMap>, -} - -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(), - } - } - - fn total_time(&self) -> u64 { - self.query_times.iter().map(|(_, time)| time).sum() - } - - fn total_cache_data(&self) -> (u64, u64) { - let (mut hits, mut total) = (0, 0); - - for (_, (h, t)) in &self.query_cache_stats { - hits += h; - total += t; - } - - (hits, total) - } -} - -impl Default for CategoryResultData { - fn default() -> CategoryResultData { - CategoryResultData::new() - } -} - -struct CalculatedResults { - categories: BTreeMap, - crate_name: Option, - optimization_level: OptLevel, - incremental: bool, - verbose: bool, -} - -impl CalculatedResults { - fn new() -> CalculatedResults { - CalculatedResults { - categories: BTreeMap::new(), - crate_name: None, - optimization_level: OptLevel::No, - incremental: false, - verbose: false, - } - } - - fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults { - for (category, data) in cr2.categories { - let cr1_data = cr1.categories.entry(category).or_default(); - - for (query, time) in data.query_times { - *cr1_data.query_times.entry(query).or_default() += time; - } - - 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 { - self.categories.iter().map(|(_, data)| data.total_time()).sum() - } - - 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 - } +fn thread_id_to_u64(tid: ThreadId) -> u64 { + unsafe { mem::transmute::(tid) } } -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 - } -} - -fn calculate_percent(numerator: u64, denominator: u64) -> f32 { - if denominator > 0 { - ((numerator as f32) / (denominator as f32)) * 100.0 - } else { - 0.0 - } +pub struct SelfProfiler { + events: HashMap>, } impl SelfProfiler { @@ -197,6 +98,7 @@ impl SelfProfiler { query_name, category, count, + time: Instant::now(), }) } @@ -205,6 +107,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryCacheHit { query_name, category, + time: Instant::now(), }) } @@ -268,208 +171,257 @@ impl SelfProfiler { events.push(event); } - fn calculate_thread_results(events: &Vec) -> CalculatedResults { + pub fn dump_raw_events(&self, opts: &Options) { 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(); - - //(event, child time to subtract) - let mut query_stack = Vec::new(); - - for event in events { - match event { - QueryStart { .. } | GenericActivityStart { .. } => { - query_stack.push((event, 0)); - }, - 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: _ }, child_time_to_subtract)) = 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 self_time_ns = time_ns - child_time_to_subtract; - let result_data = results.categories.entry(*category).or_default(); - - *result_data.query_times.entry(query_name).or_default() += self_time_ns; - - if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { - *child_time_to_subtract += time_ns; - } - } else { - bug!("Saw a query end but the previous event wasn't a query start"); - } + //find the earliest Instant to use as t=0 + //when serializing the events, we'll calculate a Duration + //using (instant - min_instant) + let min_instant = + self.events + .iter() + .map(|(_, values)| values[0].timestamp()) + .min() + .unwrap(); + + let pid = process::id(); + + let filename = + format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default()); + + let mut file = BufWriter::new(fs::File::create(filename).unwrap()); + + let threads: Vec<_> = + self.events + .keys() + .into_iter() + .map(|tid| format!("{}", thread_id_to_u64(*tid))) + .collect(); + + write!(file, + "{{\ + \"processes\": {{\ + \"{}\": {{\ + \"threads\": [{}],\ + \"crate_name\": \"{}\",\ + \"opt_level\": \"{:?}\",\ + \"incremental\": {}\ + }}\ + }},\ + \"events\": [\ + ", + pid, + threads.join(","), + opts.crate_name.clone().unwrap_or_default(), + opts.optimize, + if opts.incremental.is_some() { "true" } else { "false" }, + ).unwrap(); + + let mut is_first = true; + for (thread_id, events) in &self.events { + let thread_id = thread_id_to_u64(*thread_id); + + for event in events { + if is_first { + is_first = false; + } else { + writeln!(file, ",").unwrap(); } - GenericActivityEnd { category, time: end_time } => { - let previous_event = query_stack.pop(); - if let Some((GenericActivityStart { - category: previous_category, - time: start_time }, child_time_to_subtract)) = 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 self_time_ns = time_ns - child_time_to_subtract; - let result_data = results.categories.entry(*category).or_default(); - - *result_data.query_times - .entry("{time spent not running queries}") - .or_default() += self_time_ns; - - if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { - *child_time_to_subtract += 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; - }, - //we don't summarize incremental load result events in the simple output mode - IncrementalLoadResultStart { .. } | IncrementalLoadResultEnd { .. } => { }, - //we don't summarize parallel query blocking in the simple output mode - QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { }, - } - } - //normalize the times to ms - for (_, data) in &mut results.categories { - for (_, time) in &mut data.query_times { - *time = *time / 1_000_000; - } - } - - results - } - - 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); - - 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 = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default(); - - writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); - writeln!(lock).unwrap(); - - writeln!(lock, "| Phase | Time (ms) \ - | Time (%) | Queries | Hits (%)") - .unwrap(); - writeln!(lock, "| ----------------------------------------- | -------------- \ - | -------- | -------------- | --------") - .unwrap(); - - let mut categories: Vec<_> = results.categories.iter().collect(); - categories.sort_by_cached_key(|(_, d)| d.total_time()); - - for (category, data) in categories.iter().rev() { - 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(); + let (secs, nanos) = { + let duration = event.timestamp() - min_instant; + (duration.as_secs(), duration.subsec_nanos()) + }; + + match event { + QueryStart { query_name, category, time: _ } => + write!(file, + "{{ \ + \"QueryStart\": {{ \ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + secs, + nanos, + thread_id, + ).unwrap(), + QueryEnd { query_name, category, time: _ } => + write!(file, + "{{\ + \"QueryEnd\": {{\ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + secs, + nanos, + thread_id, + ).unwrap(), + GenericActivityStart { category, time: _ } => + write!(file, + "{{ + \"GenericActivityStart\": {{\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + category, + secs, + nanos, + thread_id, + ).unwrap(), + GenericActivityEnd { category, time: _ } => + write!(file, + "{{\ + \"GenericActivityEnd\": {{\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + category, + secs, + nanos, + thread_id, + ).unwrap(), + QueryCacheHit { query_name, category, time: _ } => + write!(file, + "{{\ + \"QueryCacheHit\": {{\ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + secs, + nanos, + thread_id, + ).unwrap(), + QueryCount { query_name, category, count, time: _ } => + write!(file, + "{{\ + \"QueryCount\": {{\ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"count\": {},\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + count, + secs, + nanos, + thread_id, + ).unwrap(), + IncrementalLoadResultStart { query_name, time: _ } => + write!(file, + "{{\ + \"IncrementalLoadResultStart\": {{\ + \"query_name\": \"{}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + secs, + nanos, + thread_id, + ).unwrap(), + IncrementalLoadResultEnd { query_name, time: _ } => + write!(file, + "{{\ + \"IncrementalLoadResultEnd\": {{\ + \"query_name\": \"{}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + secs, + nanos, + thread_id, + ).unwrap(), + QueryBlockedStart { query_name, category, time: _ } => + write!(file, + "{{\ + \"QueryBlockedStart\": {{\ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + secs, + nanos, + thread_id, + ).unwrap(), + QueryBlockedEnd { query_name, category, time: _ } => + write!(file, + "{{\ + \"QueryBlockedEnd\": {{\ + \"query_name\": \"{}\",\ + \"category\": \"{:?}\",\ + \"time\": {{\ + \"secs\": {},\ + \"nanos\": {}\ + }},\ + \"thread_id\": {}\ + }}\ + }}", + query_name, + category, + secs, + nanos, + thread_id, + ).unwrap() } } } - writeln!(lock).unwrap(); - writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap(); - writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap(); - } - - pub fn save_results(&self, opts: &Options) { - let results = self.get_results(opts); - - let compilation_options = - format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}", - 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, - compilation_options); - - fs::write("self_profiler_results.json", json).unwrap(); + write!(file, "] }}").unwrap(); } } diff --git a/src/librustc_driver/lib.rs b/src/librustc_driver/lib.rs index 9546498cf939a..cc1b8916c1074 100644 --- a/src/librustc_driver/lib.rs +++ b/src/librustc_driver/lib.rs @@ -276,13 +276,8 @@ fn run_compiler_with_pool<'a>( &control) }; - if sess.opts.debugging_opts.self_profile { - sess.profiler(|p| p.print_results(&sess.opts)); - } - - if sess.opts.debugging_opts.profile_json { - sess.profiler(|p| p.save_results(&sess.opts)); + sess.profiler(|p| p.dump_raw_events(&sess.opts)); } (result, Some(sess))