diff --git a/src/librustc/dep_graph/graph.rs b/src/librustc/dep_graph/graph.rs index 0c56fc7914b4c..b08c710534a9b 100644 --- a/src/librustc/dep_graph/graph.rs +++ b/src/librustc/dep_graph/graph.rs @@ -9,7 +9,6 @@ use std::hash::Hash; use std::collections::hash_map::Entry; use std::mem; use crate::ty::{self, TyCtxt}; -use crate::util::common::{ProfileQueriesMsg, profq_msg}; use parking_lot::{Mutex, Condvar}; use crate::ich::{StableHashingContext, StableHashingContextProvider, Fingerprint}; @@ -260,10 +259,6 @@ impl DepGraph { // - we can get an idea of the runtime cost. let mut hcx = cx.get_stable_hashing_context(); - if cfg!(debug_assertions) { - profq_msg(hcx.sess(), ProfileQueriesMsg::TaskBegin(key.clone())) - }; - let result = if no_tcx { task(cx, arg) } else { @@ -279,10 +274,6 @@ impl DepGraph { }) }; - if cfg!(debug_assertions) { - profq_msg(hcx.sess(), ProfileQueriesMsg::TaskEnd) - }; - let current_fingerprint = hash_result(&mut hcx, &result); let dep_node_index = finish_task_and_alloc_depnode( diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index 2771ce69b9e0d..ed8aafa25caa4 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -1316,10 +1316,6 @@ 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"), - 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 f22445f5d4744..9d60221fa3d75 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -11,7 +11,6 @@ use crate::session::config::{OutputType, PrintRequest, SwitchWithOptPath}; use crate::session::search_paths::{PathKind, SearchPath}; use crate::util::nodemap::{FxHashMap, FxHashSet}; use crate::util::common::{duration_to_secs_str, ErrorReported}; -use crate::util::common::ProfileQueriesMsg; use rustc_data_structures::base_n; use rustc_data_structures::sync::{ @@ -46,7 +45,7 @@ use std::fmt; use std::io::Write; use std::path::PathBuf; use std::time::Duration; -use std::sync::{Arc, mpsc}; +use std::sync::Arc; mod code_stats; pub mod config; @@ -125,9 +124,6 @@ pub struct Session { /// `-Zquery-dep-graph` is specified. pub cgu_reuse_tracker: CguReuseTracker, - /// Used by `-Z profile-queries` in `util::common`. - pub profile_channel: Lock>>, - /// Used by `-Z self-profile`. pub prof: SelfProfilerRef, @@ -509,13 +505,6 @@ impl Session { pub fn time_extended(&self) -> bool { self.opts.debugging_opts.time_passes } - 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 instrument_mcount(&self) -> bool { self.opts.debugging_opts.instrument_mcount } @@ -1234,7 +1223,6 @@ fn build_session_( incr_comp_session: OneThread::new(RefCell::new(IncrCompSession::NotInitialized)), cgu_reuse_tracker, prof: SelfProfilerRef::new(self_profiler), - profile_channel: Lock::new(None), perf_stats: PerfStats { symbol_hash_time: Lock::new(Duration::from_secs(0)), decode_def_path_tables_time: Lock::new(Duration::from_secs(0)), diff --git a/src/librustc/ty/query/on_disk_cache.rs b/src/librustc/ty/query/on_disk_cache.rs index 97fafe341a311..1bba7fdd863ea 100644 --- a/src/librustc/ty/query/on_disk_cache.rs +++ b/src/librustc/ty/query/on_disk_cache.rs @@ -1075,7 +1075,7 @@ where let desc = &format!("encode_query_results for {}", ::std::any::type_name::()); - time_ext(tcx.sess.time_extended(), Some(tcx.sess), desc, || { + time_ext(tcx.sess.time_extended(), desc, || { let shards = Q::query_cache(tcx).lock_shards(); assert!(shards.iter().all(|shard| shard.active.is_empty())); for (key, entry) in shards.iter().flat_map(|shard| shard.results.iter()) { diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index 955f1447c55b6..f7046c4ab26fa 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -9,8 +9,6 @@ use crate::ty::query::Query; use crate::ty::query::config::{QueryConfig, QueryDescription}; use crate::ty::query::job::{QueryJob, QueryResult, QueryInfo}; -use crate::util::common::{profq_msg, ProfileQueriesMsg, QueryMsg}; - use errors::DiagnosticBuilder; use errors::Level; use errors::Diagnostic; @@ -62,33 +60,6 @@ impl<'tcx, M: QueryConfig<'tcx>> Default for QueryCache<'tcx, M> { } } -// If enabled, sends a message to the profile-queries thread. -macro_rules! profq_msg { - ($tcx:expr, $msg:expr) => { - if cfg!(debug_assertions) { - if $tcx.sess.profile_queries() { - profq_msg($tcx.sess, $msg) - } - } - } -} - -// If enabled, formats a key using its debug string, which can be -// expensive to compute (in terms of time). -macro_rules! profq_query_msg { - ($query:expr, $tcx:expr, $key:expr) => {{ - let msg = if cfg!(debug_assertions) { - if $tcx.sess.profile_queries_and_keys() { - Some(format!("{:?}", $key)) - } else { None } - } else { None }; - QueryMsg { - query: $query, - msg, - } - }} -} - /// A type representing the responsibility to execute the job in the `job` field. /// This will poison the relevant query if dropped. pub(super) struct JobOwner<'a, 'tcx, Q: QueryDescription<'tcx>> { @@ -111,7 +82,6 @@ impl<'a, 'tcx, Q: QueryDescription<'tcx>> JobOwner<'a, 'tcx, Q> { loop { let mut lock = cache.get_shard_by_value(key).lock(); if let Some(value) = lock.results.get(key) { - profq_msg!(tcx, ProfileQueriesMsg::CacheHit); tcx.prof.query_cache_hit(Q::NAME); let result = (value.value.clone(), value.index); #[cfg(debug_assertions)] @@ -358,13 +328,6 @@ impl<'tcx> TyCtxt<'tcx> { key, span); - profq_msg!(self, - ProfileQueriesMsg::QueryBegin( - span.data(), - profq_query_msg!(Q::NAME.as_str(), self, key), - ) - ); - let job = match JobOwner::try_get(self, span, &key) { TryGetJob::NotYetStarted(job) => job, TryGetJob::Cycle(result) => return result, @@ -383,7 +346,6 @@ impl<'tcx> TyCtxt<'tcx> { if Q::ANON { - profq_msg!(self, ProfileQueriesMsg::ProviderBegin); let prof_timer = self.prof.query_provider(Q::NAME); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { @@ -395,7 +357,6 @@ impl<'tcx> TyCtxt<'tcx> { }); drop(prof_timer); - profq_msg!(self, ProfileQueriesMsg::ProviderEnd); self.dep_graph.read_index(dep_node_index); @@ -468,7 +429,6 @@ impl<'tcx> TyCtxt<'tcx> { }; let result = if let Some(result) = result { - profq_msg!(self, ProfileQueriesMsg::CacheHit); result } else { // We could not load a result from the on-disk cache, so @@ -546,7 +506,6 @@ impl<'tcx> TyCtxt<'tcx> { - dep-node: {:?}", key, dep_node); - profq_msg!(self, ProfileQueriesMsg::ProviderBegin); let prof_timer = self.prof.query_provider(Q::NAME); let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| { @@ -568,7 +527,6 @@ impl<'tcx> TyCtxt<'tcx> { }); drop(prof_timer); - profq_msg!(self, ProfileQueriesMsg::ProviderEnd); if unlikely!(self.sess.opts.debugging_opts.query_dep_graph) { self.dep_graph.mark_loaded_from_cache(dep_node_index, false); @@ -614,19 +572,12 @@ impl<'tcx> TyCtxt<'tcx> { let _ = self.get_query::(DUMMY_SP, key); } else { - profq_msg!(self, ProfileQueriesMsg::CacheHit); self.prof.query_cache_hit(Q::NAME); } } #[allow(dead_code)] fn force_query>(self, key: Q::Key, span: Span, dep_node: DepNode) { - profq_msg!( - self, - ProfileQueriesMsg::QueryBegin(span.data(), - profq_query_msg!(Q::NAME.as_str(), self, key)) - ); - // We may be concurrently trying both execute and force a query. // Ensure that only one of them runs the query. let job = match JobOwner::try_get(self, span, &key) { diff --git a/src/librustc/util/common.rs b/src/librustc/util/common.rs index 0f472126695e0..3e52a6aa50850 100644 --- a/src/librustc/util/common.rs +++ b/src/librustc/util/common.rs @@ -6,11 +6,8 @@ use std::cell::Cell; use std::fmt::Debug; use std::time::{Duration, Instant}; -use std::sync::mpsc::{Sender}; -use syntax_pos::{SpanData}; use syntax::symbol::{Symbol, sym}; use rustc_macros::HashStable; -use crate::dep_graph::{DepNode}; use crate::session::Session; #[cfg(test)] @@ -26,17 +23,6 @@ pub struct ErrorReported; thread_local!(static TIME_DEPTH: Cell = Cell::new(0)); -/// 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, -} - #[allow(nonstandard_style)] #[derive(Clone, Debug, PartialEq, Eq)] pub struct QueryMsg { @@ -44,53 +30,6 @@ pub struct QueryMsg { pub msg: Option, } -/// 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 timed pass. - TimeBegin(String), - /// End a timed pass. - TimeEnd, - /// Begin a task (see `dep_graph::graph::with_task`). - TaskBegin(DepNode), - /// End a task. - TaskEnd, - /// Begin a new query. - /// Cannot use `Span` because queries are sent to other thread. - QueryBegin(SpanData, 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(sess: &Session, msg: ProfileQueriesMsg) { - if let Some(s) = sess.profile_channel.borrow().as_ref() { - s.send(msg).unwrap() - } else { - // Do nothing. - } -} - -/// Set channel for profile queries channel. -pub fn profq_set_chan(sess: &Session, s: Sender) -> bool { - let mut channel = sess.profile_channel.borrow_mut(); - if channel.is_none() { - *channel = 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 { @@ -107,10 +46,10 @@ pub fn set_time_depth(depth: usize) { pub fn time(sess: &Session, what: &str, f: F) -> T where F: FnOnce() -> T, { - time_ext(sess.time_passes(), Some(sess), what, f) + time_ext(sess.time_passes(), what, f) } -pub fn time_ext(do_it: bool, sess: Option<&Session>, what: &str, f: F) -> T where +pub fn time_ext(do_it: bool, what: &str, f: F) -> T where F: FnOnce() -> T, { if !do_it { return f(); } @@ -121,19 +60,9 @@ pub fn time_ext(do_it: bool, sess: Option<&Session>, what: &str, f: F) -> r }); - if let Some(sess) = sess { - if cfg!(debug_assertions) { - profq_msg(sess, ProfileQueriesMsg::TimeBegin(what.to_string())) - } - } let start = Instant::now(); let rv = f(); let dur = start.elapsed(); - if let Some(sess) = sess { - if cfg!(debug_assertions) { - profq_msg(sess, ProfileQueriesMsg::TimeEnd) - } - } print_time_passes_entry(true, what, dur); diff --git a/src/librustc_codegen_llvm/back/lto.rs b/src/librustc_codegen_llvm/back/lto.rs index c4368d2cb8b45..da74c69d7d707 100644 --- a/src/librustc_codegen_llvm/back/lto.rs +++ b/src/librustc_codegen_llvm/back/lto.rs @@ -116,7 +116,7 @@ fn prepare_lto(cgcx: &CodegenContext, info!("adding bytecode {}", name); let bc_encoded = data.data(); - let (bc, id) = time_ext(cgcx.time_passes, None, &format!("decode {}", name), || { + let (bc, id) = time_ext(cgcx.time_passes, &format!("decode {}", name), || { match DecodedBytecode::new(bc_encoded) { Ok(b) => Ok((b.bytecode(), b.identifier().to_string())), Err(e) => Err(diag_handler.fatal(&e)), @@ -295,7 +295,7 @@ fn fat_lto(cgcx: &CodegenContext, for (bc_decoded, name) in serialized_modules { let _timer = cgcx.prof.generic_activity("LLVM_fat_lto_link_module"); info!("linking {:?}", name); - time_ext(cgcx.time_passes, None, &format!("ll link {:?}", name), || { + time_ext(cgcx.time_passes, &format!("ll link {:?}", name), || { let data = bc_decoded.data(); linker.add(&data).map_err(|()| { let msg = format!("failed to load bc of {:?}", name); @@ -590,7 +590,7 @@ pub(crate) fn run_pass_manager(cgcx: &CodegenContext, llvm::LLVMRustAddPass(pm, pass.unwrap()); } - time_ext(cgcx.time_passes, None, "LTO passes", || + time_ext(cgcx.time_passes, "LTO passes", || llvm::LLVMRunPassManager(pm, module.module_llvm.llmod())); llvm::LLVMDisposePassManager(pm); diff --git a/src/librustc_codegen_llvm/back/write.rs b/src/librustc_codegen_llvm/back/write.rs index 78db90b57b53d..17cf9ed5ba769 100644 --- a/src/librustc_codegen_llvm/back/write.rs +++ b/src/librustc_codegen_llvm/back/write.rs @@ -427,7 +427,6 @@ pub(crate) unsafe fn optimize(cgcx: &CodegenContext, { let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_function_passes"); time_ext(config.time_passes, - None, &format!("llvm function passes [{}]", module_name.unwrap()), || { llvm::LLVMRustRunFunctionPassManager(fpm, llmod) @@ -436,7 +435,6 @@ pub(crate) unsafe fn optimize(cgcx: &CodegenContext, { let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_module_passes"); time_ext(config.time_passes, - None, &format!("llvm module passes [{}]", module_name.unwrap()), || { llvm::LLVMRunPassManager(mpm, llmod) @@ -538,7 +536,7 @@ pub(crate) unsafe fn codegen(cgcx: &CodegenContext, embed_bitcode(cgcx, llcx, llmod, None); } - time_ext(config.time_passes, None, &format!("codegen passes [{}]", module_name.unwrap()), + time_ext(config.time_passes, &format!("codegen passes [{}]", module_name.unwrap()), || -> Result<(), FatalError> { if config.emit_ir { let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_emit_ir"); diff --git a/src/librustc_codegen_ssa/back/link.rs b/src/librustc_codegen_ssa/back/link.rs index 3b7ae5e33d5e7..1ce008e4d74d2 100644 --- a/src/librustc_codegen_ssa/back/link.rs +++ b/src/librustc_codegen_ssa/back/link.rs @@ -1527,7 +1527,7 @@ fn add_upstream_rust_crates<'a, B: ArchiveBuilder<'a>>( let name = cratepath.file_name().unwrap().to_str().unwrap(); let name = &name[3..name.len() - 5]; // chop off lib/.rlib - time_ext(sess.time_extended(), Some(sess), &format!("altering {}.rlib", name), || { + time_ext(sess.time_extended(), &format!("altering {}.rlib", name), || { let mut archive = ::new(sess, &dst, Some(cratepath)); archive.update_symbols(); diff --git a/src/librustc_incremental/persist/load.rs b/src/librustc_incremental/persist/load.rs index 90aefb0f32416..b7f4df62b494b 100644 --- a/src/librustc_incremental/persist/load.rs +++ b/src/librustc_incremental/persist/load.rs @@ -160,7 +160,7 @@ pub fn load_dep_graph(sess: &Session) -> DepGraphFuture { } MaybeAsync::Async(std::thread::spawn(move || { - time_ext(time_passes, None, "background load prev dep-graph", move || { + time_ext(time_passes, "background load prev dep-graph", move || { match load_data(report_incremental_info, &path) { LoadResult::DataOutOfDate => LoadResult::DataOutOfDate, LoadResult::Error { message } => LoadResult::Error { message }, diff --git a/src/librustc_interface/interface.rs b/src/librustc_interface/interface.rs index dae8fb242d58c..b26bd75c974c6 100644 --- a/src/librustc_interface/interface.rs +++ b/src/librustc_interface/interface.rs @@ -1,6 +1,5 @@ use crate::queries::Queries; use crate::util; -use crate::profile; pub use crate::passes::BoxedResolver; use rustc::lint; @@ -115,17 +114,7 @@ where compiler.sess.diagnostic().print_error_count(&util::diagnostics_registry()); }); - if compiler.sess.profile_queries() { - profile::begin(&compiler.sess); - } - - let r = f(&compiler); - - if compiler.sess.profile_queries() { - profile::dump(&compiler.sess, "profile_queries".to_string()) - } - - r + f(&compiler) } pub fn run_compiler(mut config: Config, f: F) -> R diff --git a/src/librustc_interface/lib.rs b/src/librustc_interface/lib.rs index 2e593d441553a..6be36e9b9001b 100644 --- a/src/librustc_interface/lib.rs +++ b/src/librustc_interface/lib.rs @@ -16,6 +16,5 @@ mod passes; mod queries; pub mod util; mod proc_macro_decls; -mod profile; pub use interface::{run_compiler, Config}; diff --git a/src/librustc_interface/profile/mod.rs b/src/librustc_interface/profile/mod.rs deleted file mode 100644 index 2e71d46f4154c..0000000000000 --- a/src/librustc_interface/profile/mod.rs +++ /dev/null @@ -1,297 +0,0 @@ -use log::debug; -use rustc::dep_graph::DepNode; -use rustc::session::Session; -use rustc::util::common::{ProfQDumpParams, ProfileQueriesMsg, profq_msg, profq_set_chan}; -use std::sync::mpsc::{Receiver}; -use std::io::{Write}; -use std::time::{Duration, Instant}; - -pub mod trace; - -/// begin a profile thread, if not already running -pub fn begin(sess: &Session) { - use std::thread; - use std::sync::mpsc::{channel}; - let (tx, rx) = channel(); - if profq_set_chan(sess, 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(sess: &Session, 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: true, - }; - profq_msg(sess, ProfileQueriesMsg::Dump(params)); - 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), - // Have "task-begin" information from the last message - HaveTaskBegin(DepNode, Instant), -} -struct StackFrame { - pub parse_st: ParseState, - pub traces: Vec, -} - -fn total_duration(traces: &[trace::Rec]) -> Duration { - Duration::new(0, 0) + traces.iter().map(|t| t.dur_total).sum() -} - -// 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; - - let mut profq_msgs: Vec = vec![]; - let mut frame: StackFrame = StackFrame { parse_st: ParseState::Clear, 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.is_empty()); - assert!(frame.parse_st == ParseState::Clear); - - // 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(); - - writeln!(html_file, - "\n\n", - "profile_queries.css").unwrap(); - writeln!(html_file, "\n\n").unwrap(); - trace::write_traces(&mut html_file, &mut counts_file, &frame.traces); - writeln!(html_file, "\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(); - } - // 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) | (_, ProfileQueriesMsg::Dump(_)) => { - unreachable!(); - }, - // Parse State: Clear - (ParseState::Clear, - ProfileQueriesMsg::QueryBegin(span, querymsg)) => { - let start = Instant::now(); - frame.parse_st = ParseState::HaveQuery - (Query { span, msg: querymsg }, start) - }, - (ParseState::Clear, - ProfileQueriesMsg::CacheHit) => { - panic!("parse error: unexpected CacheHit; expected QueryBegin") - }, - (ParseState::Clear, - ProfileQueriesMsg::ProviderBegin) => { - panic!("parse error: expected QueryBegin before beginning a provider") - }, - (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::HaveQuery(q, start) => { - let duration = start.elapsed(); - frame = StackFrame{ - 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, - dur_self: duration - dur_extent, - dur_total: 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 dur_extent = total_duration(&provider_extent); - let trace = Rec { - effect: Effect::TimeBegin(msg), - extent: Box::new(provider_extent), - start: start, - dur_total: duration, - dur_self: duration - dur_extent, - }; - frame.traces.push( trace ); - }, - _ => panic!("internal parse error: malformed parse stack") - } - } - } - }, - (_, 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"); - }, - (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 dur_extent = total_duration(&provider_extent); - let trace = Rec { - effect: Effect::TaskBegin(key), - extent: Box::new(provider_extent), - start: start, - dur_total: duration, - dur_self: duration - dur_extent, - }; - frame.traces.push( trace ); - }, - _ => panic!("internal parse error: malformed parse stack") - } - } - } - }, - (_, ProfileQueriesMsg::TaskEnd) => { - panic!("parse error") - }, - // 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, - dur_self: duration, - dur_total: duration, - }; - frame.traces.push( trace ); - frame.parse_st = ParseState::Clear; - }, - (ParseState::HaveQuery(_, _), - ProfileQueriesMsg::ProviderBegin) => { - stack.push(frame); - frame = StackFrame{ parse_st: ParseState::Clear, traces: vec![] }; - }, - - // Parse errors: - - (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}) - }, - (ParseState::HaveTimeBegin(_, _), _) => { - unreachable!() - }, - (ParseState::HaveTaskBegin(_, _), _) => { - unreachable!() - }, - } - } - } - } -} diff --git a/src/librustc_interface/profile/trace.rs b/src/librustc_interface/profile/trace.rs deleted file mode 100644 index 95c4ea6ff2347..0000000000000 --- a/src/librustc_interface/profile/trace.rs +++ /dev/null @@ -1,304 +0,0 @@ -use super::*; -use syntax_pos::SpanData; -use rustc_data_structures::fx::FxHashMap; -use rustc::util::common::QueryMsg; -use std::fs::File; -use std::time::{Duration, Instant}; -use rustc::dep_graph::{DepNode}; - -#[derive(Debug, Clone, Eq, PartialEq)] -pub struct Query { - pub span: SpanData, - pub msg: QueryMsg, -} -pub enum Effect { - QueryBegin(Query, CacheCase), - TimeBegin(String), - TaskBegin(DepNode), -} -pub enum CacheCase { - Hit, Miss -} -/// Recursive trace structure -pub struct Rec { - pub effect: Effect, - pub start: Instant, - pub dur_self: Duration, - pub dur_total: Duration, - pub extent: Box>, -} -pub struct QueryMetric { - pub count: usize, - pub dur_self: Duration, - pub dur_total: Duration, -} - -fn cons(s: &str) -> String { - let first = s.split(|d| d == '(' || d == '{').next(); - assert!(first.is_some() && first != Some("")); - first.unwrap().to_owned() -} - -pub fn cons_of_query_msg(q: &trace::Query) -> String { - cons(&format!("{:?}", q.msg)) -} - -pub fn cons_of_key(k: &DepNode) -> String { - cons(&format!("{:?}", k)) -} - -// 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(), - "time-begin".to_string()) - }, - 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(), - 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()), String::new()) -} - -fn html_of_fraction(frac: f64) -> (String, &'static str) { - let css = { - if frac > 0.50 { "frac-50" } - else if frac > 0.40 { "frac-40" } - else if frac > 0.30 { "frac-30" } - else if frac > 0.20 { "frac-20" } - else if frac > 0.10 { "frac-10" } - else if frac > 0.05 { "frac-05" } - else if frac > 0.02 { "frac-02" } - else if frac > 0.01 { "frac-01" } - else if frac > 0.001 { "frac-001" } - else { "frac-0" } - }; - let percent = frac * 100.0; - - if percent > 0.1 { - (format!("{:.1}%", percent), css) - } else { - ("< 0.1%".to_string(), css) - } -} - -fn total_duration(traces: &[Rec]) -> Duration { - Duration::new(0, 0) + traces.iter().map(|t| t.dur_total).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: &[Rec], 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.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); - writeln!(file, "
", - 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(); - writeln!(file, "
{}
", eff_text).unwrap(); - writeln!(file, "
{}
", dur_text).unwrap(); - writeln!(file, "
{}
", frc_text).unwrap(); - write_traces_rec(file, &t.extent, total, depth + 1); - writeln!(file, "
").unwrap(); - } -} - -fn compute_counts_rec(counts: &mut FxHashMap, traces: &[Rec]) { - counts.reserve(traces.len()); - for t in traces.iter() { - match t.effect { - Effect::TimeBegin(ref msg) => { - let qm = match counts.get(msg) { - Some(_qm) => panic!("TimeBegin with non-unique, repeat message"), - None => QueryMetric { - count: 1, - dur_self: t.dur_self, - dur_total: t.dur_total, - } - }; - counts.insert(msg.clone(), qm); - }, - Effect::TaskBegin(ref key) => { - let cons = cons_of_key(key); - let qm = match counts.get(&cons) { - Some(qm) => - QueryMetric { - count: qm.count + 1, - dur_self: qm.dur_self + t.dur_self, - dur_total: qm.dur_total + t.dur_total, - }, - None => QueryMetric { - count: 1, - dur_self: t.dur_self, - dur_total: t.dur_total, - } - }; - counts.insert(cons, qm); - }, - 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, - dur_total: qm.dur_total + t.dur_total, - dur_self: qm.dur_self + t.dur_self - }, - None => QueryMetric { - count: 1, - dur_total: t.dur_total, - dur_self: t.dur_self, - } - }; - counts.insert(qcons, qm); - } - } - compute_counts_rec(counts, &t.extent) - } -} - -pub fn write_counts(count_file: &mut File, counts: &mut FxHashMap) { - use rustc::util::common::duration_to_secs_str; - use std::cmp::Reverse; - - let mut data = counts.iter().map(|(ref cons, ref qm)| - (cons.clone(), qm.count.clone(), qm.dur_total.clone(), qm.dur_self.clone()) - ).collect::>(); - - data.sort_by_key(|k| Reverse(k.3)); - for (cons, count, dur_total, dur_self) in data { - writeln!(count_file, "{}, {}, {}, {}", - cons, count, - duration_to_secs_str(dur_total), - duration_to_secs_str(dur_self) - ).unwrap(); - } -} - -pub fn write_traces(html_file: &mut File, counts_file: &mut File, traces: &[Rec]) { - let capacity = traces.iter().fold(0, |acc, t| acc + 1 + t.extent.len()); - let mut counts = FxHashMap::with_capacity_and_hasher(capacity, Default::default()); - 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; -} -.task-begin { - border-width: 1px; - color: white; - border-color: #ff8; - font-size: 0px; -} -.miss { - border-color: red; - border-width: 1px; -} -.extent-0 { - padding: 2px; -} -.time-begin { - border-width: 4px; - font-size: 12px; - color: white; - border-color: #afa; -} -.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 -} -.frac-50 { - padding: 10px; - border-width: 10px; - font-size: 32px; -} -.frac-40 { - padding: 8px; - border-width: 8px; - font-size: 24px; -} -.frac-30 { - padding: 6px; - border-width: 6px; - font-size: 18px; -} -.frac-20 { - padding: 4px; - border-width: 6px; - font-size: 16px; -} -.frac-10 { - padding: 2px; - border-width: 6px; - font-size: 14px; -} -").unwrap(); -}