From 42510327061bd94110ddee6251107686d4ec30db Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Sun, 23 Jul 2017 10:02:07 -0600 Subject: [PATCH] -Z profile-queries includes dep_graph.with_task uses in output --- src/librustc/dep_graph/graph.rs | 7 +++ src/librustc/util/common.rs | 7 ++- src/librustc_driver/profile/mod.rs | 65 +++++++++++++++++++++++----- src/librustc_driver/profile/trace.rs | 33 ++++++++++++++ 4 files changed, 99 insertions(+), 13 deletions(-) diff --git a/src/librustc/dep_graph/graph.rs b/src/librustc/dep_graph/graph.rs index 4ca59132e0a..a9701cbf23c 100644 --- a/src/librustc/dep_graph/graph.rs +++ b/src/librustc/dep_graph/graph.rs @@ -12,6 +12,7 @@ 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 @@ pub fn with_task(&self, { 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 { diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index b8972a61568..618a4ed331e 100644 --- a/src/librustc/util/common.rs +++ b/src/librustc/util/common.rs @@ -22,6 +22,7 @@ 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 diff --git a/src/librustc_driver/profile/mod.rs b/src/librustc_driver/profile/mod.rs index 785efa78ddc..f77748447fe 100644 --- a/src/librustc_driver/profile/mod.rs +++ b/src/librustc_driver/profile/mod.rs @@ -12,6 +12,7 @@ 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) { } } } - }, + }, (ParseState::Clear, @@ -212,19 +215,44 @@ fn profile_queries_thread(r:Receiver) { }, (_, 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) { 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) { earlier query is unfinished: {:?} and now {:?}", q1, Query{span:span2, msg:querymsg2}) }, + + (ParseState::HaveTimeBegin(_, _), _) => { + unreachable!() + }, + (ParseState::HaveTaskBegin(_, _), _) => { + unreachable!() + }, } + } } } diff --git a/src/librustc_driver/profile/trace.rs b/src/librustc_driver/profile/trace.rs index e75e40b22b4..22ca69fe3b4 100644 --- a/src/librustc_driver/profile/trace.rs +++ b/src/librustc_driver/profile/trace.rs @@ -14,6 +14,7 @@ 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,6 +48,13 @@ 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 { @@ -53,6 +62,10 @@ pub fn html_of_effect(eff: &Effect) -> (String, String) { (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, traces: &Vec { + 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 @@ pub fn write_style(html_file: &mut File) { 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; -- GitLab