diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index 2e4aaeee2356..bce2a66a308a 100644 --- a/src/librustc/util/common.rs +++ b/src/librustc/util/common.rs @@ -51,8 +51,12 @@ pub struct ProfQDumpParams { /// 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 new query - QueryBegin(Span,QueryMsg), + 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. @@ -110,9 +114,15 @@ pub fn time(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); diff --git a/src/librustc_driver/profile/mod.rs b/src/librustc_driver/profile/mod.rs index 32e938ebcd61..785efa78ddcd 100644 --- a/src/librustc_driver/profile/mod.rs +++ b/src/librustc_driver/profile/mod.rs @@ -8,6 +8,7 @@ // 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}; @@ -41,6 +42,22 @@ pub fn dump(path:String) { 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), +} +struct StackFrame { + pub parse_st: ParseState, + pub traces: Vec, +} + // profiling thread; retains state (in local variables) and dump traces, upon request. fn profile_queries_thread(r:Receiver) { use self::trace::*; @@ -48,7 +65,7 @@ fn profile_queries_thread(r:Receiver) { use std::time::{Instant}; let mut profq_msgs : Vec = vec![]; - let mut frame : StackFrame = StackFrame{ parse_st:ParseState::NoQuery, traces:vec![] }; + let mut frame : StackFrame = StackFrame{ parse_st:ParseState::Clear, traces:vec![] }; let mut stack : Vec = vec![]; loop { let msg = r.recv(); @@ -64,7 +81,7 @@ fn profile_queries_thread(r:Receiver) { ProfileQueriesMsg::Halt => return, ProfileQueriesMsg::Dump(params) => { assert!(stack.len() == 0); - assert!(frame.parse_st == trace::ParseState::NoQuery); + assert!(frame.parse_st == ParseState::Clear); { // write log of all messages if params.dump_profq_msg_log { @@ -94,6 +111,10 @@ fn profile_queries_thread(r:Receiver) { trace::write_traces(&mut html_file, &mut counts_file, &frame.traces); write!(html_file, "\n\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(); } @@ -108,22 +129,22 @@ fn profile_queries_thread(r:Receiver) { (_,ProfileQueriesMsg::Halt) => unreachable!(), (_,ProfileQueriesMsg::Dump(_)) => unreachable!(), - // Parse State: NoQuery - (ParseState::NoQuery, + // 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::NoQuery, + (ParseState::Clear, ProfileQueriesMsg::CacheHit) => { panic!("parse error: unexpected CacheHit; expected QueryBegin") }, - (ParseState::NoQuery, + (ParseState::Clear, ProfileQueriesMsg::ProviderBegin) => { panic!("parse error: expected QueryBegin before beginning a provider") }, - (ParseState::NoQuery, + (ParseState::Clear, ProfileQueriesMsg::ProviderEnd) => { let provider_extent = frame.traces; match stack.pop() { @@ -131,12 +152,10 @@ fn profile_queries_thread(r:Receiver) { 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) => { + ParseState::HaveQuery(q, start) => { let duration = start.elapsed(); frame = StackFrame{ - parse_st:ParseState::NoQuery, + parse_st:ParseState::Clear, traces:old_frame.traces }; let trace = Rec { @@ -146,11 +165,66 @@ fn profile_queries_thread(r:Receiver) { duration: 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 trace = Rec { + effect: Effect::TimeBegin(msg), + extent: Box::new(provider_extent), + start: start, + duration: duration, + }; + frame.traces.push( trace ); + }, + _ => panic!("internal parse error: malformed parse stack") + } + } + } + }, + (_, ProfileQueriesMsg::TimeEnd) => { panic!("parse error") } + + + // Parse State: HaveTimeBegin -- for timing old + // passes in driver (outside of query model, but + // still in use) + (ParseState::HaveTimeBegin(_, _), + ProfileQueriesMsg::ProviderBegin) => { + }, + (ParseState::HaveTimeBegin(_, _), + ProfileQueriesMsg::CacheHit) => { unreachable!() }, + (ParseState::HaveTimeBegin(_, _), + ProfileQueriesMsg::QueryBegin(_, _)) => { unreachable!() }, + (ParseState::HaveTimeBegin(_, _), + ProfileQueriesMsg::ProviderEnd) => { unreachable!() }, // Parse State: HaveQuery (ParseState::HaveQuery(q,start), @@ -163,12 +237,12 @@ fn profile_queries_thread(r:Receiver) { duration: duration, }; frame.traces.push( trace ); - frame.parse_st = ParseState::NoQuery; + frame.parse_st = ParseState::Clear; }, (ParseState::HaveQuery(_,_), ProfileQueriesMsg::ProviderBegin) => { stack.push(frame); - frame = StackFrame{parse_st:ParseState::NoQuery, traces:vec![]}; + frame = StackFrame{parse_st:ParseState::Clear, traces:vec![]}; }, (ParseState::HaveQuery(q,_), ProfileQueriesMsg::ProviderEnd) => { diff --git a/src/librustc_driver/profile/trace.rs b/src/librustc_driver/profile/trace.rs index c0a8be603cc6..8db3a3e2dfa8 100644 --- a/src/librustc_driver/profile/trace.rs +++ b/src/librustc_driver/profile/trace.rs @@ -22,6 +22,7 @@ pub struct Query { } pub enum Effect { QueryBegin(Query, CacheCase), + TimeBegin(String), } pub enum CacheCase { Hit, Miss @@ -33,16 +34,6 @@ pub struct Rec { pub duration: Duration, pub extent: Box>, } -/// State for parsing recursive trace structure -#[derive(Clone, Eq, PartialEq)] -pub enum ParseState { - NoQuery, - HaveQuery(Query, Instant), -} -pub struct StackFrame { - pub parse_st: ParseState, - pub traces: Vec, -} pub struct QueryMetric { pub count: usize, pub duration: Duration, @@ -58,6 +49,10 @@ pub fn cons_of_query_msg(q: &trace::Query) -> 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::QueryBegin(ref qmsg, ref cc) => { let cons = cons_of_query_msg(qmsg); (cons.clone(), @@ -142,6 +137,9 @@ fn write_traces_rec(file: &mut File, traces: &Vec, total: Duration, depth: fn compute_counts_rec(counts: &mut HashMap, traces: &Vec) { for t in traces.iter() { match t.effect { + Effect::TimeBegin(ref _msg) => { + // dont count time-begin effects + } Effect::QueryBegin(ref qmsg, ref _cc) => { let qcons = cons_of_query_msg(qmsg); let qm = match counts.get(&qcons) { @@ -212,6 +210,12 @@ body { .extent-0 { padding: 2px; } +.time-begin { + border-width: 4px; + font-size: 12px; + color: white; + border-color: #afa; +} .important { border-width: 3px; font-size: 12px; @@ -234,5 +238,30 @@ body { .dur { display: none } +.frac-50 { + padding: 4px; + border-width: 10px; + font-size: 16px; +} +.frac-40 { + padding: 4px; + border-width: 8px; + font-size: 16px; +} +.frac-30 { + padding: 3px; + border-width: 6px; + font-size: 16px; +} +.frac-20 { + padding: 3px; + border-width: 6px; + font-size: 16px; +} +.frac-10 { + padding: 3px; + border-width: 6px; + font-size: 16px; +} ").unwrap(); }