Auto merge of #51657 - wesleywiser:wip_profiling, r=eddyb

Implement a self profiler

This is a work in progress implementation of #50780. I'd love feedback on the overall structure and code as well as some specific things:

- [The query categorization mechanism](https://github.com/rust-lang/rust/compare/master...wesleywiser:wip_profiling?expand=1#diff-19e0a69c10eff31eb2d16805e79f3437R101). This works but looks kind of ugly to me. Perhaps there's a better way?

- [The profiler assumes only one activity can run at a time](https://github.com/rust-lang/rust/compare/master...wesleywiser:wip_profiling?expand=1#diff-f8a403b2d88d873e4b27c097c614a236R177). This is obviously incompatible with the ongoing parallel queries.

- [The output code is just a bunch of `format!()`s](https://github.com/rust-lang/rust/compare/master...wesleywiser:wip_profiling?expand=1#diff-f8a403b2d88d873e4b27c097c614a236R91). Is there a better way to generate markdown or json in the compiler?

- [The query categorizations are likely wrong](https://github.com/rust-lang/rust/compare/master...wesleywiser:wip_profiling?expand=1#diff-19e0a69c10eff31eb2d16805e79f3437R101). I've marked what seemed obvious to me but I'm sure I got a lot of them wrong.

The overhead currently seems very low. Running `perf` on a sample compilation with profiling enabled reveals:
![image](https://user-images.githubusercontent.com/831192/41657821-9775efec-7462-11e8-9e5e-47ec94105d9d.png)

Author: bors

src/librustc/lib.rs

@@ -165,6 +165,7 @@ pub mod util {
     pub mod nodemap;
     pub mod fs;
     pub mod time_graph;
+    pub mod profiling;
 }
 
 // A private module so that macro-expanded idents like

src/librustc/session/config.rs

@@ -65,7 +65,7 @@ pub enum Sanitizer {
     Thread,
 }
 
-#[derive(Clone, Copy, PartialEq, Hash)]
+#[derive(Clone, Copy, Debug, PartialEq, Hash)]
 pub enum OptLevel {
     No,         // -O0
     Less,       // -O1
@@ -1367,6 +1367,10 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options,
         "disables the 'leak check' for subtyping; unsound, but useful for tests"),
     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"),
 }
 
 pub fn default_lib_output() -> CrateType {

src/librustc/session/mod.rs

@@ -40,6 +40,7 @@ use syntax::parse::ParseSess;
 use syntax::{ast, codemap};
 use syntax::feature_gate::AttributeType;
 use syntax_pos::{MultiSpan, Span};
+use util::profiling::SelfProfiler;
 
 use rustc_target::spec::{LinkerFlavor, PanicStrategy};
 use rustc_target::spec::{Target, TargetTriple};
@@ -133,6 +134,9 @@ 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: Lock<SelfProfiler>,
+
     /// Some measurements that are being gathered during compilation.
     pub perf_stats: PerfStats,
 
@@ -825,6 +829,21 @@ impl Session {
         }
     }
 
+    pub fn profiler<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) {
+        let mut profiler = self.self_profiling.borrow_mut();
+        f(&mut profiler);
+    }
+
+    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:      {}",
@@ -1125,6 +1144,7 @@ pub fn build_session_(
         imported_macro_spans: OneThread::new(RefCell::new(HashMap::new())),
         incr_comp_session: OneThread::new(RefCell::new(IncrCompSession::NotInitialized)),
         ignored_attr_names: ich::compute_ignored_attr_names(),
+        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/ty/query/config.rs

@@ -21,6 +21,7 @@ use ty::subst::Substs;
 use ty::query::queries;
 use ty::query::Query;
 use ty::query::QueryCache;
+use util::profiling::ProfileCategory;
 
 use std::hash::Hash;
 use std::fmt::Debug;
@@ -33,6 +34,7 @@ use ich::StableHashingContext;
 
 pub trait QueryConfig<'tcx> {
     const NAME: &'static str;
+    const CATEGORY: ProfileCategory;
 
     type Key: Eq + Hash + Clone + Debug;
     type Value: Clone + for<'a> HashStable<StableHashingContext<'a>>;

src/librustc/ty/query/mod.rs

@@ -46,6 +46,7 @@ use ty::steal::Steal;
 use ty::subst::Substs;
 use util::nodemap::{DefIdSet, DefIdMap, ItemLocalSet};
 use util::common::{ErrorReported};
+use util::profiling::ProfileCategory::*;
 
 use rustc_data_structures::indexed_set::IdxSetBuf;
 use rustc_target::spec::PanicStrategy;

src/librustc/ty/query/plumbing.rs

@@ -118,6 +118,11 @@ 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(Q::CATEGORY);
+                    p.record_query_hit(Q::CATEGORY);
+                });
+
                 let result = Ok((value.value.clone(), value.index));
                 return TryGetJob::JobCompleted(result);
             }
@@ -358,10 +363,13 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
             )
         );
 
+        self.sess.profiler(|p| p.record_query(Q::CATEGORY));
+
         let job = match JobOwner::try_get(self, span, &key) {
             TryGetJob::NotYetStarted(job) => job,
             TryGetJob::JobCompleted(result) => {
                 return result.map(|(v, index)| {
+                    self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY));
                     self.dep_graph.read_index(index);
                     v
                 })
@@ -379,13 +387,15 @@ 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));
 
             let res = job.start(self, |tcx| {
                 tcx.dep_graph.with_anon_task(dep_node.kind, || {
                     Q::compute(tcx.global_tcx(), key)
                 })
             });
 
+            self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
             profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
             let ((result, dep_node_index), diagnostics) = res;
 
@@ -402,6 +412,8 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
         if !dep_node.kind.is_input() {
             if let Some(dep_node_index) = self.try_mark_green_and_read(&dep_node) {
                 profq_msg!(self, ProfileQueriesMsg::CacheHit);
+                self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY));
+
                 return self.load_from_disk_and_cache_in_memory::<Q>(key,
                                                                     job,
                                                                     dep_node_index,
@@ -523,6 +535,11 @@ 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);
+            p.record_query(Q::CATEGORY);
+        });
+
         let res = job.start(self, |tcx| {
             if dep_node.kind.is_eval_always() {
                 tcx.dep_graph.with_eval_always_task(dep_node,
@@ -536,6 +553,8 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
                                         Q::compute)
             }
         });
+
+        self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
         profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
 
         let ((result, dep_node_index), diagnostics) = res;
@@ -574,7 +593,15 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
             // DepNodeIndex. We must invoke the query itself. The performance cost
             // this introduces should be negligible as we'll immediately hit the
             // in-memory cache, or another query down the line will.
+
+            self.sess.profiler(|p| {
+                p.start_activity(Q::CATEGORY);
+                p.record_query(Q::CATEGORY);
+            });
+
             let _ = self.get_query::<Q>(DUMMY_SP, key);
+
+            self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
         }
     }
 
@@ -655,6 +682,7 @@ macro_rules! define_queries_inner {
             rustc_data_structures::stable_hasher::StableHasher,
             ich::StableHashingContext
         };
+        use util::profiling::ProfileCategory;
 
         define_queries_struct! {
             tcx: $tcx,
@@ -768,6 +796,7 @@ macro_rules! define_queries_inner {
             type Value = $V;
 
             const NAME: &'static str = stringify!($name);
+            const CATEGORY: ProfileCategory = $category;
         }
 
         impl<$tcx> QueryAccessors<$tcx> for queries::$name<$tcx> {