mathieu/os-rust
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Rollup merge of #65081 - Mark-Simulacrum:remove-profile-queries, r=michaelwoerister

Browse source 
Remove -Zprofile-queries

r? @michaelwoerister

Per [zulip thread](https://zulip-archive.rust-lang.org/131828tcompiler/57361RemoveZprofilequeries.html).
This commit is contained in:
Mazdak Farrokhzad 2019-10-08 23:31:20 +02:00 • committed by GitHub
commit 3f2ae44ba4
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
14 changed files with 11 additions and 771 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

9
src/librustc/dep_graph/graph.rs
View file

@ -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};
@ -256,10 +255,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 {
@ -275,10 +270,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(

4
src/librustc/session/config.rs
View file

@ -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<String> = (Vec::new(), parse_list, [TRACKED],

14
src/librustc/session/mod.rs
View file

@ -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<Option<mpsc::Sender<ProfileQueriesMsg>>>,
/// 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)),

2
src/librustc/ty/query/on_disk_cache.rs
View file

@ -1075,7 +1075,7 @@ where
let desc = &format!("encode_query_results for {}",
::std::any::type_name::<Q>());
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()) {

49
src/librustc/ty/query/plumbing.rs
View file

@ -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
@ -542,7 +502,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| {
@ -564,7 +523,6 @@ impl<'tcx> TyCtxt<'tcx> {
});
drop(prof_timer);
profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
if unlikely!(!diagnostics.is_empty()) {
if dep_node.kind != crate::dep_graph::DepKind::Null {
@ -606,19 +564,12 @@ impl<'tcx> TyCtxt<'tcx> {
let _ = self.get_query::<Q>(DUMMY_SP, key);
} else {
profq_msg!(self, ProfileQueriesMsg::CacheHit);
self.prof.query_cache_hit(Q::NAME);
}
}
#[allow(dead_code)]
fn force_query<Q: QueryDescription<'tcx>>(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) {

75
src/librustc/util/common.rs
View file

@ -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<usize> = 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<String>,
}
/// 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<ProfileQueriesMsg>) -> 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<T, F>(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<T, F>(do_it: bool, sess: Option<&Session>, what: &str, f: F) -> T where
pub fn time_ext<T, F>(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<T, F>(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);

6
src/librustc_codegen_llvm/back/lto.rs
View file

@ -116,7 +116,7 @@ fn prepare_lto(cgcx: &CodegenContext<LlvmCodegenBackend>,
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<LlvmCodegenBackend>,
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<LlvmCodegenBackend>,
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);

4
src/librustc_codegen_llvm/back/write.rs
View file

@ -427,7 +427,6 @@ pub(crate) unsafe fn optimize(cgcx: &CodegenContext<LlvmCodegenBackend>,
{
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<LlvmCodegenBackend>,
{
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<LlvmCodegenBackend>,
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");

2
src/librustc_codegen_ssa/back/link.rs
View file

@ -1535,7 +1535,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 = <B as ArchiveBuilder>::new(sess, &dst, Some(cratepath));
archive.update_symbols();

2
src/librustc_incremental/persist/load.rs
View file

@ -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 },

13
src/librustc_interface/interface.rs
View file

@ -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<F, R>(mut config: Config, f: F) -> R

1
src/librustc_interface/lib.rs
View file

@ -16,6 +16,5 @@ mod passes;
mod queries;
pub mod util;
mod proc_macro_decls;
mod profile;
pub use interface::{run_compiler, Config};

297
src/librustc_interface/profile/mod.rs
View file

@ -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<trace::Rec>,
}
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<ProfileQueriesMsg>) {
use self::trace::*;
use std::fs::File;
let mut profq_msgs: Vec<ProfileQueriesMsg> = vec![];
let mut frame: StackFrame = StackFrame { parse_st: ParseState::Clear, traces: vec![] };
let mut stack: Vec<StackFrame> = 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,
"<html>\n<head>\n<link rel=\"stylesheet\" type=\"text/css\" href=\"{}\">",
"profile_queries.css").unwrap();
writeln!(html_file, "<style>").unwrap();
trace::write_style(&mut html_file);
writeln!(html_file, "</style>\n</head>\n<body>").unwrap();
trace::write_traces(&mut html_file, &mut counts_file, &frame.traces);
writeln!(html_file, "</body>\n</html>").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!()
},
}
}
}
}
}

304
src/librustc_interface/profile/trace.rs
View file

@ -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<Vec<Rec>>,
}
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, "<div class=\"trace depth-{} extent-{}{} {} {} {}\">",
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, "<div class=\"eff\">{}</div>", eff_text).unwrap();
writeln!(file, "<div class=\"dur\">{}</div>", dur_text).unwrap();
writeln!(file, "<div class=\"frc\">{}</div>", frc_text).unwrap();
write_traces_rec(file, &t.extent, total, depth + 1);
writeln!(file, "</div>").unwrap();
}
}
fn compute_counts_rec(counts: &mut FxHashMap<String,QueryMetric>, 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<String, QueryMetric>) {
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::<Vec<_>>();
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();
}