Basic profiling

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,8 @@ fn parse_cross_lang_lto(slot: &mut CrossLangLto, v: Option<&str>) -> bool {
         "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"),
 }
 
 pub fn default_lib_output() -> CrateType {

src/librustc/session/mod.rs

@@ -40,6 +40,7 @@
 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,16 @@ pub fn incr_comp_session_dir_opt(&self) -> Option<cell::Ref<PathBuf>> {
         }
     }
 
+    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 print_perf_stats(&self) {
         println!(
             "Total time spent computing symbol hashes:      {}",
@@ -1125,6 +1139,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::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 @@
 
 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::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

@@ -379,6 +379,7 @@ fn try_get_with<Q: QueryDescription<'gcx>>(
 
         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, || {
@@ -386,6 +387,7 @@ fn try_get_with<Q: QueryDescription<'gcx>>(
                 })
             });
 
+            self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
             profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
             let ((result, dep_node_index), diagnostics) = res;
 
@@ -523,6 +525,8 @@ fn force_query_with_job<Q: QueryDescription<'gcx>>(
                 key, dep_node);
 
         profq_msg!(self, ProfileQueriesMsg::ProviderBegin);
+        self.sess.profiler(|p| p.start_activity(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 +540,8 @@ fn force_query_with_job<Q: QueryDescription<'gcx>>(
                                         Q::compute)
             }
         });
+
+        self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
         profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
 
         let ((result, dep_node_index), diagnostics) = res;
@@ -655,6 +661,7 @@ pub(super) fn get_query<Q: QueryDescription<'gcx>>(
             rustc_data_structures::stable_hasher::StableHasher,
             ich::StableHashingContext
         };
+        use util::profiling::ProfileCategory;
 
         define_queries_struct! {
             tcx: $tcx,
@@ -768,6 +775,7 @@ pub fn $name<F: FnOnce() -> R, R>(f: F) -> R {
             type Value = $V;
 
             const NAME: &'static str = stringify!($name);
+            const CATEGORY: ProfileCategory = $category;
         }
 
         impl<$tcx> QueryAccessors<$tcx> for queries::$name<$tcx> {

src/librustc/util/profiling.rs

+// Copyright 2018 The Rust Project Developers. See the COPYRIGHT
+// file at the top-level directory of this distribution and at
+// http://rust-lang.org/COPYRIGHT.
+//
+// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
+// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
+// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
+// option. This file may not be copied, modified, or distributed
+// except according to those terms.
+
+use session::config::Options;
+
+use std::io::{self, StdoutLock, Write};
+use std::time::Instant;
+
+#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)]
+pub enum ProfileCategory {
+    Parsing,
+    Expansion,
+    TypeChecking,
+    BorrowChecking,
+    Codegen,
+    Linking,
+    Other,
+}
+
+struct Categories<T> {
+    parsing: T,
+    expansion: T,
+    type_checking: T,
+    borrow_checking: T,
+    codegen: T,
+    linking: T,
+    other: T,
+}
+
+impl<T: Default> Categories<T> {
+    fn new() -> Categories<T> {
+        Categories {
+            parsing: T::default(),
+            expansion: T::default(),
+            type_checking: T::default(),
+            borrow_checking: T::default(),
+            codegen: T::default(),
+            linking: T::default(),
+            other: T::default(),
+        }
+    }
+}
+
+impl<T> Categories<T> {
+    fn get(&self, category: ProfileCategory) -> &T {
+        match category {
+            ProfileCategory::Parsing => &self.parsing,
+            ProfileCategory::Expansion => &self.expansion,
+            ProfileCategory::TypeChecking => &self.type_checking,
+            ProfileCategory::BorrowChecking => &self.borrow_checking,
+            ProfileCategory::Codegen => &self.codegen,
+            ProfileCategory::Linking => &self.linking,
+            ProfileCategory::Other => &self.other,
+        }
+    }
+
+    fn set(&mut self, category: ProfileCategory, value: T) {
+        match category {
+            ProfileCategory::Parsing => self.parsing = value,
+            ProfileCategory::Expansion => self.expansion = value,
+            ProfileCategory::TypeChecking => self.type_checking = value,
+            ProfileCategory::BorrowChecking => self.borrow_checking = value,
+            ProfileCategory::Codegen => self.codegen = value,
+            ProfileCategory::Linking => self.linking = value,
+            ProfileCategory::Other => self.other = value,
+        }
+    }
+}
+
+struct CategoryData {
+    times: Categories<u64>,
+}
+
+impl CategoryData {
+    fn new() -> CategoryData {
+        CategoryData {
+            times: Categories::new(),
+        }
+    }
+
+    fn print(&self, lock: &mut StdoutLock) {
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "Parsing", self.times.parsing / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "Expansion", self.times.expansion / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "TypeChecking", self.times.type_checking / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "BorrowChecking", self.times.borrow_checking / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "Codegen", self.times.codegen / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "Linking", self.times.linking / 1_000_000).unwrap();
+        writeln!(lock, "{0: <15} \t\t {1: <15}", "Other", self.times.other / 1_000_000).unwrap();
+    }
+}
+
+pub struct SelfProfiler {
+    timer_stack: Vec<ProfileCategory>,
+    data: CategoryData,
+    current_timer: Instant,
+}
+
+pub struct ProfilerActivity<'a>(ProfileCategory, &'a mut SelfProfiler);
+
+impl<'a> Drop for ProfilerActivity<'a> {
+    fn drop(&mut self) {
+        let ProfilerActivity (category, profiler) = self;
+
+        profiler.end_activity(*category);
+    }
+}
+
+impl SelfProfiler {
+    pub fn new() -> SelfProfiler {
+        let mut profiler = SelfProfiler {
+            timer_stack: Vec::new(),
+            data: CategoryData::new(),
+            current_timer: Instant::now(),
+        };
+
+        profiler.start_activity(ProfileCategory::Other);
+
+        profiler
+    }
+
+    pub fn start_activity(&mut self, category: ProfileCategory) {
+        match self.timer_stack.last().cloned() {
+            None => {
+                self.current_timer = Instant::now();
+            },
+            Some(current_category) if current_category == category => {
+                //since the current category is the same as the new activity's category,
+                //we don't need to do anything with the timer, we just need to push it on the stack
+            }
+            Some(current_category) => {
+                let elapsed = self.stop_timer();
+
+                //record the current category's time
+                let new_time = self.data.times.get(current_category) + elapsed;
+                self.data.times.set(current_category, new_time);
+            }
+        }
+
+        //push the new category
+        self.timer_stack.push(category);
+    }
+
+    pub fn end_activity(&mut self, category: ProfileCategory) {
+        match self.timer_stack.pop() {
+            None => bug!("end_activity() was called but there was no running activity"),
+            Some(c) => 
+                assert!(
+                    c == category, 
+                    "end_activity() was called but a different activity was running"),
+        }
+
+        //check if the new running timer is in the same category as this one
+        //if it is, we don't need to do anything
+        if let Some(c) = self.timer_stack.last() {
+            if *c == category {
+                return;
+            }
+        }
+
+        //the new timer is different than the previous, so record the elapsed time and start a new timer
+        let elapsed = self.stop_timer();
+        let new_time = self.data.times.get(category) + elapsed;
+        self.data.times.set(category, new_time);
+    }
+
+    fn stop_timer(&mut self) -> u64 {
+        let elapsed = self.current_timer.elapsed();
+
+        self.current_timer = Instant::now();
+
+        (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64)
+    }
+
+    pub fn print_results(&mut self, opts: &Options) {
+        self.end_activity(ProfileCategory::Other);
+
+        assert!(self.timer_stack.is_empty(), "there were timers running when print_results() was called");
+
+        let out = io::stdout();
+        let mut lock = out.lock();
+
+        let crate_name = opts.crate_name.as_ref().map(|n| format!(" for {}", n)).unwrap_or_default();
+
+        writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
+
+        self.data.print(&mut lock);
+
+        writeln!(lock).unwrap();
+        writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
+
+        let incremental = if opts.incremental.is_some() { "on" } else { "off" };
+        writeln!(lock, "Incremental: {}", incremental).unwrap();
+    }
+
+    pub fn record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> {
+        self.start_activity(category);
+
+        ProfilerActivity(category, self)
+    }
+}
\ No newline at end of file

src/librustc_codegen_llvm/base.rs

@@ -45,6 +45,7 @@
 use rustc::middle::cstore::{self, LinkMeta, LinkagePreference};
 use rustc::middle::exported_symbols;
 use rustc::util::common::{time, print_time_passes_entry};
+use rustc::util::profiling::ProfileCategory;
 use rustc::session::config::{self, NoDebugInfo};
 use rustc::session::Session;
 use rustc_incremental;
@@ -741,11 +742,13 @@ pub fn codegen_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>,
     let link_meta = link::build_link_meta(crate_hash);
 
     // Codegen the metadata.
+    tcx.sess.profiler(|p| p.start_activity(ProfileCategory::Codegen));
     let llmod_id = "metadata";
     let metadata_llvm_module = ModuleLlvm::new(tcx.sess, llmod_id);
     let metadata = time(tcx.sess, "write metadata", || {
         write_metadata(tcx, &metadata_llvm_module, &link_meta)
     });
+    tcx.sess.profiler(|p| p.end_activity(ProfileCategory::Codegen));
 
     let metadata_module = ModuleCodegen {
         name: link::METADATA_MODULE_NAME.to_string(),

src/librustc_codegen_llvm/lib.rs

@@ -84,6 +84,7 @@
 use rustc::ty::{self, TyCtxt};
 use rustc::util::time_graph;
 use rustc::util::nodemap::{FxHashSet, FxHashMap};
+use rustc::util::profiling::ProfileCategory;
 use rustc_mir::monomorphize;
 use rustc_codegen_utils::codegen_backend::CodegenBackend;
 
@@ -240,10 +241,12 @@ fn join_codegen_and_link(
 
         // Run the linker on any artifacts that resulted from the LLVM run.
         // This should produce either a finished executable or library.
+        sess.profiler(|p| p.start_activity(ProfileCategory::Linking));
         time(sess, "linking", || {
             back::link::link_binary(sess, &ongoing_codegen,
                                     outputs, &ongoing_codegen.crate_name.as_str());
         });
+        sess.profiler(|p| p.end_activity(ProfileCategory::Linking));
 
         // Now that we won't touch anything in the incremental compilation directory
         // any more, we can finalize it (which involves renaming it)

src/librustc_driver/driver.rs

@@ -25,6 +25,7 @@
 use rustc::ty::{self, AllArenas, Resolutions, TyCtxt};
 use rustc::traits;
 use rustc::util::common::{install_panic_hook, time, ErrorReported};
+use rustc::util::profiling::ProfileCategory;
 use rustc_allocator as allocator;
 use rustc_borrowck as borrowck;
 use rustc_incremental;
@@ -352,6 +353,10 @@ pub fn compile_input(
         sess.print_perf_stats();
     }
 
+    if sess.opts.debugging_opts.self_profile {
+        sess.print_profiler_results();
+    }
+
     controller_entry_point!(
         compilation_done,
         sess,
@@ -667,6 +672,7 @@ pub fn phase_1_parse_input<'a>(
         profile::begin(sess);
     }
 
+    sess.profiler(|p| p.start_activity(ProfileCategory::Parsing));
     let krate = time(sess, "parsing", || match *input {
         Input::File(ref file) => parse::parse_crate_from_file(file, &sess.parse_sess),
         Input::Str {
@@ -674,6 +680,7 @@ pub fn phase_1_parse_input<'a>(
             ref name,
         } => parse::parse_crate_from_source_str(name.clone(), input.clone(), &sess.parse_sess),
     })?;
+    sess.profiler(|p| p.end_activity(ProfileCategory::Parsing));
 
     sess.diagnostic().set_continue_after_error(true);
 
@@ -944,6 +951,7 @@ pub fn phase_2_configure_and_expand_inner<'a, F>(
     syntax_ext::register_builtins(&mut resolver, syntax_exts, sess.features_untracked().quote);
 
     // Expand all macros
+    sess.profiler(|p| p.start_activity(ProfileCategory::Expansion));
     krate = time(sess, "expansion", || {
         // Windows dlls do not have rpaths, so they don't know how to find their
         // dependencies. It's up to us to tell the system where to find all the
@@ -1021,6 +1029,7 @@ pub fn phase_2_configure_and_expand_inner<'a, F>(
         }
         krate
     });
+    sess.profiler(|p| p.end_activity(ProfileCategory::Expansion));
 
     krate = time(sess, "maybe building test harness", || {
         syntax::test::modify_for_testing(
@@ -1350,7 +1359,9 @@ pub fn phase_4_codegen<'a, 'tcx>(
         ::rustc::middle::dependency_format::calculate(tcx)
     });
 
+    tcx.sess.profiler(|p| p.start_activity(ProfileCategory::Codegen));
     let codegen = time(tcx.sess, "codegen", move || codegen_backend.codegen_crate(tcx, rx));
+    tcx.sess.profiler(|p| p.end_activity(ProfileCategory::Codegen));
     if tcx.sess.profile_queries() {
         profile::dump(&tcx.sess, "profile_queries".to_string())
     }

src/librustc_typeck/lib.rs

@@ -109,6 +109,7 @@
 use rustc::ty::{self, Ty, TyCtxt};
 use rustc::ty::query::Providers;
 use rustc::traits::{ObligationCause, ObligationCauseCode, TraitEngine, TraitEngineExt};
+use rustc::util::profiling::ProfileCategory;
 use session::{CompileIncomplete, config};
 use util::common::time;
 
@@ -334,6 +335,8 @@ pub fn provide(providers: &mut Providers) {
 pub fn check_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>)
                              -> Result<(), CompileIncomplete>
 {
+    tcx.sess.profiler(|p| p.start_activity(ProfileCategory::TypeChecking));
+
     // this ensures that later parts of type checking can assume that items
     // have valid types and not error
     tcx.sess.track_errors(|| {
@@ -371,6 +374,8 @@ pub fn check_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>)
     check_unused::check_crate(tcx);
     check_for_entry_fn(tcx);
 
+    tcx.sess.profiler(|p| p.end_activity(ProfileCategory::TypeChecking));
+
     tcx.sess.compile_status()
 }