src/librustc_interface/profile/mod.rs

   1 use log::debug;
   2 use rustc::dep_graph::DepNode;
   3 use rustc::session::Session;
   4 use rustc::util::common::{ProfQDumpParams, ProfileQueriesMsg, profq_msg, profq_set_chan};
   5 use std::sync::mpsc::{Receiver};
   6 use std::io::{Write};
   7 use std::time::{Duration, Instant};
   8
   9 pub mod trace;
  10
  11 /// begin a profile thread, if not already running
  12 pub fn begin(sess: &Session) {
  13     use std::thread;
  14     use std::sync::mpsc::{channel};
  15     let (tx, rx) = channel();
  16     if profq_set_chan(sess, tx) {
  17         thread::spawn(move || profile_queries_thread(rx));
  18     }
  19 }
  20
  21 /// dump files with profiling information to the given base path, and
  22 /// wait for this dump to complete.
  23 ///
  24 /// wraps the RPC (send/recv channel logic) of requesting a dump.
  25 pub fn dump(sess: &Session, path: String) {
  26     use std::sync::mpsc::{channel};
  27     let (tx, rx) = channel();
  28     let params = ProfQDumpParams {
  29         path,
  30         ack: tx,
  31         // FIXME: Add another compiler flag to toggle whether this log
  32         // is written; false for now
  33         dump_profq_msg_log: true,
  34     };
  35     profq_msg(sess, ProfileQueriesMsg::Dump(params));
  36     let _ = rx.recv().unwrap();
  37 }
  38
  39 // State for parsing recursive trace structure in separate thread, via messages
  40 #[derive(Clone, Eq, PartialEq)]
  41 enum ParseState {
  42     // No (local) parse state; may be parsing a tree, focused on a
  43     // sub-tree that could be anything.
  44     Clear,
  45     // Have Query information from the last message
  46     HaveQuery(trace::Query, Instant),
  47     // Have "time-begin" information from the last message (doit flag, and message)
  48     HaveTimeBegin(String, Instant),
  49     // Have "task-begin" information from the last message
  50     HaveTaskBegin(DepNode, Instant),
  51 }
  52 struct StackFrame {
  53     pub parse_st: ParseState,
  54     pub traces:   Vec<trace::Rec>,
  55 }
  56
  57 fn total_duration(traces: &[trace::Rec]) -> Duration {
  58     Duration::new(0, 0) + traces.iter().map(|t| t.dur_total).sum()
  59 }
  60
  61 // profiling thread; retains state (in local variables) and dump traces, upon request.
  62 fn profile_queries_thread(r: Receiver<ProfileQueriesMsg>) {
  63     use self::trace::*;
  64     use std::fs::File;
  65
  66     let mut profq_msgs: Vec<ProfileQueriesMsg> = vec![];
  67     let mut frame: StackFrame = StackFrame { parse_st: ParseState::Clear, traces: vec![] };
  68     let mut stack: Vec<StackFrame> = vec![];
  69     loop {
  70         let msg = r.recv();
  71         if let Err(_recv_err) = msg {
  72             // FIXME: Perhaps do something smarter than simply quitting?
  73             break
  74         };
  75         let msg = msg.unwrap();
  76         debug!("profile_queries_thread: {:?}", msg);
  77
  78         // Meta-level versus _actual_ queries messages
  79         match msg {
  80             ProfileQueriesMsg::Halt => return,
  81             ProfileQueriesMsg::Dump(params) => {
  82                 assert!(stack.is_empty());
  83                 assert!(frame.parse_st == ParseState::Clear);
  84
  85                 // write log of all messages
  86                 if params.dump_profq_msg_log {
  87                     let mut log_file =
  88                         File::create(format!("{}.log.txt", params.path)).unwrap();
  89                     for m in profq_msgs.iter() {
  90                         writeln!(&mut log_file, "{:?}", m).unwrap()
  91                     };
  92                 }
  93
  94                 // write HTML file, and counts file
  95                 let html_path = format!("{}.html", params.path);
  96                 let mut html_file = File::create(&html_path).unwrap();
  97
  98                 let counts_path = format!("{}.counts.txt", params.path);
  99                 let mut counts_file = File::create(&counts_path).unwrap();
 100
 101                 writeln!(html_file,
 102                     "<html>\n<head>\n<link rel=\"stylesheet\" type=\"text/css\" href=\"{}\">",
 103                     "profile_queries.css").unwrap();
 104                 writeln!(html_file, "<style>").unwrap();
 105                 trace::write_style(&mut html_file);
 106                 writeln!(html_file, "</style>\n</head>\n<body>").unwrap();
 107                 trace::write_traces(&mut html_file, &mut counts_file, &frame.traces);
 108                 writeln!(html_file, "</body>\n</html>").unwrap();
 109
 110                 let ack_path = format!("{}.ack", params.path);
 111                 let ack_file = File::create(&ack_path).unwrap();
 112                 drop(ack_file);
 113
 114                 // Tell main thread that we are done, e.g., so it can exit
 115                 params.ack.send(()).unwrap();
 116             }
 117             // Actual query message:
 118             msg => {
 119                 // Record msg in our log
 120                 profq_msgs.push(msg.clone());
 121                 // Respond to the message, knowing that we've already handled Halt and Dump, above.
 122                 match (frame.parse_st.clone(), msg) {
 123                     (_, ProfileQueriesMsg::Halt) | (_, ProfileQueriesMsg::Dump(_)) => {
 124                         unreachable!();
 125                     },
 126                     // Parse State: Clear
 127                     (ParseState::Clear,
 128                      ProfileQueriesMsg::QueryBegin(span, querymsg)) => {
 129                         let start = Instant::now();
 130                         frame.parse_st = ParseState::HaveQuery
 131                             (Query { span, msg: querymsg }, start)
 132                     },
 133                     (ParseState::Clear,
 134                      ProfileQueriesMsg::CacheHit) => {
 135                         panic!("parse error: unexpected CacheHit; expected QueryBegin")
 136                     },
 137                     (ParseState::Clear,
 138                      ProfileQueriesMsg::ProviderBegin) => {
 139                         panic!("parse error: expected QueryBegin before beginning a provider")
 140                     },
 141                     (ParseState::Clear,
 142                      ProfileQueriesMsg::ProviderEnd) => {
 143                         let provider_extent = frame.traces;
 144                         match stack.pop() {
 145                             None =>
 146                                 panic!("parse error: expected a stack frame; found an empty stack"),
 147                             Some(old_frame) => {
 148                                 match old_frame.parse_st {
 149                                     ParseState::HaveQuery(q, start) => {
 150                                         let duration = start.elapsed();
 151                                         frame = StackFrame{
 152                                             parse_st: ParseState::Clear,
 153                                             traces: old_frame.traces
 154                                         };
 155                                         let dur_extent = total_duration(&provider_extent);
 156                                         let trace = Rec {
 157                                             effect: Effect::QueryBegin(q, CacheCase::Miss),
 158                                             extent: Box::new(provider_extent),
 159                                             start: start,
 160                                             dur_self: duration - dur_extent,
 161                                             dur_total: duration,
 162                                         };
 163                                         frame.traces.push( trace );
 164                                     },
 165                                     _ => panic!("internal parse error: malformed parse stack")
 166                                 }
 167                             }
 168                         }
 169                     },
 170                     (ParseState::Clear,
 171                      ProfileQueriesMsg::TimeBegin(msg)) => {
 172                         let start = Instant::now();
 173                         frame.parse_st = ParseState::HaveTimeBegin(msg, start);
 174                         stack.push(frame);
 175                         frame = StackFrame{parse_st: ParseState::Clear, traces: vec![]};
 176                     },
 177                     (_, ProfileQueriesMsg::TimeBegin(_)) => {
 178                         panic!("parse error; did not expect time begin here");
 179                     },
 180                     (ParseState::Clear,
 181                      ProfileQueriesMsg::TimeEnd) => {
 182                         let provider_extent = frame.traces;
 183                         match stack.pop() {
 184                             None =>
 185                                 panic!("parse error: expected a stack frame; found an empty stack"),
 186                             Some(old_frame) => {
 187                                 match old_frame.parse_st {
 188                                     ParseState::HaveTimeBegin(msg, start) => {
 189                                         let duration = start.elapsed();
 190                                         frame = StackFrame{
 191                                             parse_st: ParseState::Clear,
 192                                             traces: old_frame.traces
 193                                         };
 194                                         let dur_extent = total_duration(&provider_extent);
 195                                         let trace = Rec {
 196                                             effect: Effect::TimeBegin(msg),
 197                                             extent: Box::new(provider_extent),
 198                                             start: start,
 199                                             dur_total: duration,
 200                                             dur_self: duration - dur_extent,
 201                                         };
 202                                         frame.traces.push( trace );
 203                                     },
 204                                     _ => panic!("internal parse error: malformed parse stack")
 205                                 }
 206                             }
 207                         }
 208                     },
 209                     (_, ProfileQueriesMsg::TimeEnd) => {
 210                         panic!("parse error")
 211                     },
 212                     (ParseState::Clear,
 213                      ProfileQueriesMsg::TaskBegin(key)) => {
 214                         let start = Instant::now();
 215                         frame.parse_st = ParseState::HaveTaskBegin(key, start);
 216                         stack.push(frame);
 217                         frame = StackFrame{ parse_st: ParseState::Clear, traces: vec![] };
 218                     },
 219                     (_, ProfileQueriesMsg::TaskBegin(_)) => {
 220                         panic!("parse error; did not expect time begin here");
 221                     },
 222                     (ParseState::Clear,
 223                      ProfileQueriesMsg::TaskEnd) => {
 224                         let provider_extent = frame.traces;
 225                         match stack.pop() {
 226                             None =>
 227                                 panic!("parse error: expected a stack frame; found an empty stack"),
 228                             Some(old_frame) => {
 229                                 match old_frame.parse_st {
 230                                     ParseState::HaveTaskBegin(key, start) => {
 231                                         let duration = start.elapsed();
 232                                         frame = StackFrame{
 233                                             parse_st: ParseState::Clear,
 234                                             traces: old_frame.traces
 235                                         };
 236                                         let dur_extent = total_duration(&provider_extent);
 237                                         let trace = Rec {
 238                                             effect: Effect::TaskBegin(key),
 239                                             extent: Box::new(provider_extent),
 240                                             start: start,
 241                                             dur_total: duration,
 242                                             dur_self: duration - dur_extent,
 243                                         };
 244                                         frame.traces.push( trace );
 245                                     },
 246                                     _ => panic!("internal parse error: malformed parse stack")
 247                                 }
 248                             }
 249                         }
 250                     },
 251                     (_, ProfileQueriesMsg::TaskEnd) => {
 252                         panic!("parse error")
 253                     },
 254                     // Parse State: HaveQuery
 255                     (ParseState::HaveQuery(q,start),
 256                      ProfileQueriesMsg::CacheHit) => {
 257                         let duration = start.elapsed();
 258                         let trace : Rec = Rec{
 259                             effect: Effect::QueryBegin(q, CacheCase::Hit),
 260                             extent: Box::new(vec![]),
 261                             start: start,
 262                             dur_self: duration,
 263                             dur_total: duration,
 264                         };
 265                         frame.traces.push( trace );
 266                         frame.parse_st = ParseState::Clear;
 267                     },
 268                     (ParseState::HaveQuery(_, _),
 269                      ProfileQueriesMsg::ProviderBegin) => {
 270                         stack.push(frame);
 271                         frame = StackFrame{ parse_st: ParseState::Clear, traces: vec![] };
 272                     },
 273
 274                     // Parse errors:
 275
 276                     (ParseState::HaveQuery(q, _),
 277                      ProfileQueriesMsg::ProviderEnd) => {
 278                         panic!("parse error: unexpected ProviderEnd; \
 279                                 expected something else to follow BeginQuery for {:?}", q)
 280                     },
 281                     (ParseState::HaveQuery(q1, _),
 282                      ProfileQueriesMsg::QueryBegin(span2, querymsg2)) => {
 283                         panic!("parse error: unexpected QueryBegin; \
 284                                 earlier query is unfinished: {:?} and now {:?}",
 285                                q1, Query{span:span2, msg: querymsg2})
 286                     },
 287                     (ParseState::HaveTimeBegin(_, _), _) => {
 288                         unreachable!()
 289                     },
 290                     (ParseState::HaveTaskBegin(_, _), _) => {
 291                         unreachable!()
 292                     },
 293                 }
 294             }
 295         }
 296     }
 297 }