diff options
| -rw-r--r-- | Cargo.lock | 1 | ||||
| -rw-r--r-- | src/librustc/session/config.rs | 4 | ||||
| -rw-r--r-- | src/librustc/session/mod.rs | 43 | ||||
| -rw-r--r-- | src/librustc/util/profiling.rs | 627 | ||||
| -rw-r--r-- | src/librustc_codegen_ssa/Cargo.toml | 1 | ||||
| -rw-r--r-- | src/librustc_codegen_ssa/back/write.rs | 24 | ||||
| -rw-r--r-- | src/librustc_codegen_ssa/lib.rs | 3 | ||||
| -rw-r--r-- | src/librustc_driver/driver.rs | 8 | ||||
| -rw-r--r-- | src/librustc_driver/lib.rs | 4 |
9 files changed, 343 insertions, 372 deletions
diff --git a/Cargo.lock b/Cargo.lock index 2e5dce66a33..9154cb4d5b8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2625,6 +2625,7 @@ dependencies = [ "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "memmap 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)", "num_cpus 1.8.0 (registry+https://github.com/rust-lang/crates.io-index)", + "parking_lot 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)", "rustc 0.0.0", "rustc-demangle 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)", "rustc_allocator 0.0.0", diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index 99eee4b559a..774ab0333db 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<String> = (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<bool> = (None, parse_opt_bool, [TRACKED], diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 3cff5ec2309..774bc8b450b 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -44,7 +44,9 @@ use std::fmt; use std::io::Write; use std::path::PathBuf; use std::time::Duration; -use std::sync::mpsc; +use std::sync::{Arc, mpsc}; + +use parking_lot::Mutex as PlMutex; mod code_stats; pub mod config; @@ -127,11 +129,8 @@ pub struct Session { /// Used by `-Z profile-queries` in `util::common`. pub profile_channel: Lock<Option<mpsc::Sender<ProfileQueriesMsg>>>, - /// Used by `-Z self-profile`. - pub self_profiling_active: bool, - - /// Used by `-Z self-profile`. - pub self_profiling: Lock<SelfProfiler>, + /// Used by -Z self-profile + pub self_profiling: Option<Arc<PlMutex<SelfProfiler>>>, /// Some measurements that are being gathered during compilation. pub perf_stats: PerfStats, @@ -834,27 +833,23 @@ impl Session { #[inline(never)] #[cold] fn profiler_active<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) { - let mut profiler = self.self_profiling.borrow_mut(); - f(&mut profiler); + match &self.self_profiling { + None => bug!("profiler_active() called but there was no profiler active"), + Some(profiler) => { + let mut p = profiler.lock(); + + f(&mut p); + } + } } #[inline(always)] pub fn profiler<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) { - if unlikely!(self.self_profiling_active) { + if unlikely!(self.self_profiling.is_some()) { self.profiler_active(f) } } - pub fn print_profiler_results(&self) { - let mut profiler = self.self_profiling.borrow_mut(); - profiler.print_results(&self.opts); - } - - pub fn save_json_results(&self) { - let profiler = self.self_profiling.borrow(); - profiler.save_results(&self.opts); - } - pub fn print_perf_stats(&self) { println!( "Total time spent computing symbol hashes: {}", @@ -1136,6 +1131,10 @@ pub fn build_session_( source_map: Lrc<source_map::SourceMap>, driver_lint_caps: FxHashMap<lint::LintId, lint::Level>, ) -> Session { + let self_profiler = + if sopts.debugging_opts.self_profile { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) } + else { None }; + let host_triple = TargetTriple::from_triple(config::host_triple()); let host = Target::search(&host_triple).unwrap_or_else(|e| span_diagnostic @@ -1185,9 +1184,6 @@ pub fn build_session_( CguReuseTracker::new_disabled() }; - let self_profiling_active = sopts.debugging_opts.self_profile || - sopts.debugging_opts.profile_json; - let sess = Session { target: target_cfg, host, @@ -1216,8 +1212,7 @@ pub fn build_session_( imported_macro_spans: OneThread::new(RefCell::new(FxHashMap::default())), incr_comp_session: OneThread::new(RefCell::new(IncrCompSession::NotInitialized)), cgu_reuse_tracker, - self_profiling_active, - self_profiling: Lock::new(SelfProfiler::new()), + self_profiling: self_profiler, profile_channel: Lock::new(None), perf_stats: PerfStats { symbol_hash_time: Lock::new(Duration::from_secs(0)), diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index c90bd12a310..c134d48f987 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -1,10 +1,13 @@ -use std::collections::{BTreeMap, 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 std::time::{Duration, Instant, SystemTime}; -use crate::session::config::{Options, OptLevel}; +use crate::session::config::Options; + +use rustc_data_structures::fx::FxHashMap; #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)] pub enum ProfileCategory { @@ -19,154 +22,55 @@ pub enum ProfileCategory { #[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 }, - IncrementalLoadResultStart { query_name: &'static str, time: Instant }, - IncrementalLoadResultEnd { query_name: &'static str, time: Instant }, - QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant }, - QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, + QueryStart { query_name: &'static str, category: ProfileCategory, time: u64 }, + QueryEnd { query_name: &'static str, category: ProfileCategory, time: u64 }, + GenericActivityStart { category: ProfileCategory, time: u64 }, + GenericActivityEnd { category: ProfileCategory, time: u64 }, + IncrementalLoadResultStart { query_name: &'static str, time: u64 }, + IncrementalLoadResultEnd { query_name: &'static str, time: u64 }, + QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: u64 }, + QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: u64 }, + QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: u64 }, + QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: u64 }, } impl ProfilerEvent { - fn is_start_event(&self) -> bool { + fn timestamp(&self) -> u64 { use self::ProfilerEvent::*; match self { - QueryStart { .. } | - GenericActivityStart { .. } | - IncrementalLoadResultStart { .. } | - QueryBlockedStart { .. } => true, - - QueryEnd { .. } | - GenericActivityEnd { .. } | - QueryCacheHit { .. } | - QueryCount { .. } | - IncrementalLoadResultEnd { .. } | - QueryBlockedEnd { .. } => false, - } - } -} - -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(), - } - } - - 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; + QueryStart { time, .. } | + QueryEnd { time, .. } | + GenericActivityStart { time, .. } | + GenericActivityEnd { time, .. } | + QueryCacheHit { time, .. } | + QueryCount { time, .. } | + IncrementalLoadResultStart { time, .. } | + IncrementalLoadResultEnd { time, .. } | + QueryBlockedStart { time, .. } | + QueryBlockedEnd { time, .. } => *time } - - (hits, total) } } -impl Default for CategoryResultData { - fn default() -> CategoryResultData { - CategoryResultData::new() - } -} - -struct CalculatedResults { - categories: BTreeMap<ProfileCategory, CategoryResultData>, - crate_name: Option<String>, - optimization_level: OptLevel, - incremental: bool, - verbose: bool, +fn thread_id_to_u64(tid: ThreadId) -> u64 { + unsafe { mem::transmute::<ThreadId, u64>(tid) } } -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 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: FxHashMap<ThreadId, Vec<ProfilerEvent>>, + start_time: SystemTime, + start_instant: Instant, } impl SelfProfiler { pub fn new() -> SelfProfiler { - let mut profiler = SelfProfiler { - events: HashMap::new(), + let profiler = SelfProfiler { + events: Default::default(), + start_time: SystemTime::now(), + start_instant: Instant::now(), }; - profiler.start_activity(ProfileCategory::Other); - profiler } @@ -174,7 +78,7 @@ impl SelfProfiler { pub fn start_activity(&mut self, category: ProfileCategory) { self.record(ProfilerEvent::GenericActivityStart { category, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -182,7 +86,7 @@ impl SelfProfiler { pub fn end_activity(&mut self, category: ProfileCategory) { self.record(ProfilerEvent::GenericActivityEnd { category, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -197,6 +101,7 @@ impl SelfProfiler { query_name, category, count, + time: self.get_time_from_start(), }) } @@ -205,6 +110,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryCacheHit { query_name, category, + time: self.get_time_from_start(), }) } @@ -213,7 +119,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryStart { query_name, category, - time: Instant::now(), + time: self.get_time_from_start(), }); } @@ -222,7 +128,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryEnd { query_name, category, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -230,7 +136,7 @@ impl SelfProfiler { pub fn incremental_load_result_start(&mut self, query_name: &'static str) { self.record(ProfilerEvent::IncrementalLoadResultStart { query_name, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -238,7 +144,7 @@ impl SelfProfiler { pub fn incremental_load_result_end(&mut self, query_name: &'static str) { self.record(ProfilerEvent::IncrementalLoadResultEnd { query_name, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -247,7 +153,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryBlockedStart { query_name, category, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -256,7 +162,7 @@ impl SelfProfiler { self.record(ProfilerEvent::QueryBlockedEnd { query_name, category, - time: Instant::now(), + time: self.get_time_from_start(), }) } @@ -268,208 +174,255 @@ impl SelfProfiler { 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(); - - //(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(); + #[inline] + fn get_time_from_start(&self) -> u64 { + let duration = Instant::now() - self.start_instant; + duration.as_nanos() as u64 + } - *result_data.query_times.entry(query_name).or_default() += self_time_ns; + pub fn dump_raw_events(&self, opts: &Options) { + use self::ProfilerEvent::*; - 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"); - } + 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 time = self.start_time + Duration::from_nanos(event.timestamp()); + let time_since_unix = + time.duration_since(SystemTime::UNIX_EPOCH).unwrap_or_default(); + (time_since_unix.as_secs(), time_since_unix.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_codegen_ssa/Cargo.toml b/src/librustc_codegen_ssa/Cargo.toml index 0aba43580f1..4702e34aa19 100644 --- a/src/librustc_codegen_ssa/Cargo.toml +++ b/src/librustc_codegen_ssa/Cargo.toml @@ -19,6 +19,7 @@ memmap = "0.6" log = "0.4.5" libc = "0.2.44" jobserver = "0.1.11" +parking_lot = "0.7" serialize = { path = "../libserialize" } syntax = { path = "../libsyntax" } diff --git a/src/librustc_codegen_ssa/back/write.rs b/src/librustc_codegen_ssa/back/write.rs index 908ee95efcb..4bccc2a6d1f 100644 --- a/src/librustc_codegen_ssa/back/write.rs +++ b/src/librustc_codegen_ssa/back/write.rs @@ -19,6 +19,7 @@ use rustc::util::time_graph::{self, TimeGraph, Timeline}; use rustc::hir::def_id::{CrateNum, LOCAL_CRATE}; use rustc::ty::TyCtxt; use rustc::util::common::{time_depth, set_time_depth, print_time_passes_entry}; +use rustc::util::profiling::SelfProfiler; use rustc_fs_util::link_or_copy; use rustc_data_structures::svh::Svh; use rustc_errors::{Handler, Level, DiagnosticBuilder, FatalError, DiagnosticId}; @@ -29,6 +30,7 @@ use syntax::ext::hygiene::Mark; use syntax_pos::MultiSpan; use syntax_pos::symbol::Symbol; use jobserver::{Client, Acquired}; +use parking_lot::Mutex as PlMutex; use std::any::Any; use std::fs; @@ -201,6 +203,7 @@ pub struct CodegenContext<B: WriteBackendMethods> { // Resources needed when running LTO pub backend: B, pub time_passes: bool, + pub profiler: Option<Arc<PlMutex<SelfProfiler>>>, pub lto: Lto, pub no_landing_pads: bool, pub save_temps: bool, @@ -254,6 +257,26 @@ impl<B: WriteBackendMethods> CodegenContext<B> { ModuleKind::Allocator => &self.allocator_module_config, } } + + #[inline(never)] + #[cold] + fn profiler_active<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) { + match &self.profiler { + None => bug!("profiler_active() called but there was no profiler active"), + Some(profiler) => { + let mut p = profiler.lock(); + + f(&mut p); + } + } + } + + #[inline(always)] + pub fn profile<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) { + if unlikely!(self.profiler.is_some()) { + self.profiler_active(f) + } + } } fn generate_lto_work<B: ExtraBackendMethods>( @@ -1033,6 +1056,7 @@ fn start_executing_work<B: ExtraBackendMethods>( save_temps: sess.opts.cg.save_temps, opts: Arc::new(sess.opts.clone()), time_passes: sess.time_passes(), + profiler: sess.self_profiling.clone(), exported_symbols, plugin_passes: sess.plugin_llvm_passes.borrow().clone(), remark: sess.opts.cg.remark.clone(), diff --git a/src/librustc_codegen_ssa/lib.rs b/src/librustc_codegen_ssa/lib.rs index f38b22aa041..fec41936a23 100644 --- a/src/librustc_codegen_ssa/lib.rs +++ b/src/librustc_codegen_ssa/lib.rs @@ -2,9 +2,11 @@ #![feature(box_patterns)] #![feature(box_syntax)] +#![feature(core_intrinsics)] #![feature(custom_attribute)] #![feature(libc)] #![feature(rustc_diagnostic_macros)] +#![feature(stmt_expr_attributes)] #![feature(in_band_lifetimes)] #![feature(nll)] #![allow(unused_attributes)] @@ -20,6 +22,7 @@ #[macro_use] extern crate log; #[macro_use] extern crate rustc; +#[macro_use] extern crate rustc_data_structures; #[macro_use] extern crate syntax; use std::path::PathBuf; diff --git a/src/librustc_driver/driver.rs b/src/librustc_driver/driver.rs index 858a5602e7b..d3e295607c2 100644 --- a/src/librustc_driver/driver.rs +++ b/src/librustc_driver/driver.rs @@ -349,14 +349,6 @@ pub fn compile_input( sess.print_perf_stats(); } - if sess.opts.debugging_opts.self_profile { - sess.print_profiler_results(); - } - - if sess.opts.debugging_opts.profile_json { - sess.save_json_results(); - } - controller_entry_point!( compilation_done, sess, diff --git a/src/librustc_driver/lib.rs b/src/librustc_driver/lib.rs index 52dbb618d0d..cc1b8916c10 100644 --- a/src/librustc_driver/lib.rs +++ b/src/librustc_driver/lib.rs @@ -276,6 +276,10 @@ fn run_compiler_with_pool<'a>( &control) }; + if sess.opts.debugging_opts.self_profile { + sess.profiler(|p| p.dump_raw_events(&sess.opts)); + } + (result, Some(sess)) } |