languages/rust
languages/rust
1
0
Fork 0
mirror of https://github.com/rust-lang/rust synced 2024-09-15 22:50:55 +00:00
Code Issues Packages Projects Releases Wiki Activity

Remove profiler output and replace with a raw event dump

Browse source 
Related to #58372
This commit is contained in:
Wesley Wiser 2019-02-11 18:11:43 -05:00
parent 25b8c614f0
commit fccc84199c
4 changed files with 268 additions and 326 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

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

@ -1405,9 +1405,7 @@ fn parse_merge_functions(slot: &mut Option<MergeFunctions>, v: Option<&str>) ->
crate_attr: Vec<String> = (Vec::new(), parse_string_push, [TRACKED], crate_attr: Vec<String> = (Vec::new(), parse_string_push, [TRACKED],
"inject the given attribute in the crate"), "inject the given attribute in the crate"),
self_profile: bool = (false, parse_bool, [UNTRACKED], self_profile: bool = (false, parse_bool, [UNTRACKED],
"run the self profiler"), "run the self profiler and output the raw event data"),
profile_json: bool = (false, parse_bool, [UNTRACKED],
"output a json file with profiler results"),
emit_stack_sizes: bool = (false, parse_bool, [UNTRACKED], emit_stack_sizes: bool = (false, parse_bool, [UNTRACKED],
"emits a section containing stack size metadata"), "emits a section containing stack size metadata"),
plt: Option<bool> = (None, parse_opt_bool, [TRACKED], plt: Option<bool> = (None, parse_opt_bool, [TRACKED],

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

@ -1131,11 +1131,8 @@ pub fn build_session_(
source_map: Lrc<source_map::SourceMap>, source_map: Lrc<source_map::SourceMap>,
driver_lint_caps: FxHashMap<lint::LintId, lint::Level>, driver_lint_caps: FxHashMap<lint::LintId, lint::Level>,
) -> Session { ) -> Session {
let self_profiling_active = sopts.debugging_opts.self_profile ||
sopts.debugging_opts.profile_json;
let self_profiler = let self_profiler =
if self_profiling_active { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) } if sopts.debugging_opts.self_profile { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) }
else { None }; else { None };
let host_triple = TargetTriple::from_triple(config::host_triple()); let host_triple = TargetTriple::from_triple(config::host_triple());

578
src/librustc/util/profiling.rs
View file

@ -1,10 +1,12 @@
use std::collections::{BTreeMap, HashMap}; use std::collections::HashMap;
use std::fs; use std::fs;
use std::io::{self, Write}; use std::io::{BufWriter, Write};
use std::mem;
use std::process;
use std::thread::ThreadId; use std::thread::ThreadId;
use std::time::Instant; use std::time::Instant;
use crate::session::config::{Options, OptLevel}; use crate::session::config::Options;
#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)] #[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
pub enum ProfileCategory { pub enum ProfileCategory {
@ -23,142 +25,41 @@ pub enum ProfilerEvent {
QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
GenericActivityStart { category: ProfileCategory, time: Instant }, GenericActivityStart { category: ProfileCategory, time: Instant },
GenericActivityEnd { category: ProfileCategory, time: Instant }, GenericActivityEnd { category: ProfileCategory, time: Instant },
QueryCacheHit { query_name: &'static str, category: ProfileCategory },
QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
IncrementalLoadResultStart { query_name: &'static str, time: Instant }, IncrementalLoadResultStart { query_name: &'static str, time: Instant },
IncrementalLoadResultEnd { query_name: &'static str, time: Instant }, IncrementalLoadResultEnd { query_name: &'static str, time: Instant },
QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: Instant },
QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: Instant },
QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant }, QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant },
QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant }, QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
} }
impl ProfilerEvent { impl ProfilerEvent {
fn is_start_event(&self) -> bool { fn timestamp(&self) -> Instant {
use self::ProfilerEvent::*; use self::ProfilerEvent::*;
match self { match self {
QueryStart { .. } | QueryStart { time, .. } |
GenericActivityStart { .. } | QueryEnd { time, .. } |
IncrementalLoadResultStart { .. } | GenericActivityStart { time, .. } |
QueryBlockedStart { .. } => true, GenericActivityEnd { time, .. } |
QueryCacheHit { time, .. } |
QueryEnd { .. } | QueryCount { time, .. } |
GenericActivityEnd { .. } | IncrementalLoadResultStart { time, .. } |
QueryCacheHit { .. } | IncrementalLoadResultEnd { time, .. } |
QueryCount { .. } | QueryBlockedStart { time, .. } |
IncrementalLoadResultEnd { .. } | QueryBlockedEnd { time, .. } => *time
QueryBlockedEnd { .. } => false,
} }
} }
} }
fn thread_id_to_u64(tid: ThreadId) -> u64 {
unsafe { mem::transmute::<ThreadId, u64>(tid) }
}
pub struct SelfProfiler { pub struct SelfProfiler {
events: HashMap<ThreadId, Vec<ProfilerEvent>>, events: HashMap<ThreadId, Vec<ProfilerEvent>>,
} }
struct CategoryResultData {
query_times: BTreeMap<&'static str, u64>,
query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total)
}
impl CategoryResultData {
fn new() -> CategoryResultData {
CategoryResultData {
query_times: BTreeMap::new(),
query_cache_stats: BTreeMap::new(),
}
}
fn total_time(&self) -> u64 {
self.query_times.iter().map(|(_, time)| time).sum()
}
fn total_cache_data(&self) -> (u64, u64) {
let (mut hits, mut total) = (0, 0);
for (_, (h, t)) in &self.query_cache_stats {
hits += h;
total += t;
}
(hits, total)
}
}
impl Default for CategoryResultData {
fn default() -> CategoryResultData {
CategoryResultData::new()
}
}
struct CalculatedResults {
categories: BTreeMap<ProfileCategory, CategoryResultData>,
crate_name: Option<String>,
optimization_level: OptLevel,
incremental: bool,
verbose: bool,
}
impl CalculatedResults {
fn new() -> CalculatedResults {
CalculatedResults {
categories: BTreeMap::new(),
crate_name: None,
optimization_level: OptLevel::No,
incremental: false,
verbose: false,
}
}
fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults {
for (category, data) in cr2.categories {
let cr1_data = cr1.categories.entry(category).or_default();
for (query, time) in data.query_times {
*cr1_data.query_times.entry(query).or_default() += time;
}
for (query, (hits, total)) in data.query_cache_stats {
let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0));
*h += hits;
*t += total;
}
}
cr1
}
fn total_time(&self) -> u64 {
self.categories.iter().map(|(_, data)| data.total_time()).sum()
}
fn with_options(mut self, opts: &Options) -> CalculatedResults {
self.crate_name = opts.crate_name.clone();
self.optimization_level = opts.optimize;
self.incremental = opts.incremental.is_some();
self.verbose = opts.debugging_opts.verbose;
self
}
}
fn time_between_ns(start: Instant, end: Instant) -> u64 {
if start < end {
let time = end - start;
(time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64)
} else {
debug!("time_between_ns: ignorning instance of end < start");
0
}
}
fn calculate_percent(numerator: u64, denominator: u64) -> f32 {
if denominator > 0 {
((numerator as f32) / (denominator as f32)) * 100.0
} else {
0.0
}
}
impl SelfProfiler { impl SelfProfiler {
pub fn new() -> SelfProfiler { pub fn new() -> SelfProfiler {
let mut profiler = SelfProfiler { let mut profiler = SelfProfiler {
@ -197,6 +98,7 @@ pub fn record_computed_queries(
query_name, query_name,
category, category,
count, count,
time: Instant::now(),
}) })
} }
@ -205,6 +107,7 @@ pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCa
self.record(ProfilerEvent::QueryCacheHit { self.record(ProfilerEvent::QueryCacheHit {
query_name, query_name,
category, category,
time: Instant::now(),
}) })
} }
@ -268,208 +171,257 @@ fn record(&mut self, event: ProfilerEvent) {
events.push(event); events.push(event);
} }
fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults { pub fn dump_raw_events(&self, opts: &Options) {
use self::ProfilerEvent::*; use self::ProfilerEvent::*;
assert!( //find the earliest Instant to use as t=0
events.last().map(|e| !e.is_start_event()).unwrap_or(true), //when serializing the events, we'll calculate a Duration
"there was an event running when calculate_reslts() was called" //using (instant - min_instant)
); let min_instant =
self.events
.iter()
.map(|(_, values)| values[0].timestamp())
.min()
.unwrap();
let mut results = CalculatedResults::new(); let pid = process::id();
//(event, child time to subtract) let filename =
let mut query_stack = Vec::new(); format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default());
for event in events { let mut file = BufWriter::new(fs::File::create(filename).unwrap());
match event {
QueryStart { .. } | GenericActivityStart { .. } => { let threads: Vec<_> =
query_stack.push((event, 0)); self.events
}, .keys()
QueryEnd { query_name, category, time: end_time } => { .into_iter()
let previous_query = query_stack.pop(); .map(|tid| format!("{}", thread_id_to_u64(*tid)))
if let Some((QueryStart { .collect();
query_name: p_query_name,
time: start_time, write!(file,
category: _ }, child_time_to_subtract)) = previous_query { "{{\
assert_eq!( \"processes\": {{\
p_query_name, \"{}\": {{\
\"threads\": [{}],\
\"crate_name\": \"{}\",\
\"opt_level\": \"{:?}\",\
\"incremental\": {}\
}}\
}},\
\"events\": [\
",
pid,
threads.join(","),
opts.crate_name.clone().unwrap_or_default(),
opts.optimize,
if opts.incremental.is_some() { "true" } else { "false" },
).unwrap();
let mut is_first = true;
for (thread_id, events) in &self.events {
let thread_id = thread_id_to_u64(*thread_id);
for event in events {
if is_first {
is_first = false;
} else {
writeln!(file, ",").unwrap();
}
let (secs, nanos) = {
let duration = event.timestamp() - min_instant;
(duration.as_secs(), duration.subsec_nanos())
};
match event {
QueryStart { query_name, category, time: _ } =>
write!(file,
"{{ \
\"QueryStart\": {{ \
\"query_name\": \"{}\",\
\"category\": \"{:?}\",\
\"time\": {{\
\"secs\": {},\
\"nanos\": {}\
}},\
\"thread_id\": {}\
}}\
}}",
query_name, query_name,
"Saw a query end but the previous query wasn't the corresponding start"
);
let time_ns = time_between_ns(*start_time, *end_time);
let self_time_ns = time_ns - child_time_to_subtract;
let result_data = results.categories.entry(*category).or_default();
*result_data.query_times.entry(query_name).or_default() += self_time_ns;
if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
*child_time_to_subtract += time_ns;
}
} else {
bug!("Saw a query end but the previous event wasn't a query start");
}
}
GenericActivityEnd { category, time: end_time } => {
let previous_event = query_stack.pop();
if let Some((GenericActivityStart {
category: previous_category,
time: start_time }, child_time_to_subtract)) = previous_event {
assert_eq!(
previous_category,
category, category,
"Saw an end but the previous event wasn't the corresponding start" secs,
); nanos,
thread_id,
let time_ns = time_between_ns(*start_time, *end_time); ).unwrap(),
let self_time_ns = time_ns - child_time_to_subtract; QueryEnd { query_name, category, time: _ } =>
let result_data = results.categories.entry(*category).or_default(); write!(file,
"{{\
*result_data.query_times \"QueryEnd\": {{\
.entry("{time spent not running queries}") \"query_name\": \"{}\",\
.or_default() += self_time_ns; \"category\": \"{:?}\",\
\"time\": {{\
if let Some((_, child_time_to_subtract)) = query_stack.last_mut() { \"secs\": {},\
*child_time_to_subtract += time_ns; \"nanos\": {}\
} }},\
} else { \"thread_id\": {}\
bug!("Saw an activity end but the previous event wasn't an activity start"); }}\
} }}",
}, query_name,
QueryCacheHit { category, query_name } => { category,
let result_data = results.categories.entry(*category).or_default(); secs,
nanos,
let (hits, total) = thread_id,
result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); ).unwrap(),
*hits += 1; GenericActivityStart { category, time: _ } =>
*total += 1; write!(file,
}, "{{
QueryCount { category, query_name, count } => { \"GenericActivityStart\": {{\
let result_data = results.categories.entry(*category).or_default(); \"category\": \"{:?}\",\
\"time\": {{\
let (_, totals) = \"secs\": {},\
result_data.query_cache_stats.entry(query_name).or_insert((0, 0)); \"nanos\": {}\
*totals += *count as u64; }},\
}, \"thread_id\": {}\
//we don't summarize incremental load result events in the simple output mode }}\
IncrementalLoadResultStart { .. } | IncrementalLoadResultEnd { .. } => { }, }}",
//we don't summarize parallel query blocking in the simple output mode category,
QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { }, secs,
} nanos,
} thread_id,
).unwrap(),
//normalize the times to ms GenericActivityEnd { category, time: _ } =>
for (_, data) in &mut results.categories { write!(file,
for (_, time) in &mut data.query_times { "{{\
*time = *time / 1_000_000; \"GenericActivityEnd\": {{\
} \"category\": \"{:?}\",\
} \"time\": {{\
\"secs\": {},\
results \"nanos\": {}\
} }},\
\"thread_id\": {}\
fn get_results(&self, opts: &Options) -> CalculatedResults { }}\
self.events }}",
.iter() category,
.map(|(_, r)| SelfProfiler::calculate_thread_results(r)) secs,
.fold(CalculatedResults::new(), CalculatedResults::consolidate) nanos,
.with_options(opts) thread_id,
} ).unwrap(),
QueryCacheHit { query_name, category, time: _ } =>
pub fn print_results(&mut self, opts: &Options) { write!(file,
self.end_activity(ProfileCategory::Other); "{{\
\"QueryCacheHit\": {{\
let results = self.get_results(opts); \"query_name\": \"{}\",\
\"category\": \"{:?}\",\
let total_time = results.total_time() as f32; \"time\": {{\
\"secs\": {},\
let out = io::stderr(); \"nanos\": {}\
let mut lock = out.lock(); }},\
\"thread_id\": {}\
let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default(); }}\
}}",
writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); query_name,
writeln!(lock).unwrap(); category,
secs,
writeln!(lock, "| Phase | Time (ms) \ nanos,
| Time (%) | Queries | Hits (%)") thread_id,
.unwrap(); ).unwrap(),
writeln!(lock, "| ----------------------------------------- | -------------- \ QueryCount { query_name, category, count, time: _ } =>
| -------- | -------------- | --------") write!(file,
.unwrap(); "{{\
\"QueryCount\": {{\
let mut categories: Vec<_> = results.categories.iter().collect(); \"query_name\": \"{}\",\
categories.sort_by_cached_key(|(_, d)| d.total_time()); \"category\": \"{:?}\",\
\"count\": {},\
for (category, data) in categories.iter().rev() { \"time\": {{\
let (category_hits, category_total) = data.total_cache_data(); \"secs\": {},\
let category_hit_percent = calculate_percent(category_hits, category_total); \"nanos\": {}\
}},\
writeln!( \"thread_id\": {}\
lock, }}\
"| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", }}",
format!("{:?}", category), query_name,
data.total_time(), category,
((data.total_time() as f32) / total_time) * 100.0, count,
category_total, secs,
format!("{:.2}", category_hit_percent), nanos,
).unwrap(); thread_id,
).unwrap(),
//in verbose mode, show individual query data IncrementalLoadResultStart { query_name, time: _ } =>
if results.verbose { write!(file,
//don't show queries that took less than 1ms "{{\
let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect(); \"IncrementalLoadResultStart\": {{\
times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1)); \"query_name\": \"{}\",\
\"time\": {{\
for (query, time) in times { \"secs\": {},\
let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0)); \"nanos\": {}\
let hit_percent = calculate_percent(*hits, *total); }},\
\"thread_id\": {}\
writeln!( }}\
lock, }}",
"| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}", query_name,
query, secs,
time, nanos,
((*time as f32) / total_time) * 100.0, thread_id,
total, ).unwrap(),
format!("{:.2}", hit_percent), IncrementalLoadResultEnd { query_name, time: _ } =>
).unwrap(); write!(file,
"{{\
\"IncrementalLoadResultEnd\": {{\
\"query_name\": \"{}\",\
\"time\": {{\
\"secs\": {},\
\"nanos\": {}\
}},\
\"thread_id\": {}\
}}\
}}",
query_name,
secs,
nanos,
thread_id,
).unwrap(),
QueryBlockedStart { query_name, category, time: _ } =>
write!(file,
"{{\
\"QueryBlockedStart\": {{\
\"query_name\": \"{}\",\
\"category\": \"{:?}\",\
\"time\": {{\
\"secs\": {},\
\"nanos\": {}\
}},\
\"thread_id\": {}\
}}\
}}",
query_name,
category,
secs,
nanos,
thread_id,
).unwrap(),
QueryBlockedEnd { query_name, category, time: _ } =>
write!(file,
"{{\
\"QueryBlockedEnd\": {{\
\"query_name\": \"{}\",\
\"category\": \"{:?}\",\
\"time\": {{\
\"secs\": {},\
\"nanos\": {}\
}},\
\"thread_id\": {}\
}}\
}}",
query_name,
category,
secs,
nanos,
thread_id,
).unwrap()
} }
} }
} }
writeln!(lock).unwrap(); write!(file, "] }}").unwrap();
writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap();
}
pub fn save_results(&self, opts: &Options) {
let results = self.get_results(opts);
let compilation_options =
format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
results.optimization_level,
if results.incremental { "true" } else { "false" });
let mut category_data = String::new();
for (category, data) in &results.categories {
let (hits, total) = data.total_cache_data();
let hit_percent = calculate_percent(hits, total);
category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \
\"query_count\": {}, \"query_hits\": {} }}",
category,
data.total_time(),
total,
format!("{:.2}", hit_percent)));
}
let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
category_data,
compilation_options);
fs::write("self_profiler_results.json", json).unwrap();
} }
} }

7
src/librustc_driver/lib.rs
View file

@ -276,13 +276,8 @@ macro_rules! do_or_return {($expr: expr, $sess: expr) => {
&control) &control)
}; };
if sess.opts.debugging_opts.self_profile { if sess.opts.debugging_opts.self_profile {
sess.profiler(|p| p.print_results(&sess.opts)); sess.profiler(|p| p.dump_raw_events(&sess.opts));
}
if sess.opts.debugging_opts.profile_json {
sess.profiler(|p| p.save_results(&sess.opts));
} }
(result, Some(sess)) (result, Some(sess))