From d7ec3e1a7d50eed94b25ffc5019617be13d6f94b Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Wed, 19 Jul 2017 15:04:30 -0600 Subject: [PATCH 1/5] inc comp: -Z profile-queries support; see also https://github.com/rust-lang-nursery/rust-forge/blob/master/profile-queries.md --- src/librustc/session/config.rs | 2 + src/librustc/session/mod.rs | 1 + src/librustc/ty/maps.rs | 25 +++ src/librustc/util/common.rs | 57 +++++++ src/librustc_driver/driver.rs | 14 ++ src/librustc_driver/lib.rs | 1 + src/librustc_driver/profile/mod.rs | 188 +++++++++++++++++++++ src/librustc_driver/profile/trace.rs | 238 +++++++++++++++++++++++++++ 8 files changed, 526 insertions(+) create mode 100644 src/librustc_driver/profile/mod.rs create mode 100644 src/librustc_driver/profile/trace.rs diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index 5985dcb97c739..a89d5ae9cdcbc 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -995,6 +995,8 @@ 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"), no_analysis: bool = (false, parse_bool, [UNTRACKED], "parse and expand the source, but run no analysis"), extra_plugins: Vec = (Vec::new(), parse_list, [TRACKED], diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 23dcaf27c2c70..38a675922a8ab 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -389,6 +389,7 @@ 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 } pub fn count_llvm_insns(&self) -> bool { self.opts.debugging_opts.count_llvm_insns } diff --git a/src/librustc/ty/maps.rs b/src/librustc/ty/maps.rs index 26b51630d93e0..678aa047b1400 100644 --- a/src/librustc/ty/maps.rs +++ b/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; @@ -510,6 +511,16 @@ impl<'tcx> QueryDescription for queries::extern_crate<'tcx> { impl<'tcx> QueryDescription for queries::lint_levels<'tcx> { fn describe(_tcx: TyCtxt, _: CrateNum) -> String { format!("computing the lint levels for items in this crate") +} + +// 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.opts.debugging_opts.profile_queries { + profq_msg($msg) + } + } } } @@ -539,6 +550,12 @@ macro_rules! define_maps { $($(#[$attr])* $name($K)),* } + #[allow(bad_style)] + #[derive(Clone, Debug, PartialEq, Eq)] + pub enum QueryMsg { + $($name(String)),* + } + impl<$tcx> Query<$tcx> { pub fn describe(&self, tcx: TyCtxt) -> String { match *self { @@ -581,10 +598,17 @@ macro_rules! define_maps { key, span); + profq_msg!(tcx, + ProfileQueriesMsg::QueryBegin(span.clone(), + QueryMsg::$name(format!("{:?}", 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 +636,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); diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index 885be8464eb30..2e4aaeee2356e 100644 --- a/src/librustc/util/common.rs +++ b/src/librustc/util/common.rs @@ -19,6 +19,10 @@ 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}; + // The name of the associated type for `Fn` return types pub const FN_OUTPUT_NAME: &'static str = "Output"; @@ -29,6 +33,59 @@ pub struct ErrorReported; thread_local!(static TIME_DEPTH: Cell = Cell::new(0)); +/// Initialized for -Z profile-queries +thread_local!(static PROFQ_CHAN: RefCell>> = 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 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 { + panic!("no channel on which to send profq_msg: {:?}", msg) + } + }) +} + +/// Set channel for profile queries channel +pub fn profq_set_chan(s: Sender) -> 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 { diff --git a/src/librustc_driver/driver.rs b/src/librustc_driver/driver.rs index 246fc7fc5241b..1428513977cdb 100644 --- a/src/librustc_driver/driver.rs +++ b/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.opts.debugging_opts.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.opts.debugging_opts.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.opts.debugging_opts.profile_queries { + profile::dump("profile_queries".to_string()) + } + translation } diff --git a/src/librustc_driver/lib.rs b/src/librustc_driver/lib.rs index 64f61b65323c0..d7b5d4a6fe3ba 100644 --- a/src/librustc_driver/lib.rs +++ b/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; diff --git a/src/librustc_driver/profile/mod.rs b/src/librustc_driver/profile/mod.rs new file mode 100644 index 0000000000000..32e938ebcd616 --- /dev/null +++ b/src/librustc_driver/profile/mod.rs @@ -0,0 +1,188 @@ +// 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 or the MIT license +// , 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}; + +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:false, + }; + profq_msg(ProfileQueriesMsg::Dump(params)); + let _ = rx.recv().unwrap(); +} + +// profiling thread; retains state (in local variables) and dump traces, upon request. +fn profile_queries_thread(r:Receiver) { + use self::trace::*; + use std::fs::File; + use std::time::{Instant}; + + let mut profq_msgs : Vec = vec![]; + let mut frame : StackFrame = StackFrame{ parse_st:ParseState::NoQuery, traces:vec![] }; + let mut stack : Vec = 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 == trace::ParseState::NoQuery); + { + // 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, "\n").unwrap(); + write!(html_file, + "\n\n", + "profile_queries.css").unwrap(); + write!(html_file, "\n").unwrap(); + write!(html_file, "\n").unwrap(); + write!(html_file, "\n").unwrap(); + trace::write_traces(&mut html_file, &mut counts_file, &frame.traces); + write!(html_file, "\n\n").unwrap(); + + // 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: NoQuery + (ParseState::NoQuery, + ProfileQueriesMsg::QueryBegin(span,querymsg)) => { + let start = Instant::now(); + frame.parse_st = ParseState::HaveQuery + (Query{span:span, msg:querymsg}, start) + }, + (ParseState::NoQuery, + ProfileQueriesMsg::CacheHit) => { + panic!("parse error: unexpected CacheHit; expected QueryBegin") + }, + (ParseState::NoQuery, + ProfileQueriesMsg::ProviderBegin) => { + panic!("parse error: expected QueryBegin before beginning a provider") + }, + (ParseState::NoQuery, + 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) => { + let duration = start.elapsed(); + frame = StackFrame{ + parse_st:ParseState::NoQuery, + traces:old_frame.traces + }; + let trace = Rec { + effect: Effect::QueryBegin(q, CacheCase::Miss), + extent: Box::new(provider_extent), + start: start, + duration: duration, + }; + frame.traces.push( trace ); + } + } + } + } + } + + // 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, + duration: duration, + }; + frame.traces.push( trace ); + frame.parse_st = ParseState::NoQuery; + }, + (ParseState::HaveQuery(_,_), + ProfileQueriesMsg::ProviderBegin) => { + stack.push(frame); + frame = StackFrame{parse_st:ParseState::NoQuery, traces:vec![]}; + }, + (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}) + }, + } + } + } + } +} diff --git a/src/librustc_driver/profile/trace.rs b/src/librustc_driver/profile/trace.rs new file mode 100644 index 0000000000000..c0a8be603cc69 --- /dev/null +++ b/src/librustc_driver/profile/trace.rs @@ -0,0 +1,238 @@ +// 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 or the MIT license +// , 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; + +#[derive(Debug, Clone, Eq, PartialEq)] +pub struct Query { + pub span: Span, + pub msg: QueryMsg, +} +pub enum Effect { + QueryBegin(Query, CacheCase), +} +pub enum CacheCase { + Hit, Miss +} +/// Recursive trace structure +pub struct Rec { + pub effect: Effect, + pub start: Instant, + 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, +} + +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() +} + +// First return value is text; second return value is a CSS class +pub fn html_of_effect(eff: &Effect) -> (String, String) { + match *eff { + 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) -> Duration { + let mut sum : Duration = Duration::new(0,0); + for t in traces.iter() { + sum += t.duration; + } + 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, 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.duration); + let fraction = duration_div(t.duration, total); + let percent = fraction * 100.0; + let (frc_text, frc_css_classes) = html_of_fraction(fraction); + write!(file, "
\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, "
{}
\n", eff_text).unwrap(); + write!(file, "
{}
\n", dur_text).unwrap(); + write!(file, "
{}
\n", frc_text).unwrap(); + write_traces_rec(file, &t.extent, total, depth + 1); + write!(file, "
\n").unwrap(); + } +} + +fn compute_counts_rec(counts: &mut HashMap, traces: &Vec) { + for t in traces.iter() { + match t.effect { + 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, + duration: qm.duration + t.duration + }, + None => QueryMetric{ + count: 1, + duration: t.duration + } + }; + counts.insert(qcons, qm); + } + } + compute_counts_rec(counts, &t.extent) + } +} + +pub fn write_counts(count_file: &mut File, counts: &mut HashMap) { + 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.duration.clone())); + }; + data.sort_by(|&(_,_,d1),&(_,_,d2)| + if d1 > d2 { Ordering::Less } else { Ordering::Greater } ); + for (cons, count, duration) in data { + write!(count_file, "{},{},{}\n", + cons, count, duration_to_secs_str(duration) + ).unwrap(); + } +} + +pub fn write_traces(html_file: &mut File, counts_file: &mut File, traces: &Vec) { + let mut counts : HashMap = 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; +} +.miss { + border-color: red; + border-width: 1px; +} +.extent-0 { + padding: 2px; +} +.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 +} +").unwrap(); +} From 28cb03d4e1fe230496ff097798881f06c326ba67 Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Fri, 21 Jul 2017 12:32:38 -0600 Subject: [PATCH 2/5] profiling with -Z profile-queries recognizes -Z time-passes --- src/librustc/util/common.rs | 12 +++- src/librustc_driver/profile/mod.rs | 104 +++++++++++++++++++++++---- src/librustc_driver/profile/trace.rs | 49 ++++++++++--- 3 files changed, 139 insertions(+), 26 deletions(-) diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index 2e4aaeee2356e..bce2a66a308a5 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 32e938ebcd616..785efa78ddcd0 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 c0a8be603cc69..8db3a3e2dfa80 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(); } From 3c24fea882b9152f8b84ac9d5fa63da8ae831ade Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Fri, 21 Jul 2017 16:14:34 -0600 Subject: [PATCH 3/5] -Z profile-queries: remove panic when channel is unset --- src/librustc/util/common.rs | 7 ++++++- src/librustc_driver/profile/trace.rs | 30 +++++++++++++++++----------- 2 files changed, 24 insertions(+), 13 deletions(-) diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index bce2a66a308a5..b8972a615681d 100644 --- a/src/librustc/util/common.rs +++ b/src/librustc/util/common.rs @@ -75,7 +75,12 @@ pub fn profq_msg(msg: ProfileQueriesMsg) { if let Some(s) = sender.borrow().as_ref() { s.send(msg).unwrap() } else { - panic!("no channel on which to send profq_msg: {:?}", msg) + // 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) } }) } diff --git a/src/librustc_driver/profile/trace.rs b/src/librustc_driver/profile/trace.rs index 8db3a3e2dfa80..e75e40b22b454 100644 --- a/src/librustc_driver/profile/trace.rs +++ b/src/librustc_driver/profile/trace.rs @@ -137,9 +137,15 @@ 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::TimeBegin(ref msg) => { + let qm = match counts.get(msg) { + Some(_qm) => { panic!("TimeBegin with non-unique, repeat message") } + None => QueryMetric{ + count: 1, + duration: t.duration + }}; + counts.insert(msg.clone(), qm); + }, Effect::QueryBegin(ref qmsg, ref _cc) => { let qcons = cons_of_query_msg(qmsg); let qm = match counts.get(&qcons) { @@ -239,29 +245,29 @@ body { display: none } .frac-50 { - padding: 4px; + padding: 10px; border-width: 10px; - font-size: 16px; + font-size: 32px; } .frac-40 { - padding: 4px; + padding: 8px; border-width: 8px; - font-size: 16px; + font-size: 24px; } .frac-30 { - padding: 3px; + padding: 6px; border-width: 6px; - font-size: 16px; + font-size: 18px; } .frac-20 { - padding: 3px; + padding: 4px; border-width: 6px; font-size: 16px; } .frac-10 { - padding: 3px; + padding: 2px; border-width: 6px; - font-size: 16px; + font-size: 14px; } ").unwrap(); } From 42510327061bd94110ddee6251107686d4ec30db Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Sun, 23 Jul 2017 10:02:07 -0600 Subject: [PATCH 4/5] -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 4ca59132e0ad9..a9701cbf23cf0 100644 --- a/src/librustc/dep_graph/graph.rs +++ b/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 { diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index b8972a615681d..618a4ed331e76 100644 --- a/src/librustc/util/common.rs +++ b/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 diff --git a/src/librustc_driver/profile/mod.rs b/src/librustc_driver/profile/mod.rs index 785efa78ddcd0..f77748447fef9 100644 --- a/src/librustc_driver/profile/mod.rs +++ b/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) { } } } - }, + }, (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 e75e40b22b454..22ca69fe3b444 100644 --- a/src/librustc_driver/profile/trace.rs +++ b/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,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 @@ 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; From 43335aec22327ef542088263dd7353accda40517 Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Wed, 2 Aug 2017 12:58:23 -0600 Subject: [PATCH 5/5] -Z profile-query-and-key, separate from -Z profile-query; query key is string option --- src/librustc/session/config.rs | 2 ++ src/librustc/session/mod.rs | 8 +++++- src/librustc/ty/maps.rs | 24 +++++++++++++--- src/librustc_driver/driver.rs | 6 ++-- src/librustc_driver/profile/mod.rs | 25 +++++++++++++---- src/librustc_driver/profile/trace.rs | 41 +++++++++++++++++----------- 6 files changed, 76 insertions(+), 30 deletions(-) diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index a89d5ae9cdcbc..99fe8e60ae52b 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -997,6 +997,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options, "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 = (Vec::new(), parse_list, [TRACKED], diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 38a675922a8ab..823a637c7e0d4 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -389,7 +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 } + 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 } diff --git a/src/librustc/ty/maps.rs b/src/librustc/ty/maps.rs index 678aa047b1400..6e02e38aee129 100644 --- a/src/librustc/ty/maps.rs +++ b/src/librustc/ty/maps.rs @@ -511,19 +511,32 @@ impl<'tcx> QueryDescription for queries::extern_crate<'tcx> { impl<'tcx> QueryDescription for queries::lint_levels<'tcx> { fn describe(_tcx: TyCtxt, _: CrateNum) -> String { format!("computing the lint levels for items in this crate") + } } // 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.opts.debugging_opts.profile_queries { + 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])* @@ -553,7 +566,7 @@ macro_rules! define_maps { #[allow(bad_style)] #[derive(Clone, Debug, PartialEq, Eq)] pub enum QueryMsg { - $($name(String)),* + $($name(Option)),* } impl<$tcx> Query<$tcx> { @@ -599,8 +612,11 @@ macro_rules! define_maps { span); profq_msg!(tcx, - ProfileQueriesMsg::QueryBegin(span.clone(), - QueryMsg::$name(format!("{:?}", key)))); + 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); diff --git a/src/librustc_driver/driver.rs b/src/librustc_driver/driver.rs index 1428513977cdb..c16b30338f691 100644 --- a/src/librustc_driver/driver.rs +++ b/src/librustc_driver/driver.rs @@ -107,7 +107,7 @@ pub fn compile_input(sess: &Session, sess.abort_if_errors(); } - if sess.opts.debugging_opts.profile_queries { + if sess.profile_queries() { profile::begin(); } @@ -543,7 +543,7 @@ 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.opts.debugging_opts.profile_queries { + if sess.profile_queries() { profile::begin(); } @@ -1130,7 +1130,7 @@ 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.opts.debugging_opts.profile_queries { + if tcx.sess.profile_queries() { profile::dump("profile_queries".to_string()) } diff --git a/src/librustc_driver/profile/mod.rs b/src/librustc_driver/profile/mod.rs index f77748447fef9..061077d05a438 100644 --- a/src/librustc_driver/profile/mod.rs +++ b/src/librustc_driver/profile/mod.rs @@ -8,11 +8,11 @@ // 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}; use rustc::dep_graph::{DepNode}; +use std::time::{Duration, Instant}; pub mod trace; @@ -37,7 +37,7 @@ pub fn dump(path:String) { path, ack:tx, // FIXME: Add another compiler flag to toggle whether this log // is written; false for now - dump_profq_msg_log:false, + dump_profq_msg_log:true, }; profq_msg(ProfileQueriesMsg::Dump(params)); let _ = rx.recv().unwrap(); @@ -61,6 +61,12 @@ struct StackFrame { pub traces: Vec, } +fn total_duration(traces: &Vec) -> 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) { use self::trace::*; @@ -161,11 +167,13 @@ fn profile_queries_thread(r:Receiver) { 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, - duration: duration, + dur_self: duration - dur_extent, + dur_total: duration, }; frame.traces.push( trace ); }, @@ -200,11 +208,13 @@ fn profile_queries_thread(r:Receiver) { 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, - duration: duration, + dur_total: duration, + dur_self: duration - dur_extent, }; frame.traces.push( trace ); }, @@ -239,11 +249,13 @@ fn profile_queries_thread(r:Receiver) { 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, - duration: duration, + dur_total: duration, + dur_self: duration - dur_extent, }; frame.traces.push( trace ); }, @@ -262,7 +274,8 @@ fn profile_queries_thread(r:Receiver) { effect: Effect::QueryBegin(q, CacheCase::Hit), extent: Box::new(vec![]), start: start, - duration: duration, + dur_self: duration, + dur_total: duration, }; frame.traces.push( trace ); frame.parse_st = ParseState::Clear; diff --git a/src/librustc_driver/profile/trace.rs b/src/librustc_driver/profile/trace.rs index 22ca69fe3b444..f5079836c3ca4 100644 --- a/src/librustc_driver/profile/trace.rs +++ b/src/librustc_driver/profile/trace.rs @@ -33,12 +33,14 @@ pub enum CacheCase { pub struct Rec { pub effect: Effect, pub start: Instant, - pub duration: Duration, + pub dur_self: Duration, + pub dur_total: Duration, pub extent: Box>, } pub struct QueryMetric { pub count: usize, - pub duration: Duration, + pub dur_self: Duration, + pub dur_total: Duration, } pub fn cons_of_query_msg(q: &trace::Query) -> String { @@ -108,7 +110,7 @@ fn html_of_fraction(frac: f64) -> (String, String) { fn total_duration(traces: &Vec) -> Duration { let mut sum : Duration = Duration::new(0,0); for t in traces.iter() { - sum += t.duration; + sum += t.dur_total; } return sum } @@ -124,8 +126,8 @@ fn duration_div(nom: Duration, den: Duration) -> f64 { fn write_traces_rec(file: &mut File, traces: &Vec, 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.duration); - let fraction = duration_div(t.duration, total); + 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, "
\n", @@ -155,7 +157,8 @@ fn compute_counts_rec(counts: &mut HashMap, traces: &Vec { panic!("TimeBegin with non-unique, repeat message") } None => QueryMetric{ count: 1, - duration: t.duration + dur_self: t.dur_self, + dur_total: t.dur_total, }}; counts.insert(msg.clone(), qm); }, @@ -165,11 +168,13 @@ fn compute_counts_rec(counts: &mut HashMap, traces: &Vec QueryMetric{ count: qm.count + 1, - duration: qm.duration + t.duration + dur_self: qm.dur_self + t.dur_self, + dur_total: qm.dur_total + t.dur_total, }, None => QueryMetric{ count: 1, - duration: t.duration + dur_self: t.dur_self, + dur_total: t.dur_total, }}; counts.insert(cons, qm); }, @@ -179,11 +184,13 @@ fn compute_counts_rec(counts: &mut HashMap, traces: &Vec QueryMetric{ count: qm.count + 1, - duration: qm.duration + t.duration + dur_total: qm.dur_total + t.dur_total, + dur_self: qm.dur_self + t.dur_self }, None => QueryMetric{ count: 1, - duration: t.duration + dur_total: t.dur_total, + dur_self: t.dur_self, } }; counts.insert(qcons, qm); @@ -199,13 +206,15 @@ pub fn write_counts(count_file: &mut File, counts: &mut HashMap d2 { Ordering::Less } else { Ordering::Greater } ); - for (cons, count, duration) in data { - write!(count_file, "{},{},{}\n", - cons, count, duration_to_secs_str(duration) + 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(); } }