rustc: improve -Z trans-stats to report per-fn LLVM instruction counts and translation timing

Author: graydon

src/librustc/middle/trans/base.rs

@@ -72,6 +72,7 @@ use std::uint;
 use std::vec;
 use std::local_data;
 use extra::time;
+use extra::sort;
 use syntax::ast::ident;
 use syntax::ast_map::{path, path_elt_to_str, path_name};
 use syntax::ast_util::{local_def, path_to_ident};
@@ -141,6 +142,48 @@ fn fcx_has_nonzero_span(fcx: fn_ctxt) -> bool {
     }
 }
 
+struct StatRecorder<'self> {
+    ccx: @mut CrateContext,
+    name: &'self str,
+    start: u64,
+    istart: uint,
+}
+
+impl<'self> StatRecorder<'self> {
+    pub fn new(ccx: @mut CrateContext,
+               name: &'self str) -> StatRecorder<'self> {
+        let start = if ccx.sess.trans_stats() {
+            time::precise_time_ns()
+        } else {
+            0
+        };
+        let istart = ccx.stats.n_llvm_insns;
+        StatRecorder {
+            ccx: ccx,
+            name: name,
+            start: start,
+            istart: istart,
+        }
+    }
+}
+
+#[unsafe_destructor]
+impl<'self> Drop for StatRecorder<'self> {
+    pub fn drop(&self) {
+        if self.ccx.sess.trans_stats() {
+            let end = time::precise_time_ns();
+            let elapsed = ((end - self.start) / 1_000_000) as uint;
+            let iend = self.ccx.stats.n_llvm_insns;
+            self.ccx.stats.fn_stats.push((self.name.to_owned(),
+                                          elapsed,
+                                          iend - self.istart));
+            self.ccx.stats.n_fns += 1;
+            // Reset LLVM insn count to avoid compound costs.
+            self.ccx.stats.n_llvm_insns = self.istart;
+        }
+    }
+}
+
 pub fn decl_fn(llmod: ModuleRef, name: &str, cc: lib::llvm::CallConv, ty: Type) -> ValueRef {
     let llfn: ValueRef = do name.as_c_str |buf| {
         unsafe {
@@ -1866,18 +1909,16 @@ pub fn trans_fn(ccx: @mut CrateContext,
                 param_substs: Option<@param_substs>,
                 id: ast::node_id,
                 attrs: &[ast::attribute]) {
-    let do_time = ccx.sess.trans_stats();
-    let start = if do_time { time::get_time() }
-                else { time::Timespec::new(0, 0) };
+
+    let the_path_str = path_str(ccx.sess, path);
+    let _s = StatRecorder::new(ccx, the_path_str);
     debug!("trans_fn(self_arg=%?, param_substs=%s)",
            self_arg,
            param_substs.repr(ccx.tcx));
     let _icx = push_ctxt("trans_fn");
-    ccx.stats.n_fns += 1;
-    let the_path_str = path_str(ccx.sess, path);
     let output_type = ty::ty_fn_ret(ty::node_id_to_type(ccx.tcx, id));
     trans_closure(ccx,
-                  path,
+                  copy path,
                   decl,
                   body,
                   llfndecl,
@@ -1893,10 +1934,6 @@ pub fn trans_fn(ccx: @mut CrateContext,
                       }
                   },
                   |_bcx| { });
-    if do_time {
-        let end = time::get_time();
-        ccx.log_fn_time(the_path_str, start, end);
-    }
 }
 
 pub fn trans_enum_variant(ccx: @mut CrateContext,
@@ -2961,8 +2998,14 @@ pub fn trans_crate(sess: session::Session,
         io::println(fmt!("n_monos: %u", ccx.stats.n_monos));
         io::println(fmt!("n_inlines: %u", ccx.stats.n_inlines));
         io::println(fmt!("n_closures: %u", ccx.stats.n_closures));
+        io::println("fn stats:");
+        do sort::quick_sort(ccx.stats.fn_stats) |&(_, _, insns_a), &(_, _, insns_b)| {
+            insns_a > insns_b
+        }
+        for ccx.stats.fn_stats.iter().advance |&(name, ms, insns)| {
+            io::println(fmt!("%u insns, %u ms, %s", insns, ms, name));
+        }
     }
-
     if ccx.sess.count_llvm_insns() {
         for ccx.stats.llvm_insns.iter().advance |(&k, &v)| {
             io::println(fmt!("%-7u %s", v, k));

src/librustc/middle/trans/build.rs

@@ -46,6 +46,9 @@ pub fn B(cx: block) -> BuilderRef {
 }
 
 pub fn count_insn(cx: block, category: &str) {
+    if cx.ccx().sess.trans_stats() {
+        cx.ccx().stats.n_llvm_insns += 1;
+    }
     do base::with_insn_ctxt |v| {
         let h = &mut cx.ccx().stats.llvm_insns;
 

src/librustc/middle/trans/common.rs

@@ -96,8 +96,10 @@ pub struct Stats {
     n_monos: uint,
     n_inlines: uint,
     n_closures: uint,
+    n_llvm_insns: uint,
+    llvm_insn_ctxt: ~[~str],
     llvm_insns: HashMap<~str, uint>,
-    fn_times: ~[(~str, int)] // (ident, time)
+    fn_stats: ~[(~str, uint, uint)] // (ident, time-in-ms, llvm-instructions)
 }
 
 pub struct BuilderRef_res {

src/librustc/middle/trans/context.rs

@@ -210,8 +210,10 @@ impl CrateContext {
                     n_monos: 0u,
                     n_inlines: 0u,
                     n_closures: 0u,
+                    n_llvm_insns: 0u,
+                    llvm_insn_ctxt: ~[],
                     llvm_insns: HashMap::new(),
-                    fn_times: ~[]
+                    fn_stats: ~[]
                   },
                   upcalls: upcall::declare_upcalls(targ_cfg, llmod),
                   tydesc_type: tydesc_type,
@@ -226,12 +228,6 @@ impl CrateContext {
             }
         }
     }
-
-    pub fn log_fn_time(&mut self, name: ~str, start: time::Timespec, end: time::Timespec) {
-        let elapsed = 1000 * ((end.sec - start.sec) as int) +
-            ((end.nsec as int) - (start.nsec as int)) / 1000000;
-        self.stats.fn_times.push((name, elapsed));
-    }
 }
 
 #[unsafe_destructor]

src/librustc/middle/trans/glue.rs

@@ -738,15 +738,9 @@ pub fn make_generic_glue(ccx: @mut CrateContext,
                          name: &str)
                       -> ValueRef {
     let _icx = push_ctxt("make_generic_glue");
-    if !ccx.sess.trans_stats() {
-        return make_generic_glue_inner(ccx, t, llfn, helper);
-    }
-
-    let start = time::get_time();
-    let llval = make_generic_glue_inner(ccx, t, llfn, helper);
-    let end = time::get_time();
-    ccx.log_fn_time(fmt!("glue %s %s", name, ty_to_short_str(ccx.tcx, t)), start, end);
-    return llval;
+    let glue_name = fmt!("glue %s %s", name, ty_to_short_str(ccx.tcx, t));
+    let _s = StatRecorder::new(ccx, glue_name);
+    make_generic_glue_inner(ccx, t, llfn, helper)
 }
 
 pub fn emit_tydescs(ccx: &mut CrateContext) {