Profile queries

src/librustc/session/config.rs

@@ -973,6 +973,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options,
           "dump the dependency graph to $RUST_DEP_GRAPH (default: /tmp/dep_graph.gv)"),
     query_dep_graph: bool = (false, parse_bool, [UNTRACKED],
           "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"),
     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],
@@ -2499,6 +2501,8 @@ mod tests {
         assert_eq!(reference.dep_tracking_hash(), opts.dep_tracking_hash());
         opts.debugging_opts.query_dep_graph = true;
         assert_eq!(reference.dep_tracking_hash(), opts.dep_tracking_hash());
+        opts.debugging_opts.profile_queries = true;
+        assert_eq!(reference.dep_tracking_hash(), opts.dep_tracking_hash());
         opts.debugging_opts.no_analysis = true;
         assert_eq!(reference.dep_tracking_hash(), opts.dep_tracking_hash());
         opts.debugging_opts.unstable_options = true;

src/librustc/session/mod.rs

@@ -352,6 +352,7 @@ 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 count_llvm_insns(&self) -> bool {
         self.opts.debugging_opts.count_llvm_insns
     }

src/librustc/ty/context.rs

@@ -40,6 +40,7 @@ use ty::layout::{Layout, TargetDataLayout};
 use ty::inhabitedness::DefIdForest;
 use ty::maps;
 use ty::steal::Steal;
+
 use util::nodemap::{NodeMap, NodeSet, DefIdMap, DefIdSet};
 use util::nodemap::{FxHashMap, FxHashSet};
 use rustc_data_structures::accumulate_vec::AccumulateVec;
@@ -54,6 +55,7 @@ use std::mem;
 use std::ops::Deref;
 use std::iter;
 use std::rc::Rc;
+
 use syntax::abi;
 use syntax::ast::{self, Name, NodeId};
 use syntax::attr;

src/librustc/ty/maps.rs

@@ -22,6 +22,8 @@ use ty::{self, CrateInherentImpls, Ty, TyCtxt};
 use ty::item_path;
 use ty::steal::Steal;
 use ty::subst::Substs;
+
+use util::common::{profq_msg,ProfileQueriesMsg};
 use util::nodemap::{DefIdSet, NodeSet};
 
 use rustc_data_structures::indexed_vec::IndexVec;
@@ -391,6 +393,15 @@ impl<'tcx> QueryDescription for queries::is_mir_available<'tcx> {
     }
 }
 
+// If enabled, send a message to the profile-queries thread
+macro_rules! profq_msg {
+    ($tcx:expr, $msg:expr) => {
+        if $tcx.sess.opts.debugging_opts.profile_queries {
+            profq_msg($msg)
+        }
+    }
+}
+
 macro_rules! define_maps {
     (<$tcx:tt>
      $($(#[$attr:meta])*
@@ -418,6 +429,12 @@ macro_rules! define_maps {
             $($(#[$attr])* $name($K)),*
         }
 
+        #[allow(bad_style)]
+        #[derive(Clone, Debug, PartialEq, Eq)]
+        pub enum QueryMsg {
+            $($name(String)),*
+        }
+
         impl<$tcx> Query<$tcx> {
             pub fn describe(&self, tcx: TyCtxt) -> String {
                 match *self {
@@ -459,9 +476,16 @@ macro_rules! define_maps {
                        key,
                        span);
 
+                profq_msg!(tcx, 
+                    ProfileQueriesMsg::QueryBegin(span.clone(),
+                                                  QueryMsg::$name(format!("{:?}", key))));
+
                 if let Some(result) = tcx.maps.$name.borrow().get(&key) {
+                    profq_msg!(tcx, ProfileQueriesMsg::CacheHit);
                     return Ok(f(result));
                 }
+                // else, we are going to run the provider:
+                profq_msg!(tcx, ProfileQueriesMsg::ProviderBegin);
 
                 // FIXME(eddyb) Get more valid Span's on queries.
                 // def_span guard is necesary to prevent a recursive loop,
@@ -476,6 +500,7 @@ macro_rules! define_maps {
                     let provider = tcx.maps.providers[key.map_crate()].$name;
                     provider(tcx.global_tcx(), key)
                 })?;
+                profq_msg!(tcx, ProfileQueriesMsg::ProviderEnd);
 
                 Ok(f(tcx.maps.$name.borrow_mut().entry(key).or_insert(result)))
             }

src/librustc/util/common.rs

@@ -19,6 +19,10 @@ use std::iter::repeat;
 use std::path::Path;
 use std::time::{Duration, Instant};
 
+use std::sync::mpsc::{Sender};
+use syntax_pos::{Span};
+use ty::maps::{QueryMsg};
+
 // The name of the associated type for `Fn` return types
 pub const FN_OUTPUT_NAME: &'static str = "Output";
 
@@ -29,6 +33,52 @@ pub struct ErrorReported;
 
 thread_local!(static TIME_DEPTH: Cell<usize> = Cell::new(0));
 
+/// Initialized for -Z profile-queries
+thread_local!(static PROFQ_CHAN: RefCell<Option<Sender<ProfileQueriesMsg>>> = RefCell::new(None));
+
+/// A sequence of these messages induce a trace of query-based incremental compilation.
+/// FIXME(matthewhammer): Determine whether we should include cycle detection here or not.
+#[derive(Clone,Debug)]
+pub enum ProfileQueriesMsg {
+    /// begin a new query
+    QueryBegin(Span,QueryMsg),
+    /// query is satisfied by using an already-known value for the given key
+    CacheHit,
+    /// query requires running a provider; providers may nest, permitting queries to nest.
+    ProviderBegin,
+    /// query is satisfied by a provider terminating with a value
+    ProviderEnd,
+    /// dump a record of the queries to the given path
+    Dump(String),
+    /// stop the profilequeriesmsg service
+    Halt
+}
+
+// If enabled, send a message to the profile-queries thread
+pub fn profq_msg(msg: ProfileQueriesMsg) {
+    PROFQ_CHAN.with(|sender|{
+        if let Some(s) = sender.borrow().as_ref() {
+            s.send(msg).unwrap()
+        } else {
+            panic!("no channel on which to send profq_msg: {:?}", msg)
+        }                                  
+    })
+}
+
+pub fn profq_set_chan(s: Sender<ProfileQueriesMsg>) -> bool {
+    PROFQ_CHAN.with(|chan|{                    
+        let is_none = 
+            if let None = chan.borrow().as_ref() {
+                true
+            } else { false }
+        ;
+        if is_none {
+            *chan.borrow_mut() = Some(s);
+            true
+        } else { false }
+    })
+}
+
 /// Read the current depth of `time()` calls. This is used to
 /// encourage indentation across threads.
 pub fn time_depth() -> usize {

src/librustc_driver/driver.rs

@@ -22,7 +22,7 @@ use rustc::middle::{self, dependency_format, stability, reachable};
 use rustc::middle::privacy::AccessLevels;
 use rustc::mir::transform::{MIR_CONST, MIR_VALIDATED, MIR_OPTIMIZED, Passes};
 use rustc::ty::{self, TyCtxt, Resolutions, GlobalArenas};
-use rustc::util::common::time;
+use rustc::util::common::{time,ProfileQueriesMsg,profq_msg};
 use rustc::util::nodemap::NodeSet;
 use rustc::util::fs::rename_or_copy_remove;
 use rustc_borrowck as borrowck;
@@ -49,6 +49,7 @@ use std::io::{self, Write};
 use std::iter;
 use std::path::{Path, PathBuf};
 use std::rc::Rc;
+
 use syntax::{ast, diagnostics, visit};
 use syntax::attr;
 use syntax::ext::base::ExtCtxt;
@@ -61,6 +62,8 @@ use arena::DroplessArena;
 
 use derive_registrar;
 
+use profile;
+
 pub fn compile_input(sess: &Session,
                      cstore: &CStore,
                      input: &Input,
@@ -82,6 +85,10 @@ pub fn compile_input(sess: &Session,
         }}
     }
 
+    if sess.opts.debugging_opts.profile_queries {
+        profile::begin();
+    }
+
     // We need nested scopes here, because the intermediate results can keep
     // large chunks of memory alive and we want to free them as soon as
     // possible to keep the peak memory usage low
@@ -497,6 +504,10 @@ pub fn phase_1_parse_input<'a>(sess: &'a Session, input: &Input) -> PResult<'a,
     let continue_after_error = sess.opts.debugging_opts.continue_parse_after_error;
     sess.diagnostic().set_continue_after_error(continue_after_error);
 
+    if sess.opts.debugging_opts.profile_queries {
+        profile::begin();
+    }
+
     let krate = time(sess.time_passes(), "parsing", || {
         match *input {
             Input::File(ref file) => {
@@ -952,6 +963,7 @@ pub fn phase_3_run_analysis_passes<'tcx, F, R>(sess: &'tcx Session,
                              index,
                              name,
                              |tcx| {
+
         let incremental_hashes_map =
             time(time_passes,
                  "compute_incremental_hashes_map",
@@ -1062,6 +1074,11 @@ pub fn phase_4_translate_to_llvm<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>,
                                               &incremental_hashes_map,
                                               &translation.metadata.hashes,
                                               translation.link.crate_hash));
+
+    if tcx.sess.opts.debugging_opts.profile_queries {
+        profq_msg(ProfileQueriesMsg::Dump("profile_queries".to_string()))
+    }
+
     translation
 }
 

src/librustc_driver/lib.rs

@@ -107,6 +107,7 @@ use syntax_pos::{DUMMY_SP, MultiSpan};
 pub mod test;
 
 pub mod driver;
+pub mod profile;
 pub mod pretty;
 pub mod target_features;
 mod derive_registrar;

src/librustc_driver/profile/mod.rs

@@ -0,0 +1,144 @@
+use rustc::util::common::{ProfileQueriesMsg,profq_set_chan};
+use std::sync::mpsc::{Receiver};
+use std::io::{Write};
+
+pub mod trace;
+
+pub fn begin() {
+    use std::thread;
+    use std::sync::mpsc::{channel};
+    let (tx, rx) = channel();
+    if profq_set_chan(tx) {
+        thread::spawn(move||profile_queries_thread(rx));
+    }
+}
+
+fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
+    use self::trace::*;
+    use std::fs::File;
+    use std::time::{Instant};
+
+    let mut queries  : Vec<ProfileQueriesMsg> = vec![];
+    let mut frame    : StackFrame = StackFrame{ parse_st:ParseState::NoQuery, traces:vec![] };
+    let mut stack    : Vec<StackFrame> = vec![];
+    loop {
+        let msg = r.recv();
+        if let Err(_recv_err) = msg {
+            // FIXME: Perhaps do something smarter than simply quitting?
+            break
+        };
+        let msg = msg.unwrap();
+        debug!("profile_queries_thread: {:?}", msg);
+
+        // Meta-level versus _actual_ queries messages
+        match msg {
+            ProfileQueriesMsg::Halt => return,
+            ProfileQueriesMsg::Dump(path) => {
+                assert!(stack.len() == 0);
+                assert!(frame.parse_st == trace::ParseState::NoQuery);
+                { // write HTML file
+                    let html_path = format!("{}.html", path);
+                    let mut html_file = File::create(&html_path).unwrap();
+
+                    let counts_path = format!("{}.counts.txt", path);
+                    let mut counts_file = File::create(&counts_path).unwrap();
+
+                    write!(html_file, "<html>\n").unwrap();
+                    write!(html_file,
+                           "<head>\n<link rel=\"stylesheet\" type=\"text/css\" href=\"{}\">\n",
+                           "profile_queries.css").unwrap();
+                    write!(html_file, "<style>\n").unwrap();
+                    trace::write_style(&mut html_file);
+                    write!(html_file, "</style>\n").unwrap();
+                    write!(html_file, "</head>\n").unwrap();
+                    write!(html_file, "<body>\n").unwrap();
+                    trace::write_traces(&mut html_file, &mut counts_file, &frame.traces);
+                    write!(html_file, "</body>\n</html>\n").unwrap();
+                }
+                continue
+            }
+            // Actual query message:
+            msg => {
+                queries.push(msg.clone());
+                match (frame.parse_st.clone(), msg) {
+                    (_,ProfileQueriesMsg::Halt) => unreachable!(),
+                    (_,ProfileQueriesMsg::Dump(_)) => unreachable!(),
+
+                    // Parse State: NoQuery
+                    (ParseState::NoQuery,
+                     ProfileQueriesMsg::QueryBegin(span,querymsg)) => {
+                        let start = Instant::now();
+                        frame.parse_st = ParseState::HaveQuery
+                            (Query{span:span, msg:querymsg}, start)
+                    },
+                    (ParseState::NoQuery,
+                     ProfileQueriesMsg::CacheHit) => {
+                        panic!("parse error: unexpected CacheHit; expected QueryBegin")
+                    },
+                    (ParseState::NoQuery,
+                     ProfileQueriesMsg::ProviderBegin) => {
+                        panic!("parse error: expected QueryBegin before beginning a provider")
+                    },
+                    (ParseState::NoQuery,
+                     ProfileQueriesMsg::ProviderEnd) => {
+                        let provider_extent = frame.traces;
+                        match stack.pop() {
+                            None =>
+                                panic!("parse error: expected a stack frame; found an empty stack"),
+                            Some(old_frame) => {
+                                match old_frame.parse_st {
+                                    ParseState::NoQuery =>
+                                        panic!("parse error: expected a stack frame for a query"),
+                                    ParseState::HaveQuery(q,start) => {
+                                        let duration = start.elapsed();
+                                        frame = StackFrame{
+                                            parse_st:ParseState::NoQuery,
+                                            traces:old_frame.traces
+                                        };
+                                        let trace = Rec {
+                                            effect: Effect::QueryBegin(q, CacheCase::Miss),
+                                            extent: Box::new(provider_extent),
+                                            start: start,
+                                            duration: duration,
+                                        };
+                                        frame.traces.push( trace );
+                                    }
+                                }
+                            }
+                        }
+                    }
+
+                    // Parse State: HaveQuery
+                    (ParseState::HaveQuery(q,start),
+                     ProfileQueriesMsg::CacheHit) => {
+                        let duration = start.elapsed();
+                        let trace : Rec = Rec{
+                            effect: Effect::QueryBegin(q, CacheCase::Hit),
+                            extent: Box::new(vec![]),
+                            start: start,
+                            duration: duration,
+                        };
+                        frame.traces.push( trace );
+                        frame.parse_st = ParseState::NoQuery;
+                    },
+                    (ParseState::HaveQuery(_,_),
+                     ProfileQueriesMsg::ProviderBegin) => {
+                        stack.push(frame);
+                        frame = StackFrame{parse_st:ParseState::NoQuery, traces:vec![]};
+                    },
+                    (ParseState::HaveQuery(q,_),
+                     ProfileQueriesMsg::ProviderEnd) => {
+                        panic!("parse error: unexpected ProviderEnd;
+expected something else to follow BeginQuery for {:?}", q)
+                    },
+                    (ParseState::HaveQuery(q1,_),
+                     ProfileQueriesMsg::QueryBegin(span2,querymsg2)) => {
+                        panic!("parse error: unexpected QueryBegin;
+earlier query is unfinished: {:?} and now {:?}",
+                               q1, Query{span:span2, msg:querymsg2})
+                    },
+                }
+            }
+        }
+    }
+}