Skip to content

Commit

Permalink
profiling with -Z profile-queries recognizes -Z time-passes
Browse files Browse the repository at this point in the history
  • Loading branch information
Matthew Hammer committed Aug 23, 2017
1 parent d7ec3e1 commit 28cb03d
Show file tree
Hide file tree
Showing 3 changed files with 139 additions and 26 deletions.
12 changes: 11 additions & 1 deletion src/librustc/util/common.rs
View file
Expand Up @@ -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.
Expand Down Expand Up @@ -110,9 +114,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);

Expand Down
104 changes: 89 additions & 15 deletions src/librustc_driver/profile/mod.rs
View file
Expand Up @@ -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};
Expand Down Expand Up @@ -41,14 +42,30 @@ 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<trace::Rec>,
}

// 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::NoQuery, traces:vec![] };
let mut frame : StackFrame = StackFrame{ parse_st:ParseState::Clear, traces:vec![] };
let mut stack : Vec<StackFrame> = vec![];
loop {
let msg = r.recv();
Expand All @@ -64,7 +81,7 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
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 {
Expand Down Expand Up @@ -94,6 +111,10 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
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();
}
Expand All @@ -108,35 +129,33 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
(_,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() {
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) => {
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 {
Expand All @@ -146,11 +165,66 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
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),
Expand All @@ -163,12 +237,12 @@ fn profile_queries_thread(r:Receiver<ProfileQueriesMsg>) {
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) => {
Expand Down
49 changes: 39 additions & 10 deletions src/librustc_driver/profile/trace.rs
View file
Expand Up @@ -22,6 +22,7 @@ pub struct Query {
}
pub enum Effect {
QueryBegin(Query, CacheCase),
TimeBegin(String),
}
pub enum CacheCase {
Hit, Miss
Expand All @@ -33,16 +34,6 @@ pub struct Rec {
pub duration: Duration,
pub extent: Box<Vec<Rec>>,
}
/// 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<Rec>,
}
pub struct QueryMetric {
pub count: usize,
pub duration: Duration,
Expand All @@ -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(),
Expand Down Expand Up @@ -142,6 +137,9 @@ fn write_traces_rec(file: &mut File, traces: &Vec<Rec>, total: Duration, depth:
fn compute_counts_rec(counts: &mut HashMap<String,QueryMetric>, traces: &Vec<Rec>) {
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) {
Expand Down Expand Up @@ -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;
Expand All @@ -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();
}

0 comments on commit 28cb03d

Please sign in to comment.