Auto merge of #58425 - wesleywiser:more_profiler_changes, r=michaelwoerister

[self-profiler] Make the profiler faster/more efficient

Related to #58372

r? @michaelwoerister

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",

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"),
+        "run the self profiler and output the raw event data"),
-    profile_json: bool = (false, parse_bool, [UNTRACKED],
-        "output a json file with profiler results"),
     emit_stack_sizes: bool = (false, parse_bool, [UNTRACKED],
         "emits a section containing stack size metadata"),
     plt: Option<bool> = (None, parse_opt_bool, [TRACKED],

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`.
+    /// Used by -Z self-profile
-    pub self_profiling_active: bool,
+    pub self_profiling: Option<Arc<PlMutex<SelfProfiler>>>,
-
-    /// Used by `-Z self-profile`.
-    pub self_profiling: Lock<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();
+        match &self.self_profiling {
-        f(&mut 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 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: self_profiler,
-        self_profiling: Lock::new(SelfProfiler::new()),
         profile_channel: Lock::new(None),
         perf_stats: PerfStats {
             symbol_hash_time: Lock::new(Duration::from_secs(0)),

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 },
+    QueryStart { query_name: &'static str, category: ProfileCategory, time: u64 },
-    QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
+    QueryEnd { query_name: &'static str, category: ProfileCategory, time: u64 },
-    GenericActivityStart { category: ProfileCategory, time: Instant },
+    GenericActivityStart { category: ProfileCategory, time: u64 },
-    GenericActivityEnd { category: ProfileCategory, time: Instant },
+    GenericActivityEnd { category: ProfileCategory, time: u64 },
-    QueryCacheHit { query_name: &'static str, category: ProfileCategory },
+    IncrementalLoadResultStart { query_name: &'static str, time: u64 },
-    QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
+    IncrementalLoadResultEnd { query_name: &'static str, time: u64 },
-    IncrementalLoadResultStart { query_name: &'static str, time: Instant },
+    QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: u64 },
-    IncrementalLoadResultEnd { query_name: &'static str, time: Instant },
+    QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: u64 },
-    QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant },
+    QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: u64 },
-    QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
+    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 { .. } |
+            QueryStart { time, .. } |
-            GenericActivityStart { .. } |
+            QueryEnd { time, .. } |
-            IncrementalLoadResultStart { .. } |
+            GenericActivityStart { time, .. } |
-            QueryBlockedStart { .. } => true,
+            GenericActivityEnd { time, .. } |
-
+            QueryCacheHit { time, .. } |
-            QueryEnd { .. } |
+            QueryCount { time, .. } |
-            GenericActivityEnd { .. } |
+            IncrementalLoadResultStart { time, .. } |
-            QueryCacheHit { .. } |
+            IncrementalLoadResultEnd { time, .. } |
-            QueryCount { .. } |
+            QueryBlockedStart { time, .. } |
-            IncrementalLoadResultEnd { .. } |
+            QueryBlockedEnd { time, .. } => *time
-            QueryBlockedEnd { .. } => false,
         }
     }
 }
 
+fn thread_id_to_u64(tid: ThreadId) -> u64 {
+    unsafe { mem::transmute::<ThreadId, u64>(tid) }
+}
+
 pub struct SelfProfiler {
-    events: HashMap<ThreadId, Vec<ProfilerEvent>>,
+    events: FxHashMap<ThreadId, Vec<ProfilerEvent>>,
-}
+    start_time: SystemTime,
-
+    start_instant: Instant,
-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<ProfileCategory, CategoryResultData>,
-    crate_name: Option<String>,
-    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 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
-    }
 }
 
 impl SelfProfiler {
     pub fn new() -> SelfProfiler {
-        let mut profiler = SelfProfiler {
+        let profiler = SelfProfiler {
-            events: HashMap::new(),
+            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 {
+    #[inline]
+    fn get_time_from_start(&self) -> u64 {
+        let duration = Instant::now() - self.start_instant;
+        duration.as_nanos() as u64
+    }
+
+    pub fn dump_raw_events(&self, opts: &Options) {
         use self::ProfilerEvent::*;
 
-        assert!(
+        let pid = process::id();
-            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 filename =
+            format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default());
 
-        //(event, child time to subtract)
+        let mut file = BufWriter::new(fs::File::create(filename).unwrap());
-        let mut query_stack = Vec::new();
 
-        for event in events {
+        let threads: Vec<_> =
-            match event {
+            self.events
-                QueryStart { .. } | GenericActivityStart { .. } => {
+                .keys()
-                    query_stack.push((event, 0));
+                .into_iter()
-                },
+                .map(|tid| format!("{}", thread_id_to_u64(*tid)))
-                QueryEnd { query_name, category, time: end_time } => {
+                .collect();
-                    let previous_query = query_stack.pop();
+
-                    if let Some((QueryStart {
+        write!(file,
-                                    query_name: p_query_name,
+            "{{\
-                                    time: start_time,
+                \"processes\": {{\
-                                    category: _ }, child_time_to_subtract)) = previous_query {
+                    \"{}\": {{\
-                        assert_eq!(
+                        \"threads\": [{}],\
-                            p_query_name,
+                        \"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();
+                }
+
+                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,
-                            "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");
-                    }
-                }
-                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"
+                            secs,
-                        );
+                            nanos,
-
+                            thread_id,
-                        let time_ns = time_between_ns(*start_time, *end_time);
+                        ).unwrap(),
-                        let self_time_ns = time_ns - child_time_to_subtract;
+                    QueryEnd { query_name, category, time: _ } =>
-                        let result_data = results.categories.entry(*category).or_default();
+                        write!(file,
-
+                            "{{\
-                        *result_data.query_times
+                                \"QueryEnd\": {{\
-                            .entry("{time spent not running queries}")
+                                    \"query_name\": \"{}\",\
-                            .or_default() += self_time_ns;
+                                    \"category\": \"{:?}\",\
-
+                                    \"time\": {{\
-                        if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
+                                        \"secs\": {},\
-                            *child_time_to_subtract += time_ns;
+                                        \"nanos\": {}\
-                        }
+                                    }},\
-                    } else {
+                                    \"thread_id\": {}\
-                        bug!("Saw an activity end but the previous event wasn't an activity start");
+                                }}\
-                    }
+                            }}",
-                },
+                            query_name,
-                QueryCacheHit { category, query_name } => {
+                            category,
-                    let result_data = results.categories.entry(*category).or_default();
+                            secs,
-
+                            nanos,
-                    let (hits, total) =
+                            thread_id,
-                        result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
+                        ).unwrap(),
-                    *hits += 1;
+                    GenericActivityStart { category, time: _ } =>
-                    *total += 1;
+                        write!(file,
-                },
+                            "{{
-                QueryCount { category, query_name, count } => {
+                                \"GenericActivityStart\": {{\
-                    let result_data = results.categories.entry(*category).or_default();
+                                    \"category\": \"{:?}\",\
-
+                                    \"time\": {{\
-                    let (_, totals) =
+                                        \"secs\": {},\
-                        result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
+                                        \"nanos\": {}\
-                    *totals += *count as u64;
+                                    }},\
-                },
+                                    \"thread_id\": {}\
-                //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
+                            category,
-                QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { },
+                            secs,
-            }
+                            nanos,
-        }
+                            thread_id,
-
+                        ).unwrap(),
-        //normalize the times to ms
+                    GenericActivityEnd { category, time: _ } =>
-        for (_, data) in &mut results.categories {
+                        write!(file,
-            for (_, time) in &mut data.query_times {
+                            "{{\
-                *time = *time / 1_000_000;
+                                \"GenericActivityEnd\": {{\
-            }
+                                    \"category\": \"{:?}\",\
-        }
+                                    \"time\": {{\
-
+                                        \"secs\": {},\
-        results
+                                        \"nanos\": {}\
-    }
+                                    }},\
-
+                                    \"thread_id\": {}\
-    fn get_results(&self, opts: &Options) -> CalculatedResults {
+                                }}\
-        self.events
+                            }}",
-            .iter()
+                            category,
-            .map(|(_, r)| SelfProfiler::calculate_thread_results(r))
+                            secs,
-            .fold(CalculatedResults::new(), CalculatedResults::consolidate)
+                            nanos,
-            .with_options(opts)
+                            thread_id,
-    }
+                        ).unwrap(),
-
+                    QueryCacheHit { query_name, category, time: _ } =>
-    pub fn print_results(&mut self, opts: &Options) {
+                        write!(file,
-        self.end_activity(ProfileCategory::Other);
+                            "{{\
-
+                                \"QueryCacheHit\": {{\
-        let results = self.get_results(opts);
+                                    \"query_name\": \"{}\",\
-
+                                    \"category\": \"{:?}\",\
-        let total_time = results.total_time() as f32;
+                                    \"time\": {{\
-
+                                        \"secs\": {},\
-        let out = io::stderr();
+                                        \"nanos\": {}\
-        let mut lock = out.lock();
+                                    }},\
-
+                                    \"thread_id\": {}\
-        let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default();
+                                }}\
-
+                            }}",
-        writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
+                            query_name,
-        writeln!(lock).unwrap();
+                            category,
-
+                            secs,
-        writeln!(lock, "| Phase                                     | Time (ms)      \
+                            nanos,
-                        | Time (%) | Queries        | Hits (%)")
+                            thread_id,
-            .unwrap();
+                        ).unwrap(),
-        writeln!(lock, "| ----------------------------------------- | -------------- \
+                    QueryCount { query_name, category, count, time: _ } =>
-                        | -------- | -------------- | --------")
+                        write!(file,
-            .unwrap();
+                            "{{\
-
+                                \"QueryCount\": {{\
-        let mut categories: Vec<_> = results.categories.iter().collect();
+                                    \"query_name\": \"{}\",\
-        categories.sort_by_cached_key(|(_, d)| d.total_time());
+                                    \"category\": \"{:?}\",\
-
+                                    \"count\": {},\
-        for (category, data) in categories.iter().rev() {
+                                    \"time\": {{\
-            let (category_hits, category_total) = data.total_cache_data();
+                                        \"secs\": {},\
-            let category_hit_percent = calculate_percent(category_hits, category_total);
+                                        \"nanos\": {}\
-
+                                    }},\
-            writeln!(
+                                    \"thread_id\": {}\
-                lock,
+                                }}\
-                "| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
+                            }}",
-                format!("{:?}", category),
+                            query_name,
-                data.total_time(),
+                            category,
-                ((data.total_time() as f32) / total_time) * 100.0,
+                            count,
-                category_total,
+                            secs,
-                format!("{:.2}", category_hit_percent),
+                            nanos,
-            ).unwrap();
+                            thread_id,
-
+                        ).unwrap(),
-            //in verbose mode, show individual query data
+                    IncrementalLoadResultStart { query_name, time: _ } =>
-            if results.verbose {
+                        write!(file,
-                //don't show queries that took less than 1ms
+                            "{{\
-                let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect();
+                                \"IncrementalLoadResultStart\": {{\
-                times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1));
+                                    \"query_name\": \"{}\",\
-
+                                    \"time\": {{\
-                for (query, time) in times {
+                                        \"secs\": {},\
-                    let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0));
+                                        \"nanos\": {}\
-                    let hit_percent = calculate_percent(*hits, *total);
+                                    }},\
-
+                                    \"thread_id\": {}\
-                    writeln!(
+                                }}\
-                        lock,
+                            }}",
-                        "| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
+                            query_name,
-                        query,
+                            secs,
-                        time,
+                            nanos,
-                        ((*time as f32) / total_time) * 100.0,
+                            thread_id,
-                        total,
+                        ).unwrap(),
-                        format!("{:.2}", hit_percent),
+                    IncrementalLoadResultEnd { query_name, time: _ } =>
-                    ).unwrap();
+                        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();
+        write!(file, "] }}").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();
     }
 }

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" }

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(),

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;

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,

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))
 }