Auto merge of #43345 - matthewhammer:master, r=nikomatsakis

Profile queries

This PR implements the "profile queries" debugging feature described here:
https://github.com/rust-lang-nursery/rust-forge/blob/master/profile-queries.md

In particular, it implements the debugging flag `-Z profile-queries`

FYI: This PR is my second attempt at pushing these changes.  My original PR required a rebase; I have now done that rebase manually, after messing up with git's "interactive" rebase support.  The original (now closed/cancelled) PR is this one: https://github.com/rust-lang/rust/issues/43156

r? @nikomatsakis

src/librustc/dep_graph/graph.rs

@@ -12,6 +12,7 @@ use rustc_data_structures::fx::FxHashMap;
 use session::config::OutputType;
 use std::cell::{Ref, RefCell};
 use std::rc::Rc;
+use util::common::{ProfileQueriesMsg, profq_msg};
 
 use super::dep_node::{DepNode, DepKind, WorkProductId};
 use super::query::DepGraphQuery;
@@ -118,7 +119,13 @@ impl DepGraph {
     {
         if let Some(ref data) = self.data {
             data.edges.borrow_mut().push_task(key);
+            if cfg!(debug_assertions) {
+                profq_msg(ProfileQueriesMsg::TaskBegin(key.clone()))
+            };
             let result = task(cx, arg);
+            if cfg!(debug_assertions) {
+                profq_msg(ProfileQueriesMsg::TaskEnd)
+            };
             let dep_node_index = data.edges.borrow_mut().pop_task(key);
             (result, dep_node_index)
         } else {

src/librustc/session/config.rs

@@ -995,6 +995,10 @@ 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"),
+    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,6 +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 ||
+            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

@@ -28,6 +28,7 @@ use ty::steal::Steal;
 use ty::subst::Substs;
 use ty::fast_reject::SimplifiedType;
 use util::nodemap::{DefIdSet, NodeSet};
+use util::common::{profq_msg, ProfileQueriesMsg};
 
 use rustc_data_structures::indexed_vec::IndexVec;
 use rustc_data_structures::fx::FxHashMap;
@@ -513,6 +514,29 @@ impl<'tcx> QueryDescription for queries::lint_levels<'tcx> {
     }
 }
 
+// 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.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])*
@@ -539,6 +563,12 @@ macro_rules! define_maps {
             $($(#[$attr])* $name($K)),*
         }
 
+        #[allow(bad_style)]
+        #[derive(Clone, Debug, PartialEq, Eq)]
+        pub enum QueryMsg {
+            $($name(Option<String>)),*
+        }
+
         impl<$tcx> Query<$tcx> {
             pub fn describe(&self, tcx: TyCtxt) -> String {
                 match *self {
@@ -581,10 +611,20 @@ macro_rules! define_maps {
                        key,
                        span);
 
+                profq_msg!(tcx,
+                    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);
+                    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 necessary to prevent a recursive loop,
@@ -612,6 +652,7 @@ macro_rules! define_maps {
                         tcx.dep_graph.with_task(dep_node, tcx, key, run_provider)
                     }
                 })?;
+                profq_msg!(tcx, ProfileQueriesMsg::ProviderEnd);
 
                 tcx.dep_graph.read_index(dep_node_index);
 

src/librustc/util/common.rs

@@ -19,6 +19,11 @@ 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};
+use dep_graph::{DepNode};
+
 // The name of the associated type for `Fn` return types
 pub const FN_OUTPUT_NAME: &'static str = "Output";
 
@@ -29,6 +34,72 @@ 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));
+
+/// Parameters to the `Dump` variant of type `ProfileQueriesMsg`.
+#[derive(Clone,Debug)]
+pub struct ProfQDumpParams {
+    /// A base path for the files we will dump
+    pub path:String,
+    /// To ensure that the compiler waits for us to finish our dumps
+    pub ack:Sender<()>,
+    /// toggle dumping a log file with every `ProfileQueriesMsg`
+    pub dump_profq_msg_log:bool,
+}
+
+/// 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 timed pass
+    TimeBegin(String),
+    /// end a timed pass
+    TimeEnd,
+    /// begin a task (see dep_graph::graph::with_task)
+    TaskBegin(DepNode),
+    /// end a task
+    TaskEnd,
+    /// 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(ProfQDumpParams),
+    /// halt the profiling/monitoring background thread
+    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 {
+            // Do nothing.
+            //
+            // FIXME(matthewhammer): Multi-threaded translation phase triggers the panic below.
+            // From backtrace: rustc_trans::back::write::spawn_work::{{closure}}.
+            //
+            // panic!("no channel on which to send profq_msg: {:?}", msg)
+        }
+    })
+}
+
+/// Set channel for profile queries channel
+pub fn profq_set_chan(s: Sender<ProfileQueriesMsg>) -> bool {
+    PROFQ_CHAN.with(|chan|{
+        if chan.borrow().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 {
@@ -53,9 +124,15 @@ pub fn time<T, F>(do_it: bool, what: &str, f: F) -> T where
         r
     });
 
+    if cfg!(debug_assertions) {
+        profq_msg(ProfileQueriesMsg::TimeBegin(what.to_string()))
+    };
     let start = Instant::now();
     let rv = f();
     let dur = start.elapsed();
+    if cfg!(debug_assertions) {
+        profq_msg(ProfileQueriesMsg::TimeEnd)
+    };
 
     print_time_passes_entry_internal(what, dur);
 

src/librustc_driver/driver.rs

@@ -64,6 +64,8 @@ use arena::DroplessArena;
 
 use derive_registrar;
 
+use profile;
+
 pub fn compile_input(sess: &Session,
                      cstore: &CStore,
                      input: &Input,
@@ -105,6 +107,10 @@ pub fn compile_input(sess: &Session,
         sess.abort_if_errors();
     }
 
+    if sess.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
@@ -537,6 +543,10 @@ 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.profile_queries() {
+        profile::begin();
+    }
+
     let krate = time(sess.time_passes(), "parsing", || {
         match *input {
             Input::File(ref file) => {
@@ -1120,6 +1130,10 @@ 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.profile_queries() {
+        profile::dump("profile_queries".to_string())
+    }
+
     translation
 }
 

src/librustc_driver/lib.rs

@@ -104,6 +104,7 @@ use syntax_pos::{DUMMY_SP, MultiSpan};
 #[cfg(test)]
 mod test;
 
+pub mod profile;
 pub mod driver;
 pub mod pretty;
 pub mod target_features;

src/librustc_driver/profile/mod.rs

@@ -0,0 +1,316 @@
+// Copyright 2012-2015 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 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;
+
+/// begin a profile thread, if not already running
+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));
+    }
+}
+
+/// dump files with profiling information to the given base path, and
+/// wait for this dump to complete.
+///
+/// wraps the RPC (send/recv channel logic) of requesting a dump.
+pub fn dump(path:String) {
+    use std::sync::mpsc::{channel};
+    let (tx, rx) = channel();
+    let params = ProfQDumpParams{
+        path, ack:tx,
+        // FIXME: Add another compiler flag to toggle whether this log
+        // is written; false for now
+        dump_profq_msg_log:true,
+    };
+    profq_msg(ProfileQueriesMsg::Dump(params));
+    let _ = rx.recv().unwrap();
+}
+
+// State for parsing recursive trace structure in separate thread, via messages
+#[derive(Clone, Eq, PartialEq)]
+enum ParseState {
+    // No (local) parse state; may be parsing a tree, focused on a
+    // sub-tree that could be anything.
+    Clear,
+    // Have Query information from the last message
+    HaveQuery(trace::Query, Instant),
+    // Have "time-begin" information from the last message (doit flag, and message)
+    HaveTimeBegin(String, Instant),
+    // Have "task-begin" information from the last message
+    HaveTaskBegin(DepNode, Instant),
+}
+struct StackFrame {
+    pub parse_st: ParseState,
+    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::*;
+    use std::fs::File;
+    use std::time::{Instant};
+
+    let mut profq_msgs : Vec<ProfileQueriesMsg> = vec![];
+    let mut frame : StackFrame = StackFrame{ parse_st:ParseState::Clear, 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(params) => {
+                assert!(stack.len() == 0);
+                assert!(frame.parse_st == ParseState::Clear);
+                {
+                    // write log of all messages
+                    if params.dump_profq_msg_log {
+                        let mut log_file =
+                            File::create(format!("{}.log.txt", params.path)).unwrap();
+                        for m in profq_msgs.iter() {
+                            writeln!(&mut log_file, "{:?}", m).unwrap()
+                        };
+                    }
+
+                    // write HTML file, and counts file
+                    let html_path = format!("{}.html", params.path);
+                    let mut html_file = File::create(&html_path).unwrap();
+
+                    let counts_path = format!("{}.counts.txt", params.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();
+
+                    let ack_path = format!("{}.ack", params.path);
+                    let ack_file = File::create(&ack_path).unwrap();
+                    drop(ack_file);
+
+                    // Tell main thread that we are done, e.g., so it can exit
+                    params.ack.send(()).unwrap();
+                }
+                continue
+            }
+            // Actual query message:
+            msg => {
+                // Record msg in our log
+                profq_msgs.push(msg.clone());
+                // Respond to the message, knowing that we've already handled Halt and Dump, above.
+                match (frame.parse_st.clone(), msg) {
+                    (_,ProfileQueriesMsg::Halt) => unreachable!(),
+                    (_,ProfileQueriesMsg::Dump(_)) => unreachable!(),
+
+                    // Parse State: Clear
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::QueryBegin(span,querymsg)) => {
+                        let start = Instant::now();
+                        frame.parse_st = ParseState::HaveQuery
+                            (Query{span:span, msg:querymsg}, start)
+                    },
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::CacheHit) => {
+                        panic!("parse error: unexpected CacheHit; expected QueryBegin")
+                    },
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::ProviderBegin) => {
+                        panic!("parse error: expected QueryBegin before beginning a provider")
+                    },
+                    (ParseState::Clear,
+                     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::HaveQuery(q, start) => {
+                                        let duration = start.elapsed();
+                                        frame = StackFrame{
+                                            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,
+                                            dur_self: duration - dur_extent,
+                                            dur_total: duration,
+                                        };
+                                        frame.traces.push( trace );
+                                    },
+                                    _ => panic!("internal parse error: malformed parse stack")
+                                }
+                            }
+                        }
+                    },
+
+
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::TimeBegin(msg)) => {
+                        let start = Instant::now();
+                        frame.parse_st = ParseState::HaveTimeBegin(msg, start);
+                        stack.push(frame);
+                        frame = StackFrame{parse_st:ParseState::Clear, traces:vec![]};
+                    },
+                    (_, ProfileQueriesMsg::TimeBegin(_)) =>
+                        panic!("parse error; did not expect time begin here"),
+
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::TimeEnd) => {
+                        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::HaveTimeBegin(msg, start) => {
+                                        let duration = start.elapsed();
+                                        frame = StackFrame{
+                                            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,
+                                            dur_total: duration,
+                                            dur_self: duration - dur_extent,
+                                        };
+                                        frame.traces.push( trace );
+                                    },
+                                    _ => panic!("internal parse error: malformed parse stack")
+                                }
+                            }
+                        }
+                    },
+                    (_, ProfileQueriesMsg::TimeEnd) => { panic!("parse error") }
+
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::TaskBegin(key)) => {
+                        let start = Instant::now();
+                        frame.parse_st = ParseState::HaveTaskBegin(key, start);
+                        stack.push(frame);
+                        frame = StackFrame{parse_st:ParseState::Clear, traces:vec![]};
+                    },
+                    (_, ProfileQueriesMsg::TaskBegin(_)) =>
+                        panic!("parse error; did not expect time begin here"),
+
+                    (ParseState::Clear,
+                     ProfileQueriesMsg::TaskEnd) => {
+                        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::HaveTaskBegin(key, start) => {
+                                        let duration = start.elapsed();
+                                        frame = StackFrame{
+                                            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,
+                                            dur_total: duration,
+                                            dur_self: duration - dur_extent,
+                                        };
+                                        frame.traces.push( trace );
+                                    },
+                                    _ => panic!("internal parse error: malformed parse stack")
+                                }
+                            }
+                        }
+                    },
+                    (_, ProfileQueriesMsg::TaskEnd) => { panic!("parse error") }
+
+                    // 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,
+                            dur_self: duration,
+                            dur_total: duration,
+                        };
+                        frame.traces.push( trace );
+                        frame.parse_st = ParseState::Clear;
+                    },
+                    (ParseState::HaveQuery(_,_),
+                     ProfileQueriesMsg::ProviderBegin) => {
+                        stack.push(frame);
+                        frame = StackFrame{parse_st:ParseState::Clear, traces:vec![]};
+                    },
+
+                    //
+                    //
+                    // Parse errors:
+
+                    (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})
+                    },
+
+                    (ParseState::HaveTimeBegin(_, _), _) => {
+                        unreachable!()
+                    },
+                    (ParseState::HaveTaskBegin(_, _), _) => {
+                        unreachable!()
+                    },
+                }
+
+            }
+        }
+    }
+}

src/librustc_driver/profile/trace.rs

@@ -0,0 +1,315 @@
+// Copyright 2012-2017 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 super::*;
+use syntax_pos::Span;
+use rustc::ty::maps::QueryMsg;
+use std::fs::File;
+use std::time::{Duration, Instant};
+use std::collections::hash_map::HashMap;
+use rustc::dep_graph::{DepNode};
+
+#[derive(Debug, Clone, Eq, PartialEq)]
+pub struct Query {
+    pub span: Span,
+    pub msg: QueryMsg,
+}
+pub enum Effect {
+    QueryBegin(Query, CacheCase),
+    TimeBegin(String),
+    TaskBegin(DepNode),
+}
+pub enum CacheCase {
+    Hit, Miss
+}
+/// Recursive trace structure
+pub struct Rec {
+    pub effect: Effect,
+    pub start: Instant,
+    pub dur_self: Duration,
+    pub dur_total: Duration,
+    pub extent: Box<Vec<Rec>>,
+}
+pub struct QueryMetric {
+    pub count: usize,
+    pub dur_self: Duration,
+    pub dur_total: Duration,
+}
+
+pub fn cons_of_query_msg(q: &trace::Query) -> String {
+    let s = format!("{:?}", q.msg);
+    let cons: Vec<&str> = s.split(|d| d == '(' || d == '{').collect();
+    assert!(cons.len() > 0 && cons[0] != "");
+    cons[0].to_string()
+}
+
+pub fn cons_of_key(k: &DepNode) -> String {
+    let s = format!("{:?}", k);
+    let cons: Vec<&str> = s.split(|d| d == '(' || d == '{').collect();
+    assert!(cons.len() > 0 && cons[0] != "");
+    cons[0].to_string()
+}
+
+// First return value is text; second return value is a CSS class
+pub fn html_of_effect(eff: &Effect) -> (String, String) {
+    match *eff {
+        Effect::TimeBegin(ref msg) => {
+            (msg.clone(),
+             format!("time-begin"))
+        },
+        Effect::TaskBegin(ref key) => {
+            let cons = cons_of_key(key);
+            (cons.clone(), format!("{} task-begin", cons))
+        },
+        Effect::QueryBegin(ref qmsg, ref cc) => {
+            let cons = cons_of_query_msg(qmsg);
+            (cons.clone(),
+             format!("{} {}",
+                     cons,
+                     match *cc {
+                         CacheCase::Hit => "hit",
+                         CacheCase::Miss => "miss",
+                     }))
+        }
+    }
+}
+
+// First return value is text; second return value is a CSS class
+fn html_of_duration(_start: &Instant, dur: &Duration) -> (String, String) {
+    use rustc::util::common::duration_to_secs_str;
+    (duration_to_secs_str(dur.clone()),
+     "".to_string()
+    )
+}
+
+fn html_of_fraction(frac: f64) -> (String, String) {
+    let css = {
+        if       frac > 0.50  { format!("frac-50") }
+        else if  frac > 0.40  { format!("frac-40") }
+        else if  frac > 0.30  { format!("frac-30") }
+        else if  frac > 0.20  { format!("frac-20") }
+        else if  frac > 0.10  { format!("frac-10") }
+        else if  frac > 0.05  { format!("frac-05") }
+        else if  frac > 0.02  { format!("frac-02") }
+        else if  frac > 0.01  { format!("frac-01") }
+        else if  frac > 0.001 { format!("frac-001") }
+        else                  { format!("frac-0") }
+    };
+    let percent = frac * 100.0;
+    if percent > 0.1 { (format!("{:.1}%", percent), css) }
+    else { (format!("< 0.1%", ), css) }
+}
+
+fn total_duration(traces: &Vec<Rec>) -> Duration {
+    let mut sum : Duration = Duration::new(0,0);
+    for t in traces.iter() {
+        sum += t.dur_total;
+    }
+    return sum
+}
+
+fn duration_div(nom: Duration, den: Duration) -> f64 {
+    fn to_nanos(d: Duration) -> u64 {
+        d.as_secs() * 1_000_000_000 + d.subsec_nanos() as u64
+    }
+
+    to_nanos(nom) as f64 / to_nanos(den) as 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.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",
+               depth,
+               t.extent.len(),
+               /* Heuristic for 'important' CSS class: */
+               if t.extent.len() > 5 || percent >= 1.0 {
+                   " important" }
+               else { "" },
+               eff_css_classes,
+               dur_css_classes,
+               frc_css_classes,
+        ).unwrap();
+        write!(file, "<div class=\"eff\">{}</div>\n", eff_text).unwrap();
+        write!(file, "<div class=\"dur\">{}</div>\n", dur_text).unwrap();
+        write!(file, "<div class=\"frc\">{}</div>\n", frc_text).unwrap();
+        write_traces_rec(file, &t.extent, total, depth + 1);
+        write!(file, "</div>\n").unwrap();
+    }
+}
+
+fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec>) {
+    for t in traces.iter() {
+        match t.effect {
+            Effect::TimeBegin(ref msg) => {
+                let qm = match counts.get(msg) {
+                    Some(_qm) => { panic!("TimeBegin with non-unique, repeat message") }
+                    None => QueryMetric{
+                        count: 1,
+                        dur_self: t.dur_self,
+                        dur_total: t.dur_total,
+                    }};
+                counts.insert(msg.clone(), qm);
+            },
+            Effect::TaskBegin(ref key) => {
+                let cons = cons_of_key(key);
+                let qm = match counts.get(&cons) {
+                    Some(qm) =>
+                        QueryMetric{
+                            count: qm.count + 1,
+                            dur_self: qm.dur_self + t.dur_self,
+                            dur_total: qm.dur_total + t.dur_total,
+                        },
+                    None => QueryMetric{
+                        count: 1,
+                        dur_self: t.dur_self,
+                        dur_total: t.dur_total,
+                    }};
+                counts.insert(cons, qm);
+            },
+            Effect::QueryBegin(ref qmsg, ref _cc) => {
+                let qcons = cons_of_query_msg(qmsg);
+                let qm = match counts.get(&qcons) {
+                    Some(qm) =>
+                        QueryMetric{
+                            count: qm.count + 1,
+                            dur_total: qm.dur_total + t.dur_total,
+                            dur_self: qm.dur_self + t.dur_self
+                        },
+                    None => QueryMetric{
+                        count: 1,
+                        dur_total: t.dur_total,
+                        dur_self: t.dur_self,
+                    }
+                };
+                counts.insert(qcons, qm);
+            }
+        }
+        compute_counts_rec(counts, &t.extent)
+    }
+}
+
+pub fn write_counts(count_file: &mut File, counts: &mut HashMap<String,QueryMetric>) {
+    use rustc::util::common::duration_to_secs_str;
+    use std::cmp::Ordering;
+
+    let mut data = vec![];
+    for (ref cons, ref qm) in counts.iter() {
+        data.push((cons.clone(), qm.count.clone(), qm.dur_total.clone(), qm.dur_self.clone()));
+    };
+    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();
+    }
+}
+
+pub fn write_traces(html_file: &mut File, counts_file: &mut File, traces: &Vec<Rec>) {
+    let mut counts : HashMap<String,QueryMetric> = HashMap::new();
+    compute_counts_rec(&mut counts, traces);
+    write_counts(counts_file, &mut counts);
+
+    let total : Duration = total_duration(traces);
+    write_traces_rec(html_file, traces, total, 0)
+}
+
+pub fn write_style(html_file: &mut File) {
+    write!(html_file,"{}", "
+body {
+    font-family: sans-serif;
+    background: black;
+}
+.trace {
+    color: black;
+    display: inline-block;
+    border-style: solid;
+    border-color: red;
+    border-width: 1px;
+    border-radius: 5px;
+    padding: 0px;
+    margin: 1px;
+    font-size: 0px;
+}
+.task-begin {
+    border-width: 1px;
+    color: white;
+    border-color: #ff8;
+    font-size: 0px;
+}
+.miss {
+    border-color: red;
+    border-width: 1px;
+}
+.extent-0 {
+    padding: 2px;
+}
+.time-begin {
+    border-width: 4px;
+    font-size: 12px;
+    color: white;
+    border-color: #afa;
+}
+.important {
+    border-width: 3px;
+    font-size: 12px;
+    color: white;
+    border-color: #f77;
+}
+.hit {
+    padding: 0px;
+    border-color: blue;
+    border-width: 3px;
+}
+.eff {
+  color: #fff;
+  display: inline-block;
+}
+.frc {
+  color: #7f7;
+  display: inline-block;
+}
+.dur {
+  display: none
+}
+.frac-50 {
+  padding: 10px;
+  border-width: 10px;
+  font-size: 32px;
+}
+.frac-40 {
+  padding: 8px;
+  border-width: 8px;
+  font-size: 24px;
+}
+.frac-30 {
+  padding: 6px;
+  border-width: 6px;
+  font-size: 18px;
+}
+.frac-20 {
+  padding: 4px;
+  border-width: 6px;
+  font-size: 16px;
+}
+.frac-10 {
+  padding: 2px;
+  border-width: 6px;
+  font-size: 14px;
+}
+").unwrap();
+}