[rustc.git] / src / librustc_driver / profile / mod.rs

// Copyright 2012-2015 The Rust Project Developers. See the COPYRIGHT
// file at the top-level directory of this distribution and at
// http://rust-lang.org/COPYRIGHT.
//
// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
// option. This file may not be copied, modified, or distributed
// except according to those terms.

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 rustc::dep_graph::{DepNode};
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: &Vec<trace::Rec>) -> 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<ProfileQueriesMsg>) {
    use self::trace::*;
    use std::fs::File;
    use std::time::{Instant};

    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.len() == 0);
                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();

                    write!(html_file, "<html>\n").unwrap();
                    write!(html_file,
                           "<head>\n<link rel=\"stylesheet\" type=\"text/css\" href=\"{}\">\n",
                           "profile_queries.css").unwrap();
                    write!(html_file, "<style>\n").unwrap();
                    trace::write_style(&mut html_file);
                    write!(html_file, "</style>\n").unwrap();
                    write!(html_file, "</head>\n").unwrap();
                    write!(html_file, "<body>\n").unwrap();
                    trace::write_traces(&mut html_file, &mut counts_file, &frame.traces);
                    write!(html_file, "</body>\n</html>\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();
                }
                continue
            }
            // 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) => unreachable!(),
                    (_,ProfileQueriesMsg::Dump(_)) => unreachable!(),

                    // Parse State: Clear
                    (ParseState::Clear,
                     ProfileQueriesMsg::QueryBegin(span,querymsg)) => {
                        let start = Instant::now();
                        frame.parse_st = ParseState::HaveQuery
                            (Query{span: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!()
                    },
                }

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