mirror of
https://github.com/rust-lang/rust
synced 2024-09-06 01:11:17 +00:00
Auto merge of #58425 - wesleywiser:more_profiler_changes, r=michaelwoerister
[self-profiler] Make the profiler faster/more efficient Related to #58372 r? @michaelwoerister
This commit is contained in:
bors
commit
87a436377a
|
|
@ -2625,6 +2625,7 @@ dependencies = [
|
|||
"log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)",
|
||||
"memmap 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)",
|
||||
"num_cpus 1.8.0 (registry+https://github.com/rust-lang/crates.io-index)",
|
||||
"parking_lot 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)",
|
||||
"rustc 0.0.0",
|
||||
"rustc-demangle 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)",
|
||||
"rustc_allocator 0.0.0",
|
||||
|
|
|
|||
|
|
@ -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],
|
||||
"inject the given attribute in the crate"),
|
||||
self_profile: bool = (false, parse_bool, [UNTRACKED],
|
||||
"run the self profiler"),
|
||||
profile_json: bool = (false, parse_bool, [UNTRACKED],
|
||||
"output a json file with profiler results"),
|
||||
"run the self profiler and output the raw event data"),
|
||||
emit_stack_sizes: bool = (false, parse_bool, [UNTRACKED],
|
||||
"emits a section containing stack size metadata"),
|
||||
plt: Option<bool> = (None, parse_opt_bool, [TRACKED],
|
||||
|
|
|
|||
|
|
@ -44,7 +44,9 @@
|
|||
use std::io::Write;
|
||||
use std::path::PathBuf;
|
||||
use std::time::Duration;
|
||||
use std::sync::mpsc;
|
||||
use std::sync::{Arc, mpsc};
|
||||
|
||||
use parking_lot::Mutex as PlMutex;
|
||||
|
||||
mod code_stats;
|
||||
pub mod config;
|
||||
|
|
@ -127,11 +129,8 @@ pub struct Session {
|
|||
/// Used by `-Z profile-queries` in `util::common`.
|
||||
pub profile_channel: Lock<Option<mpsc::Sender<ProfileQueriesMsg>>>,
|
||||
|
||||
/// Used by `-Z self-profile`.
|
||||
pub self_profiling_active: bool,
|
||||
|
||||
/// Used by `-Z self-profile`.
|
||||
pub self_profiling: Lock<SelfProfiler>,
|
||||
/// Used by -Z self-profile
|
||||
pub self_profiling: Option<Arc<PlMutex<SelfProfiler>>>,
|
||||
|
||||
/// Some measurements that are being gathered during compilation.
|
||||
pub perf_stats: PerfStats,
|
||||
|
|
@ -834,27 +833,23 @@ pub fn incr_comp_session_dir_opt(&self) -> Option<cell::Ref<'_, PathBuf>> {
|
|||
#[inline(never)]
|
||||
#[cold]
|
||||
fn profiler_active<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) {
|
||||
let mut profiler = self.self_profiling.borrow_mut();
|
||||
f(&mut profiler);
|
||||
match &self.self_profiling {
|
||||
None => bug!("profiler_active() called but there was no profiler active"),
|
||||
Some(profiler) => {
|
||||
let mut p = profiler.lock();
|
||||
|
||||
f(&mut p);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[inline(always)]
|
||||
pub fn profiler<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) {
|
||||
if unlikely!(self.self_profiling_active) {
|
||||
if unlikely!(self.self_profiling.is_some()) {
|
||||
self.profiler_active(f)
|
||||
}
|
||||
}
|
||||
|
||||
pub fn print_profiler_results(&self) {
|
||||
let mut profiler = self.self_profiling.borrow_mut();
|
||||
profiler.print_results(&self.opts);
|
||||
}
|
||||
|
||||
pub fn save_json_results(&self) {
|
||||
let profiler = self.self_profiling.borrow();
|
||||
profiler.save_results(&self.opts);
|
||||
}
|
||||
|
||||
pub fn print_perf_stats(&self) {
|
||||
println!(
|
||||
"Total time spent computing symbol hashes: {}",
|
||||
|
|
@ -1136,6 +1131,10 @@ pub fn build_session_(
|
|||
source_map: Lrc<source_map::SourceMap>,
|
||||
driver_lint_caps: FxHashMap<lint::LintId, lint::Level>,
|
||||
) -> Session {
|
||||
let self_profiler =
|
||||
if sopts.debugging_opts.self_profile { Some(Arc::new(PlMutex::new(SelfProfiler::new()))) }
|
||||
else { None };
|
||||
|
||||
let host_triple = TargetTriple::from_triple(config::host_triple());
|
||||
let host = Target::search(&host_triple).unwrap_or_else(|e|
|
||||
span_diagnostic
|
||||
|
|
@ -1185,9 +1184,6 @@ pub fn build_session_(
|
|||
CguReuseTracker::new_disabled()
|
||||
};
|
||||
|
||||
let self_profiling_active = sopts.debugging_opts.self_profile ||
|
||||
sopts.debugging_opts.profile_json;
|
||||
|
||||
let sess = Session {
|
||||
target: target_cfg,
|
||||
host,
|
||||
|
|
@ -1216,8 +1212,7 @@ pub fn build_session_(
|
|||
imported_macro_spans: OneThread::new(RefCell::new(FxHashMap::default())),
|
||||
incr_comp_session: OneThread::new(RefCell::new(IncrCompSession::NotInitialized)),
|
||||
cgu_reuse_tracker,
|
||||
self_profiling_active,
|
||||
self_profiling: Lock::new(SelfProfiler::new()),
|
||||
self_profiling: self_profiler,
|
||||
profile_channel: Lock::new(None),
|
||||
perf_stats: PerfStats {
|
||||
symbol_hash_time: Lock::new(Duration::from_secs(0)),
|
||||
|
|
|
|||
|
|
@ -1,10 +1,13 @@
|
|||
use std::collections::{BTreeMap, HashMap};
|
||||
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::time::Instant;
|
||||
use std::time::{Duration, Instant, SystemTime};
|
||||
|
||||
use crate::session::config::{Options, OptLevel};
|
||||
use crate::session::config::Options;
|
||||
|
||||
use rustc_data_structures::fx::FxHashMap;
|
||||
|
||||
#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
|
||||
pub enum ProfileCategory {
|
||||
|
|
@ -19,154 +22,55 @@ pub enum ProfileCategory {
|
|||
|
||||
#[derive(Clone, Copy, Debug, Eq, PartialEq)]
|
||||
pub enum ProfilerEvent {
|
||||
QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant },
|
||||
QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
|
||||
GenericActivityStart { 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 },
|
||||
IncrementalLoadResultEnd { query_name: &'static str, time: Instant },
|
||||
QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: Instant },
|
||||
QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
|
||||
QueryStart { query_name: &'static str, category: ProfileCategory, time: u64 },
|
||||
QueryEnd { query_name: &'static str, category: ProfileCategory, time: u64 },
|
||||
GenericActivityStart { category: ProfileCategory, time: u64 },
|
||||
GenericActivityEnd { category: ProfileCategory, time: u64 },
|
||||
IncrementalLoadResultStart { query_name: &'static str, time: u64 },
|
||||
IncrementalLoadResultEnd { query_name: &'static str, time: u64 },
|
||||
QueryCacheHit { query_name: &'static str, category: ProfileCategory, time: u64 },
|
||||
QueryCount { query_name: &'static str, category: ProfileCategory, count: usize, time: u64 },
|
||||
QueryBlockedStart { query_name: &'static str, category: ProfileCategory, time: u64 },
|
||||
QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: u64 },
|
||||
}
|
||||
|
||||
impl ProfilerEvent {
|
||||
fn is_start_event(&self) -> bool {
|
||||
fn timestamp(&self) -> u64 {
|
||||
use self::ProfilerEvent::*;
|
||||
|
||||
match self {
|
||||
QueryStart { .. } |
|
||||
GenericActivityStart { .. } |
|
||||
IncrementalLoadResultStart { .. } |
|
||||
QueryBlockedStart { .. } => true,
|
||||
|
||||
QueryEnd { .. } |
|
||||
GenericActivityEnd { .. } |
|
||||
QueryCacheHit { .. } |
|
||||
QueryCount { .. } |
|
||||
IncrementalLoadResultEnd { .. } |
|
||||
QueryBlockedEnd { .. } => false,
|
||||
QueryStart { time, .. } |
|
||||
QueryEnd { time, .. } |
|
||||
GenericActivityStart { time, .. } |
|
||||
GenericActivityEnd { time, .. } |
|
||||
QueryCacheHit { time, .. } |
|
||||
QueryCount { time, .. } |
|
||||
IncrementalLoadResultStart { time, .. } |
|
||||
IncrementalLoadResultEnd { time, .. } |
|
||||
QueryBlockedStart { time, .. } |
|
||||
QueryBlockedEnd { time, .. } => *time
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn thread_id_to_u64(tid: ThreadId) -> u64 {
|
||||
unsafe { mem::transmute::<ThreadId, u64>(tid) }
|
||||
}
|
||||
|
||||
pub struct SelfProfiler {
|
||||
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
|
||||
}
|
||||
events: FxHashMap<ThreadId, Vec<ProfilerEvent>>,
|
||||
start_time: SystemTime,
|
||||
start_instant: Instant,
|
||||
}
|
||||
|
||||
impl SelfProfiler {
|
||||
pub fn new() -> SelfProfiler {
|
||||
let mut profiler = SelfProfiler {
|
||||
events: HashMap::new(),
|
||||
let profiler = SelfProfiler {
|
||||
events: Default::default(),
|
||||
start_time: SystemTime::now(),
|
||||
start_instant: Instant::now(),
|
||||
};
|
||||
|
||||
profiler.start_activity(ProfileCategory::Other);
|
||||
|
||||
profiler
|
||||
}
|
||||
|
||||
|
|
@ -174,7 +78,7 @@ pub fn new() -> SelfProfiler {
|
|||
pub fn start_activity(&mut self, category: ProfileCategory) {
|
||||
self.record(ProfilerEvent::GenericActivityStart {
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -182,7 +86,7 @@ pub fn start_activity(&mut self, category: ProfileCategory) {
|
|||
pub fn end_activity(&mut self, category: ProfileCategory) {
|
||||
self.record(ProfilerEvent::GenericActivityEnd {
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -197,6 +101,7 @@ pub fn record_computed_queries(
|
|||
query_name,
|
||||
category,
|
||||
count,
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -205,6 +110,7 @@ pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCa
|
|||
self.record(ProfilerEvent::QueryCacheHit {
|
||||
query_name,
|
||||
category,
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -213,7 +119,7 @@ pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategor
|
|||
self.record(ProfilerEvent::QueryStart {
|
||||
query_name,
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
});
|
||||
}
|
||||
|
||||
|
|
@ -222,7 +128,7 @@ pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory)
|
|||
self.record(ProfilerEvent::QueryEnd {
|
||||
query_name,
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -230,7 +136,7 @@ pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory)
|
|||
pub fn incremental_load_result_start(&mut self, query_name: &'static str) {
|
||||
self.record(ProfilerEvent::IncrementalLoadResultStart {
|
||||
query_name,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -238,7 +144,7 @@ pub fn incremental_load_result_start(&mut self, query_name: &'static str) {
|
|||
pub fn incremental_load_result_end(&mut self, query_name: &'static str) {
|
||||
self.record(ProfilerEvent::IncrementalLoadResultEnd {
|
||||
query_name,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -247,7 +153,7 @@ pub fn query_blocked_start(&mut self, query_name: &'static str, category: Profil
|
|||
self.record(ProfilerEvent::QueryBlockedStart {
|
||||
query_name,
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -256,7 +162,7 @@ pub fn query_blocked_end(&mut self, query_name: &'static str, category: ProfileC
|
|||
self.record(ProfilerEvent::QueryBlockedEnd {
|
||||
query_name,
|
||||
category,
|
||||
time: Instant::now(),
|
||||
time: self.get_time_from_start(),
|
||||
})
|
||||
}
|
||||
|
||||
|
|
@ -268,208 +174,255 @@ fn record(&mut self, event: ProfilerEvent) {
|
|||
events.push(event);
|
||||
}
|
||||
|
||||
fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
|
||||
#[inline]
|
||||
fn get_time_from_start(&self) -> u64 {
|
||||
let duration = Instant::now() - self.start_instant;
|
||||
duration.as_nanos() as u64
|
||||
}
|
||||
|
||||
pub fn dump_raw_events(&self, opts: &Options) {
|
||||
use self::ProfilerEvent::*;
|
||||
|
||||
assert!(
|
||||
events.last().map(|e| !e.is_start_event()).unwrap_or(true),
|
||||
"there was an event running when calculate_reslts() was called"
|
||||
);
|
||||
let pid = process::id();
|
||||
|
||||
let mut results = CalculatedResults::new();
|
||||
let filename =
|
||||
format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default());
|
||||
|
||||
//(event, child time to subtract)
|
||||
let mut query_stack = Vec::new();
|
||||
let mut file = BufWriter::new(fs::File::create(filename).unwrap());
|
||||
|
||||
for event in events {
|
||||
match event {
|
||||
QueryStart { .. } | GenericActivityStart { .. } => {
|
||||
query_stack.push((event, 0));
|
||||
},
|
||||
QueryEnd { query_name, category, time: end_time } => {
|
||||
let previous_query = query_stack.pop();
|
||||
if let Some((QueryStart {
|
||||
query_name: p_query_name,
|
||||
time: start_time,
|
||||
category: _ }, child_time_to_subtract)) = previous_query {
|
||||
assert_eq!(
|
||||
p_query_name,
|
||||
let threads: Vec<_> =
|
||||
self.events
|
||||
.keys()
|
||||
.into_iter()
|
||||
.map(|tid| format!("{}", thread_id_to_u64(*tid)))
|
||||
.collect();
|
||||
|
||||
write!(file,
|
||||
"{{\
|
||||
\"processes\": {{\
|
||||
\"{}\": {{\
|
||||
\"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 time = self.start_time + Duration::from_nanos(event.timestamp());
|
||||
let time_since_unix =
|
||||
time.duration_since(SystemTime::UNIX_EPOCH).unwrap_or_default();
|
||||
(time_since_unix.as_secs(), time_since_unix.subsec_nanos())
|
||||
};
|
||||
|
||||
match event {
|
||||
QueryStart { query_name, category, time: _ } =>
|
||||
write!(file,
|
||||
"{{ \
|
||||
\"QueryStart\": {{ \
|
||||
\"query_name\": \"{}\",\
|
||||
\"category\": \"{:?}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
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,
|
||||
"Saw an end but the previous event 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("{time spent not running queries}")
|
||||
.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 an activity end but the previous event wasn't an activity start");
|
||||
}
|
||||
},
|
||||
QueryCacheHit { category, query_name } => {
|
||||
let result_data = results.categories.entry(*category).or_default();
|
||||
|
||||
let (hits, total) =
|
||||
result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
|
||||
*hits += 1;
|
||||
*total += 1;
|
||||
},
|
||||
QueryCount { category, query_name, count } => {
|
||||
let result_data = results.categories.entry(*category).or_default();
|
||||
|
||||
let (_, totals) =
|
||||
result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
|
||||
*totals += *count as u64;
|
||||
},
|
||||
//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
|
||||
QueryBlockedStart { .. } | QueryBlockedEnd { .. } => { },
|
||||
}
|
||||
}
|
||||
|
||||
//normalize the times to ms
|
||||
for (_, data) in &mut results.categories {
|
||||
for (_, time) in &mut data.query_times {
|
||||
*time = *time / 1_000_000;
|
||||
}
|
||||
}
|
||||
|
||||
results
|
||||
}
|
||||
|
||||
fn get_results(&self, opts: &Options) -> CalculatedResults {
|
||||
self.events
|
||||
.iter()
|
||||
.map(|(_, r)| SelfProfiler::calculate_thread_results(r))
|
||||
.fold(CalculatedResults::new(), CalculatedResults::consolidate)
|
||||
.with_options(opts)
|
||||
}
|
||||
|
||||
pub fn print_results(&mut self, opts: &Options) {
|
||||
self.end_activity(ProfileCategory::Other);
|
||||
|
||||
let results = self.get_results(opts);
|
||||
|
||||
let total_time = results.total_time() as f32;
|
||||
|
||||
let out = io::stderr();
|
||||
let mut lock = out.lock();
|
||||
|
||||
let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default();
|
||||
|
||||
writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
|
||||
writeln!(lock).unwrap();
|
||||
|
||||
writeln!(lock, "| Phase | Time (ms) \
|
||||
| Time (%) | Queries | Hits (%)")
|
||||
.unwrap();
|
||||
writeln!(lock, "| ----------------------------------------- | -------------- \
|
||||
| -------- | -------------- | --------")
|
||||
.unwrap();
|
||||
|
||||
let mut categories: Vec<_> = results.categories.iter().collect();
|
||||
categories.sort_by_cached_key(|(_, d)| d.total_time());
|
||||
|
||||
for (category, data) in categories.iter().rev() {
|
||||
let (category_hits, category_total) = data.total_cache_data();
|
||||
let category_hit_percent = calculate_percent(category_hits, category_total);
|
||||
|
||||
writeln!(
|
||||
lock,
|
||||
"| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
|
||||
format!("{:?}", category),
|
||||
data.total_time(),
|
||||
((data.total_time() as f32) / total_time) * 100.0,
|
||||
category_total,
|
||||
format!("{:.2}", category_hit_percent),
|
||||
).unwrap();
|
||||
|
||||
//in verbose mode, show individual query data
|
||||
if results.verbose {
|
||||
//don't show queries that took less than 1ms
|
||||
let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect();
|
||||
times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1));
|
||||
|
||||
for (query, time) in times {
|
||||
let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0));
|
||||
let hit_percent = calculate_percent(*hits, *total);
|
||||
|
||||
writeln!(
|
||||
lock,
|
||||
"| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
|
||||
query,
|
||||
time,
|
||||
((*time as f32) / total_time) * 100.0,
|
||||
total,
|
||||
format!("{:.2}", hit_percent),
|
||||
).unwrap();
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
QueryEnd { query_name, category, time: _ } =>
|
||||
write!(file,
|
||||
"{{\
|
||||
\"QueryEnd\": {{\
|
||||
\"query_name\": \"{}\",\
|
||||
\"category\": \"{:?}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
query_name,
|
||||
category,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
GenericActivityStart { category, time: _ } =>
|
||||
write!(file,
|
||||
"{{
|
||||
\"GenericActivityStart\": {{\
|
||||
\"category\": \"{:?}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
category,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
GenericActivityEnd { category, time: _ } =>
|
||||
write!(file,
|
||||
"{{\
|
||||
\"GenericActivityEnd\": {{\
|
||||
\"category\": \"{:?}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
category,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
QueryCacheHit { query_name, category, time: _ } =>
|
||||
write!(file,
|
||||
"{{\
|
||||
\"QueryCacheHit\": {{\
|
||||
\"query_name\": \"{}\",\
|
||||
\"category\": \"{:?}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
query_name,
|
||||
category,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
QueryCount { query_name, category, count, time: _ } =>
|
||||
write!(file,
|
||||
"{{\
|
||||
\"QueryCount\": {{\
|
||||
\"query_name\": \"{}\",\
|
||||
\"category\": \"{:?}\",\
|
||||
\"count\": {},\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
query_name,
|
||||
category,
|
||||
count,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
IncrementalLoadResultStart { query_name, time: _ } =>
|
||||
write!(file,
|
||||
"{{\
|
||||
\"IncrementalLoadResultStart\": {{\
|
||||
\"query_name\": \"{}\",\
|
||||
\"time\": {{\
|
||||
\"secs\": {},\
|
||||
\"nanos\": {}\
|
||||
}},\
|
||||
\"thread_id\": {}\
|
||||
}}\
|
||||
}}",
|
||||
query_name,
|
||||
secs,
|
||||
nanos,
|
||||
thread_id,
|
||||
).unwrap(),
|
||||
IncrementalLoadResultEnd { query_name, time: _ } =>
|
||||
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();
|
||||
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();
|
||||
write!(file, "] }}").unwrap();
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -19,6 +19,7 @@ memmap = "0.6"
|
|||
log = "0.4.5"
|
||||
libc = "0.2.44"
|
||||
jobserver = "0.1.11"
|
||||
parking_lot = "0.7"
|
||||
|
||||
serialize = { path = "../libserialize" }
|
||||
syntax = { path = "../libsyntax" }
|
||||
|
|
|
|||
|
|
@ -19,6 +19,7 @@
|
|||
use rustc::hir::def_id::{CrateNum, LOCAL_CRATE};
|
||||
use rustc::ty::TyCtxt;
|
||||
use rustc::util::common::{time_depth, set_time_depth, print_time_passes_entry};
|
||||
use rustc::util::profiling::SelfProfiler;
|
||||
use rustc_fs_util::link_or_copy;
|
||||
use rustc_data_structures::svh::Svh;
|
||||
use rustc_errors::{Handler, Level, DiagnosticBuilder, FatalError, DiagnosticId};
|
||||
|
|
@ -29,6 +30,7 @@
|
|||
use syntax_pos::MultiSpan;
|
||||
use syntax_pos::symbol::Symbol;
|
||||
use jobserver::{Client, Acquired};
|
||||
use parking_lot::Mutex as PlMutex;
|
||||
|
||||
use std::any::Any;
|
||||
use std::fs;
|
||||
|
|
@ -201,6 +203,7 @@ pub struct CodegenContext<B: WriteBackendMethods> {
|
|||
// Resources needed when running LTO
|
||||
pub backend: B,
|
||||
pub time_passes: bool,
|
||||
pub profiler: Option<Arc<PlMutex<SelfProfiler>>>,
|
||||
pub lto: Lto,
|
||||
pub no_landing_pads: bool,
|
||||
pub save_temps: bool,
|
||||
|
|
@ -254,6 +257,26 @@ pub fn config(&self, kind: ModuleKind) -> &ModuleConfig {
|
|||
ModuleKind::Allocator => &self.allocator_module_config,
|
||||
}
|
||||
}
|
||||
|
||||
#[inline(never)]
|
||||
#[cold]
|
||||
fn profiler_active<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) {
|
||||
match &self.profiler {
|
||||
None => bug!("profiler_active() called but there was no profiler active"),
|
||||
Some(profiler) => {
|
||||
let mut p = profiler.lock();
|
||||
|
||||
f(&mut p);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[inline(always)]
|
||||
pub fn profile<F: FnOnce(&mut SelfProfiler) -> ()>(&self, f: F) {
|
||||
if unlikely!(self.profiler.is_some()) {
|
||||
self.profiler_active(f)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn generate_lto_work<B: ExtraBackendMethods>(
|
||||
|
|
@ -1033,6 +1056,7 @@ fn start_executing_work<B: ExtraBackendMethods>(
|
|||
save_temps: sess.opts.cg.save_temps,
|
||||
opts: Arc::new(sess.opts.clone()),
|
||||
time_passes: sess.time_passes(),
|
||||
profiler: sess.self_profiling.clone(),
|
||||
exported_symbols,
|
||||
plugin_passes: sess.plugin_llvm_passes.borrow().clone(),
|
||||
remark: sess.opts.cg.remark.clone(),
|
||||
|
|
|
|||
|
|
@ -2,9 +2,11 @@
|
|||
|
||||
#![feature(box_patterns)]
|
||||
#![feature(box_syntax)]
|
||||
#![feature(core_intrinsics)]
|
||||
#![feature(custom_attribute)]
|
||||
#![feature(libc)]
|
||||
#![feature(rustc_diagnostic_macros)]
|
||||
#![feature(stmt_expr_attributes)]
|
||||
#![feature(in_band_lifetimes)]
|
||||
#![feature(nll)]
|
||||
#![allow(unused_attributes)]
|
||||
|
|
@ -20,6 +22,7 @@
|
|||
|
||||
#[macro_use] extern crate log;
|
||||
#[macro_use] extern crate rustc;
|
||||
#[macro_use] extern crate rustc_data_structures;
|
||||
#[macro_use] extern crate syntax;
|
||||
|
||||
use std::path::PathBuf;
|
||||
|
|
|
|||
|
|
@ -349,14 +349,6 @@ macro_rules! controller_entry_point {
|
|||
sess.print_perf_stats();
|
||||
}
|
||||
|
||||
if sess.opts.debugging_opts.self_profile {
|
||||
sess.print_profiler_results();
|
||||
}
|
||||
|
||||
if sess.opts.debugging_opts.profile_json {
|
||||
sess.save_json_results();
|
||||
}
|
||||
|
||||
controller_entry_point!(
|
||||
compilation_done,
|
||||
sess,
|
||||
|
|
|
|||
|
|
@ -276,6 +276,10 @@ macro_rules! do_or_return {($expr: expr, $sess: expr) => {
|
|||
&control)
|
||||
};
|
||||
|
||||
if sess.opts.debugging_opts.self_profile {
|
||||
sess.profiler(|p| p.dump_raw_events(&sess.opts));
|
||||
}
|
||||
|
||||
(result, Some(sess))
|
||||
}
|
||||
|
||||
|
|
|
|||
Loading…
Reference in a new issue