-Z profile-query-and-key, separate from -Z profile-query; query key is string option

Author: Matthew Hammer

src/librustc/session/config.rs

@@ -997,6 +997,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options,
           "enable queries of the dependency graph for regression testing"),
     profile_queries: bool = (false, parse_bool, [UNTRACKED],
           "trace and profile the queries of the incremental compilation framework"),
+    profile_queries_and_keys: bool = (false, parse_bool, [UNTRACKED],
+          "trace and profile the queries and keys of the incremental compilation framework"),
     no_analysis: bool = (false, parse_bool, [UNTRACKED],
           "parse and expand the source, but run no analysis"),
     extra_plugins: Vec<String> = (Vec::new(), parse_list, [TRACKED],

src/librustc/session/mod.rs

@@ -389,7 +389,13 @@ impl Session {
     }
     pub fn verbose(&self) -> bool { self.opts.debugging_opts.verbose }
     pub fn time_passes(&self) -> bool { self.opts.debugging_opts.time_passes }
-    pub fn profile_queries(&self) -> bool { self.opts.debugging_opts.profile_queries }
+    pub fn profile_queries(&self) -> bool {
+        self.opts.debugging_opts.profile_queries ||
+            self.opts.debugging_opts.profile_queries_and_keys
+    }
+    pub fn profile_queries_and_keys(&self) -> bool {
+        self.opts.debugging_opts.profile_queries_and_keys
+    }
     pub fn count_llvm_insns(&self) -> bool {
         self.opts.debugging_opts.count_llvm_insns
     }

src/librustc/ty/maps.rs

@@ -511,19 +511,32 @@ impl<'tcx> QueryDescription for queries::extern_crate<'tcx> {
 impl<'tcx> QueryDescription for queries::lint_levels<'tcx> {
     fn describe(_tcx: TyCtxt, _: CrateNum) -> String {
         format!("computing the lint levels for items in this crate")
+    }
 }
 
 // If enabled, send a message to the profile-queries thread
 macro_rules! profq_msg {
     ($tcx:expr, $msg:expr) => {
         if cfg!(debug_assertions) {
-            if $tcx.sess.opts.debugging_opts.profile_queries {
+            if  $tcx.sess.profile_queries() {
                 profq_msg($msg)
             }
         }
     }
 }
 
+// If enabled, format a key using its debug string, which can be
+// expensive to compute (in terms of time).
+macro_rules! profq_key {
+    ($tcx:expr, $key:expr) => {
+        if cfg!(debug_assertions) {
+            if $tcx.sess.profile_queries_and_keys() {
+                Some(format!("{:?}", $key))
+            } else { None }
+        } else { None }
+    }
+}
+
 macro_rules! define_maps {
     (<$tcx:tt>
      $($(#[$attr:meta])*
@@ -553,7 +566,7 @@ macro_rules! define_maps {
         #[allow(bad_style)]
         #[derive(Clone, Debug, PartialEq, Eq)]
         pub enum QueryMsg {
-            $($name(String)),*
+            $($name(Option<String>)),*
         }
 
         impl<$tcx> Query<$tcx> {
@@ -599,8 +612,11 @@ macro_rules! define_maps {
                        span);
 
                 profq_msg!(tcx,
-                    ProfileQueriesMsg::QueryBegin(span.clone(),
-                                                  QueryMsg::$name(format!("{:?}", key))));
+                    ProfileQueriesMsg::QueryBegin(
+                        span.clone(),
+                        QueryMsg::$name(profq_key!(tcx, key))
+                    )
+                );
 
                 if let Some(&(ref result, dep_node_index)) = tcx.maps.$name.borrow().map.get(&key) {
                     tcx.dep_graph.read_index(dep_node_index);

src/librustc_driver/driver.rs

@@ -107,7 +107,7 @@ pub fn compile_input(sess: &Session,
         sess.abort_if_errors();
     }
 
-    if sess.opts.debugging_opts.profile_queries {
+    if sess.profile_queries() {
         profile::begin();
     }
 
@@ -543,7 +543,7 @@ pub fn phase_1_parse_input<'a>(control: &CompileController,
                                -> PResult<'a, ast::Crate> {
     sess.diagnostic().set_continue_after_error(control.continue_parse_after_error);
 
-    if sess.opts.debugging_opts.profile_queries {
+    if sess.profile_queries() {
         profile::begin();
     }
 
@@ -1130,7 +1130,7 @@ pub fn phase_4_translate_to_llvm<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>,
              "translation",
              move || trans::trans_crate(tcx, analysis, incremental_hashes_map, output_filenames));
 
-    if tcx.sess.opts.debugging_opts.profile_queries {
+    if tcx.sess.profile_queries() {
         profile::dump("profile_queries".to_string())
     }
 

src/librustc_driver/profile/mod.rs

@@ -8,11 +8,11 @@
 // option. This file may not be copied, modified, or distributed
 // except according to those terms.
 
-use std::time::{Instant};
 use rustc::util::common::{ProfQDumpParams, ProfileQueriesMsg, profq_msg, profq_set_chan};
 use std::sync::mpsc::{Receiver};
 use std::io::{Write};
 use rustc::dep_graph::{DepNode};
+use std::time::{Duration, Instant};
 
 pub mod trace;
 
@@ -37,7 +37,7 @@ pub fn dump(path:String) {
         path, ack:tx,
         // FIXME: Add another compiler flag to toggle whether this log
         // is written; false for now
-        dump_profq_msg_log:false,
+        dump_profq_msg_log:true,
     };
     profq_msg(ProfileQueriesMsg::Dump(params));
     let _ = rx.recv().unwrap();
@@ -61,6 +61,12 @@ struct StackFrame {
     pub traces:   Vec<trace::Rec>,
 }
 
+fn total_duration(traces: &Vec<trace::Rec>) -> Duration {
+    let mut sum : Duration = Duration::new(0,0);
+    for t in traces.iter() { sum += t.dur_total; }
+    return sum
+}
+
 // profiling thread; retains state (in local variables) and dump traces, upon request.
 fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
     use self::trace::*;
@@ -161,11 +167,13 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                                             parse_st:ParseState::Clear,
                                             traces:old_frame.traces
                                         };
+                                        let dur_extent = total_duration(&provider_extent);
                                         let trace = Rec {
                                             effect: Effect::QueryBegin(q, CacheCase::Miss),
                                             extent: Box::new(provider_extent),
                                             start: start,
-                                            duration: duration,
+                                            dur_self: duration - dur_extent,
+                                            dur_total: duration,
                                         };
                                         frame.traces.push( trace );
                                     },
@@ -200,11 +208,13 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                                             parse_st:ParseState::Clear,
                                             traces:old_frame.traces
                                         };
+                                        let dur_extent = total_duration(&provider_extent);
                                         let trace = Rec {
                                             effect: Effect::TimeBegin(msg),
                                             extent: Box::new(provider_extent),
                                             start: start,
-                                            duration: duration,
+                                            dur_total: duration,
+                                            dur_self: duration - dur_extent,
                                         };
                                         frame.traces.push( trace );
                                     },
@@ -239,11 +249,13 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                                             parse_st:ParseState::Clear,
                                             traces:old_frame.traces
                                         };
+                                        let dur_extent = total_duration(&provider_extent);
                                         let trace = Rec {
                                             effect: Effect::TaskBegin(key),
                                             extent: Box::new(provider_extent),
                                             start: start,
-                                            duration: duration,
+                                            dur_total: duration,
+                                            dur_self: duration - dur_extent,
                                         };
                                         frame.traces.push( trace );
                                     },
@@ -262,7 +274,8 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                             effect: Effect::QueryBegin(q, CacheCase::Hit),
                             extent: Box::new(vec![]),
                             start: start,
-                            duration: duration,
+                            dur_self: duration,
+                            dur_total: duration,
                         };
                         frame.traces.push( trace );
                         frame.parse_st = ParseState::Clear;

src/librustc_driver/profile/trace.rs

@@ -33,12 +33,14 @@ pub enum CacheCase {
 pub struct Rec {
     pub effect: Effect,
     pub start: Instant,
-    pub duration: Duration,
+    pub dur_self: Duration,
+    pub dur_total: Duration,
     pub extent: Box<Vec<Rec>>,
 }
 pub struct QueryMetric {
     pub count: usize,
-    pub duration: Duration,
+    pub dur_self: Duration,
+    pub dur_total: Duration,
 }
 
 pub fn cons_of_query_msg(q: &trace::Query) -> String {
@@ -108,7 +110,7 @@ fn html_of_fraction(frac: f64) -> (String, String) {
 fn total_duration(traces: &Vec<Rec>) -> Duration {
     let mut sum : Duration = Duration::new(0,0);
     for t in traces.iter() {
-        sum += t.duration;
+        sum += t.dur_total;
     }
     return sum
 }
@@ -124,8 +126,8 @@ fn duration_div(nom: Duration, den: Duration) -> f64 {
 fn write_traces_rec(file: &mut File, traces: &Vec<Rec>, total: Duration, depth: usize) {
     for t in traces {
         let (eff_text, eff_css_classes) = html_of_effect(&t.effect);
-        let (dur_text, dur_css_classes) = html_of_duration(&t.start, &t.duration);
-        let fraction = duration_div(t.duration, total);
+        let (dur_text, dur_css_classes) = html_of_duration(&t.start, &t.dur_total);
+        let fraction = duration_div(t.dur_total, total);
         let percent = fraction * 100.0;
         let (frc_text, frc_css_classes) = html_of_fraction(fraction);
         write!(file, "<div class=\"trace depth-{} extent-{}{} {} {} {}\">\n",
@@ -155,7 +157,8 @@ fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec
                     Some(_qm) => { panic!("TimeBegin with non-unique, repeat message") }
                     None => QueryMetric{
                         count: 1,
-                        duration: t.duration
+                        dur_self: t.dur_self,
+                        dur_total: t.dur_total,
                     }};
                 counts.insert(msg.clone(), qm);
             },
@@ -165,11 +168,13 @@ fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec
                     Some(qm) =>
                         QueryMetric{
                             count: qm.count + 1,
-                            duration: qm.duration + t.duration
+                            dur_self: qm.dur_self + t.dur_self,
+                            dur_total: qm.dur_total + t.dur_total,
                         },
                     None => QueryMetric{
                         count: 1,
-                        duration: t.duration
+                        dur_self: t.dur_self,
+                        dur_total: t.dur_total,
                     }};
                 counts.insert(cons, qm);
             },
@@ -179,11 +184,13 @@ fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec
                     Some(qm) =>
                         QueryMetric{
                             count: qm.count + 1,
-                            duration: qm.duration + t.duration
+                            dur_total: qm.dur_total + t.dur_total,
+                            dur_self: qm.dur_self + t.dur_self
                         },
                     None => QueryMetric{
                         count: 1,
-                        duration: t.duration
+                        dur_total: t.dur_total,
+                        dur_self: t.dur_self,
                     }
                 };
                 counts.insert(qcons, qm);
@@ -199,13 +206,15 @@ pub fn write_counts(count_file: &mut File, counts: &mut HashMap<String,QueryMetr
 
     let mut data = vec![];
     for (ref cons, ref qm) in counts.iter() {
-        data.push((cons.clone(), qm.count.clone(), qm.duration.clone()));
+        data.push((cons.clone(), qm.count.clone(), qm.dur_total.clone(), qm.dur_self.clone()));
     };
-    data.sort_by(|&(_,_,d1),&(_,_,d2)|
-                 if d1 > d2 { Ordering::Less } else { Ordering::Greater } );
-    for (cons, count, duration) in data {
-        write!(count_file, "{},{},{}\n",
-               cons, count, duration_to_secs_str(duration)
+    data.sort_by(|&(_,_,_,self1),&(_,_,_,self2)|
+                 if self1 > self2 { Ordering::Less } else { Ordering::Greater } );
+    for (cons, count, dur_total, dur_self) in data {
+        write!(count_file, "{}, {}, {}, {}\n",
+               cons, count,
+               duration_to_secs_str(dur_total),
+               duration_to_secs_str(dur_self)
         ).unwrap();
     }
 }