-use std::collections::{BTreeMap, HashMap};
+use std::collections::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 crate::session::config::{Options, OptLevel};
+use crate::session::config::Options;
#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
pub enum ProfileCategory {
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 },
+ 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 },
QueryBlockedEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
}
impl ProfilerEvent {
- fn is_start_event(&self) -> bool {
+ fn timestamp(&self) -> Instant {
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
}
}
}
-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 thread_id_to_u64(tid: ThreadId) -> u64 {
+ unsafe { mem::transmute::<ThreadId, u64>(tid) }
}
-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
- }
+pub struct SelfProfiler {
+ events: HashMap<ThreadId, Vec<ProfilerEvent>>,
}
impl SelfProfiler {
query_name,
category,
count,
+ time: Instant::now(),
})
}
self.record(ProfilerEvent::QueryCacheHit {
query_name,
category,
+ time: Instant::now(),
})
}
events.push(event);
}
- fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
+ 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 mut results = CalculatedResults::new();
-
- //(event, child time to subtract)
- let mut query_stack = Vec::new();
-
- 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,
- 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");
- }
+ //find the earliest Instant to use as t=0
+ //when serializing the events, we'll calculate a Duration
+ //using (instant - min_instant)
+ let min_instant =
+ self.events
+ .iter()
+ .map(|(_, values)| values[0].timestamp())
+ .min()
+ .unwrap();
+
+ let pid = process::id();
+
+ let filename =
+ format!("{}.profile_events.json", opts.crate_name.clone().unwrap_or_default());
+
+ let mut file = BufWriter::new(fs::File::create(filename).unwrap());
+
+ 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();
}
- 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();
+ 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,
+ category,
+ 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();
}
}
projects / rust.git / commitdiff