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!() }, } } } } }