-Z profile-queries includes dep_graph.with_task uses in output

Author: Matthew Hammer

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/util/common.rs

@@ -22,6 +22,7 @@ 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";
@@ -53,8 +54,12 @@ pub struct ProfQDumpParams {
 pub enum ProfileQueriesMsg {
     /// begin a timed pass
     TimeBegin(String),
-    // end a timed pass
+    /// 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

src/librustc_driver/profile/mod.rs

@@ -12,6 +12,7 @@ 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};
 
 pub mod trace;
 
@@ -52,6 +53,8 @@ enum ParseState {
     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,
@@ -170,7 +173,7 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                                 }
                             }
                         }
-                   },
+                    },
 
 
                     (ParseState::Clear,
@@ -212,19 +215,44 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                     },
                     (_, 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"),
 
-                    // Parse State: HaveTimeBegin -- for timing old
-                    // passes in driver (outside of query model, but
-                    // still in use)
-                    (ParseState::HaveTimeBegin(_, _),
-                     ProfileQueriesMsg::ProviderBegin) => {
+                    (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 trace = Rec {
+                                            effect: Effect::TaskBegin(key),
+                                            extent: Box::new(provider_extent),
+                                            start: start,
+                                            duration: duration,
+                                        };
+                                        frame.traces.push( trace );
+                                    },
+                                    _ => panic!("internal parse error: malformed parse stack")
+                                }
+                            }
+                        }
                     },
-                    (ParseState::HaveTimeBegin(_, _),
-                     ProfileQueriesMsg::CacheHit) => { unreachable!() },
-                    (ParseState::HaveTimeBegin(_, _),
-                     ProfileQueriesMsg::QueryBegin(_, _)) => { unreachable!() },
-                    (ParseState::HaveTimeBegin(_, _),
-                     ProfileQueriesMsg::ProviderEnd) => { unreachable!() },
+                    (_, ProfileQueriesMsg::TaskEnd) => { panic!("parse error") }
 
                     // Parse State: HaveQuery
                     (ParseState::HaveQuery(q,start),
@@ -244,6 +272,11 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                         stack.push(frame);
                         frame = StackFrame{parse_st:ParseState::Clear, traces:vec![]};
                     },
+
+                    //
+                    //
+                    // Parse errors:
+
                     (ParseState::HaveQuery(q,_),
                      ProfileQueriesMsg::ProviderEnd) => {
                         panic!("parse error: unexpected ProviderEnd; \
@@ -255,7 +288,15 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
                                 earlier query is unfinished: {:?} and now {:?}",
                                q1, Query{span:span2, msg:querymsg2})
                     },
+
+                    (ParseState::HaveTimeBegin(_, _), _) => {
+                        unreachable!()
+                    },
+                    (ParseState::HaveTaskBegin(_, _), _) => {
+                        unreachable!()
+                    },
                 }
+
             }
         }
     }

src/librustc_driver/profile/trace.rs

@@ -14,6 +14,7 @@ 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 {
@@ -23,6 +24,7 @@ pub struct Query {
 pub enum Effect {
     QueryBegin(Query, CacheCase),
     TimeBegin(String),
+    TaskBegin(DepNode),
 }
 pub enum CacheCase {
     Hit, Miss
@@ -46,13 +48,24 @@ pub fn cons_of_query_msg(q: &trace::Query) -> String {
     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(),
@@ -146,6 +159,20 @@ fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec
                     }};
                 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,
+                            duration: qm.duration + t.duration
+                        },
+                    None => QueryMetric{
+                        count: 1,
+                        duration: t.duration
+                    }};
+                counts.insert(cons, qm);
+            },
             Effect::QueryBegin(ref qmsg, ref _cc) => {
                 let qcons = cons_of_query_msg(qmsg);
                 let qm = match counts.get(&qcons) {
@@ -209,6 +236,12 @@ body {
     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;