Add some infrastructure for timing things where time_passes can't be used.

Author: michaelwoerister

src/librustc/session/config.rs

@@ -908,6 +908,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options,
           "dump MIR state at various points in translation"),
     dump_mir_dir: Option<String> = (None, parse_opt_string, [UNTRACKED],
           "the directory the MIR is dumped into"),
+    perf_stats: bool = (false, parse_bool, [UNTRACKED],
+          "print some performance-related statistics"),
 }
 
 pub fn default_lib_output() -> CrateType {

src/librustc/session/mod.rs

@@ -18,6 +18,7 @@ use session::search_paths::PathKind;
 use session::config::{DebugInfoLevel, PanicStrategy};
 use ty::tls;
 use util::nodemap::{NodeMap, FnvHashMap};
+use util::common::duration_to_secs_str;
 use mir::transform as mir_pass;
 
 use syntax::ast::{NodeId, Name};
@@ -43,6 +44,7 @@ use std::env;
 use std::ffi::CString;
 use std::rc::Rc;
 use std::fmt;
+use std::time::Duration;
 use libc::c_int;
 
 pub mod config;
@@ -104,9 +106,23 @@ pub struct Session {
 
     incr_comp_session: RefCell<IncrCompSession>,
 
+    /// Some measurements that are being gathered during compilation.
+    pub perf_stats: PerfStats,
+
     next_node_id: Cell<ast::NodeId>,
 }
 
+pub struct PerfStats {
+    // The accumulated time needed for computing the SVH of the crate
+    pub svh_time: Cell<Duration>,
+    // The accumulated time spent on computing incr. comp. hashes
+    pub incr_comp_hashes_time: Cell<Duration>,
+    // The number of incr. comp. hash computations performed
+    pub incr_comp_hashes_count: Cell<u64>,
+    // The accumulated time spent on computing symbol hashes
+    pub symbol_hash_time: Cell<Duration>,
+}
+
 impl Session {
     pub fn local_crate_disambiguator(&self) -> token::InternedString {
         self.crate_disambiguator.borrow().clone()
@@ -404,6 +420,17 @@ impl Session {
             None
         }
     }
+
+    pub fn print_perf_stats(&self) {
+        println!("Total time spent computing SVHs:               {}",
+                 duration_to_secs_str(self.perf_stats.svh_time.get()));
+        println!("Total time spent computing incr. comp. hashes: {}",
+                 duration_to_secs_str(self.perf_stats.incr_comp_hashes_time.get()));
+        println!("Total number of incr. comp. hashes computed:   {}",
+                 self.perf_stats.incr_comp_hashes_count.get());
+        println!("Total time spent computing symbol hashes:      {}",
+                 duration_to_secs_str(self.perf_stats.symbol_hash_time.get()));
+    }
 }
 
 pub fn build_session(sopts: config::Options,
@@ -520,6 +547,12 @@ pub fn build_session_(sopts: config::Options,
         available_macros: RefCell::new(HashSet::new()),
         imported_macro_spans: RefCell::new(HashMap::new()),
         incr_comp_session: RefCell::new(IncrCompSession::NotInitialized),
+        perf_stats: PerfStats {
+            svh_time: Cell::new(Duration::from_secs(0)),
+            incr_comp_hashes_time: Cell::new(Duration::from_secs(0)),
+            incr_comp_hashes_count: Cell::new(0),
+            symbol_hash_time: Cell::new(Duration::from_secs(0)),
+        }
     };
 
     init_llvm(&sess);

src/librustc/util/common.rs

@@ -17,7 +17,7 @@ use std::fmt::Debug;
 use std::hash::{Hash, BuildHasher};
 use std::iter::repeat;
 use std::path::Path;
-use std::time::Instant;
+use std::time::{Duration, Instant};
 
 use hir;
 use hir::intravisit;
@@ -47,27 +47,44 @@ pub fn time<T, F>(do_it: bool, what: &str, f: F) -> T where
     let rv = f();
     let dur = start.elapsed();
 
-    // Hack up our own formatting for the duration to make it easier for scripts
-    // to parse (always use the same number of decimal places and the same unit).
-    const NANOS_PER_SEC: f64 = 1_000_000_000.0;
-    let secs = dur.as_secs() as f64;
-    let secs = secs + dur.subsec_nanos() as f64 / NANOS_PER_SEC;
-
     let mem_string = match get_resident() {
         Some(n) => {
             let mb = n as f64 / 1_000_000.0;
             format!("; rss: {}MB", mb.round() as usize)
         }
         None => "".to_owned(),
     };
-    println!("{}time: {:.3}{}\t{}", repeat("  ").take(old).collect::<String>(),
-             secs, mem_string, what);
+    println!("{}time: {}{}\t{}",
+             repeat("  ").take(old).collect::<String>(),
+             duration_to_secs_str(dur),
+             mem_string,
+             what);
 
     DEPTH.with(|slot| slot.set(old));
 
     rv
 }
 
+// Hack up our own formatting for the duration to make it easier for scripts
+// to parse (always use the same number of decimal places and the same unit).
+pub fn duration_to_secs_str(dur: Duration) -> String {
+    const NANOS_PER_SEC: f64 = 1_000_000_000.0;
+    let secs = dur.as_secs() as f64 +
+               dur.subsec_nanos() as f64 / NANOS_PER_SEC;
+
+    format!("{:.3}", secs)
+}
+
+pub fn record_time<T, F>(accu: &Cell<Duration>, f: F) -> T where
+    F: FnOnce() -> T,
+{
+    let start = Instant::now();
+    let rv = f();
+    let duration = start.elapsed();
+    accu.set(duration + accu.get());
+    rv
+}
+
 // Like std::macros::try!, but for Option<>.
 macro_rules! option_try(
     ($e:expr) => (match $e { Some(e) => e, None => return None })

src/librustc_driver/driver.rs

@@ -233,6 +233,10 @@ pub fn compile_input(sess: &Session,
     // any more, we can finalize it (which involves renaming it)
     rustc_incremental::finalize_session_directory(sess, trans.link.crate_hash);
 
+    if sess.opts.debugging_opts.perf_stats {
+        sess.print_perf_stats();
+    }
+
     controller_entry_point!(compilation_done,
                             sess,
                             CompileState::state_when_compilation_done(input, sess, outdir, output),

src/librustc_trans/back/symbol_names.rs

@@ -108,6 +108,7 @@ use rustc::ty::{Ty, TyCtxt, TypeFoldable};
 use rustc::ty::item_path::{self, ItemPathBuffer, RootMode};
 use rustc::ty::subst::Substs;
 use rustc::hir::map::definitions::{DefPath, DefPathData};
+use rustc::util::common::record_time;
 
 use syntax::attr;
 use syntax::parse::token::{self, InternedString};
@@ -138,33 +139,35 @@ fn get_symbol_hash<'a, 'tcx>(scx: &SharedCrateContext<'a, 'tcx>,
 
     let tcx = scx.tcx();
 
-    let mut hash_state = scx.symbol_hasher().borrow_mut();
-
-    hash_state.reset();
-
-    // the main symbol name is not necessarily unique; hash in the
-    // compiler's internal def-path, guaranteeing each symbol has a
-    // truly unique path
-    hash_state.input_str(&def_path.to_string(tcx));
-
-    // Include the main item-type. Note that, in this case, the
-    // assertions about `needs_subst` may not hold, but this item-type
-    // ought to be the same for every reference anyway.
-    assert!(!item_type.has_erasable_regions());
-    let encoded_item_type = tcx.sess.cstore.encode_type(tcx, item_type, def_id_to_string);
-    hash_state.input(&encoded_item_type[..]);
-
-    // also include any type parameters (for generic items)
-    if let Some(substs) = substs {
-        for t in substs.types() {
-            assert!(!t.has_erasable_regions());
-            assert!(!t.needs_subst());
-            let encoded_type = tcx.sess.cstore.encode_type(tcx, t, def_id_to_string);
-            hash_state.input(&encoded_type[..]);
+    return record_time(&tcx.sess.perf_stats.symbol_hash_time, || {
+        let mut hash_state = scx.symbol_hasher().borrow_mut();
+
+        hash_state.reset();
+
+        // the main symbol name is not necessarily unique; hash in the
+        // compiler's internal def-path, guaranteeing each symbol has a
+        // truly unique path
+        hash_state.input_str(&def_path.to_string(tcx));
+
+        // Include the main item-type. Note that, in this case, the
+        // assertions about `needs_subst` may not hold, but this item-type
+        // ought to be the same for every reference anyway.
+        assert!(!item_type.has_erasable_regions());
+        let encoded_item_type = tcx.sess.cstore.encode_type(tcx, item_type, def_id_to_string);
+        hash_state.input(&encoded_item_type[..]);
+
+        // also include any type parameters (for generic items)
+        if let Some(substs) = substs {
+            for t in substs.types() {
+                assert!(!t.has_erasable_regions());
+                assert!(!t.needs_subst());
+                let encoded_type = tcx.sess.cstore.encode_type(tcx, t, def_id_to_string);
+                hash_state.input(&encoded_type[..]);
+            }
         }
-    }
 
-    return format!("h{}", truncated_hash_result(&mut *hash_state));
+        format!("h{}", truncated_hash_result(&mut *hash_state))
+    });
 
     fn truncated_hash_result(symbol_hasher: &mut Sha256) -> String {
         let output = symbol_hasher.result_bytes();