From 43335aec22327ef542088263dd7353accda40517 Mon Sep 17 00:00:00 2001 From: Matthew Hammer Date: Wed, 2 Aug 2017 12:58:23 -0600 Subject: [PATCH] -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 a89d5ae9cdc..99fe8e60ae5 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 38a675922a8..823a637c7e0 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 678aa047b14..6e02e38aee1 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 1428513977c..c16b30338f6 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 f77748447fe..061077d05a4 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 22ca69fe3b4..f5079836c3c 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(); } }