Skip to content
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.

Commit 68650ca

Browse files
borsbors
committedFeb 10, 2019
Auto merge of #58085 - wesleywiser:profiler_2, r=wesleywiser
Implement more detailed self profiling Timing data and cache hits/misses are now recorded at the query level. This allows us to show detailed per query information such as total time for each query. To see detailed query information in the summary pass the `-Z verbose` flag. For example: ``` rustc -Z self-profile -Z verbose hello_world.rs ``` results in something like: ```md Self profiling results: | Phase | Time (ms) | Time (%) | Queries | Hits (%) | ----------------------------------------- | -------------- | -------- | -------------- | -------- | Other | 177 | 54.97 | 8094 | 45.47 | - {time spent not running queries} | 113 | 35.09 | 0 | 0.00 | - const_eval | 16 | 4.97 | 26 | 11.54 | - type_of | 9 | 2.80 | 627 | 27.75 | - const_eval_raw | 8 | 2.48 | 22 | 0.00 | - adt_def | 7 | 2.17 | 381 | 11.55 | - visible_parent_map | 7 | 2.17 | 99 | 98.99 | - item_attrs | 6 | 1.86 | 698 | 50.14 | - item_children | 5 | 1.55 | 2815 | 0.00 | - adt_dtorck_constraint | 4 | 1.24 | 2 | 0.00 | - adt_destructor | 2 | 0.62 | 15 | 86.67 | TypeChecking | 53 | 16.46 | 2834 | 79.89 | - trait_impls_of | 9 | 2.80 | 65 | 86.15 | - evaluate_obligation | 7 | 2.17 | 80 | 2.50 | - const_is_rvalue_promotable_to_static | 6 | 1.86 | 1 | 0.00 | - is_copy_raw | 6 | 1.86 | 29 | 58.62 | - rvalue_promotable_map | 6 | 1.86 | 2 | 50.00 | - {time spent not running queries} | 6 | 1.86 | 0 | 0.00 | - typeck_item_bodies | 5 | 1.55 | 1 | 0.00 | - typeck_tables_of | 5 | 1.55 | 19 | 94.74 | - dropck_outlives | 2 | 0.62 | 1 | 0.00 | - layout_raw | 1 | 0.31 | 668 | 87.87 | Linking | 48 | 14.91 | 43 | 46.51 | - {time spent not running queries} | 48 | 14.91 | 0 | 0.00 | Codegen | 29 | 9.01 | 420 | 61.90 | - {time spent not running queries} | 16 | 4.97 | 0 | 0.00 | - collect_and_partition_mono_items | 11 | 3.42 | 13 | 92.31 | - mir_const | 1 | 0.31 | 1 | 0.00 | - mir_validated | 1 | 0.31 | 3 | 66.67 | Expansion | 14 | 4.35 | 0 | 0.00 | - {time spent not running queries} | 14 | 4.35 | 0 | 0.00 | BorrowChecking | 1 | 0.31 | 12 | 41.67 | - borrowck | 1 | 0.31 | 2 | 50.00 | Parsing | 0 | 0.00 | 0 | 0.00 Optimization level: No Incremental: off ``` <details> <summary>Rendered</summary> Self profiling results: | Phase | Time (ms) | Time (%) | Queries | Hits (%) | ----------------------------------------- | -------------- | -------- | -------------- | -------- | **Other** | **177** | **54.97** | **8094** | **45.47** | - {time spent not running queries} | 113 | 35.09 | 0 | 0.00 | - const_eval | 16 | 4.97 | 26 | 11.54 | - type_of | 9 | 2.80 | 627 | 27.75 | - const_eval_raw | 8 | 2.48 | 22 | 0.00 | - adt_def | 7 | 2.17 | 381 | 11.55 | - visible_parent_map | 7 | 2.17 | 99 | 98.99 | - item_attrs | 6 | 1.86 | 698 | 50.14 | - item_children | 5 | 1.55 | 2815 | 0.00 | - adt_dtorck_constraint | 4 | 1.24 | 2 | 0.00 | - adt_destructor | 2 | 0.62 | 15 | 86.67 | TypeChecking | 53 | 16.46 | 2834 | 79.89 | - trait_impls_of | 9 | 2.80 | 65 | 86.15 | - evaluate_obligation | 7 | 2.17 | 80 | 2.50 | - const_is_rvalue_promotable_to_static | 6 | 1.86 | 1 | 0.00 | - is_copy_raw | 6 | 1.86 | 29 | 58.62 | - rvalue_promotable_map | 6 | 1.86 | 2 | 50.00 | - {time spent not running queries} | 6 | 1.86 | 0 | 0.00 | - typeck_item_bodies | 5 | 1.55 | 1 | 0.00 | - typeck_tables_of | 5 | 1.55 | 19 | 94.74 | - dropck_outlives | 2 | 0.62 | 1 | 0.00 | - layout_raw | 1 | 0.31 | 668 | 87.87 | Linking | 48 | 14.91 | 43 | 46.51 | - {time spent not running queries} | 48 | 14.91 | 0 | 0.00 | Codegen | 29 | 9.01 | 420 | 61.90 | - {time spent not running queries} | 16 | 4.97 | 0 | 0.00 | - collect_and_partition_mono_items | 11 | 3.42 | 13 | 92.31 | - mir_const | 1 | 0.31 | 1 | 0.00 | - mir_validated | 1 | 0.31 | 3 | 66.67 | Expansion | 14 | 4.35 | 0 | 0.00 | - {time spent not running queries} | 14 | 4.35 | 0 | 0.00 | BorrowChecking | 1 | 0.31 | 12 | 41.67 | - borrowck | 1 | 0.31 | 2 | 50.00 | Parsing | 0 | 0.00 | 0 | 0.00 Optimization level: No Incremental: off </details> cc @nikomatsakis @michaelwoerister @Zoxc Fixes #54141
2 parents de111e6 + 584081a commit 68650ca

File tree

2 files changed

+363
-182
lines changed

2 files changed

+363
-182
lines changed
 

‎src/librustc/ty/query/plumbing.rs

Lines changed: 10 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -113,7 +113,7 @@ impl<'a, 'tcx, Q: QueryDescription<'tcx>> JobOwner<'a, 'tcx, Q> {
113113
let mut lock = cache.borrow_mut();
114114
if let Some(value) = lock.results.get(key) {
115115
profq_msg!(tcx, ProfileQueriesMsg::CacheHit);
116-
tcx.sess.profiler(|p| p.record_query_hit(Q::CATEGORY));
116+
tcx.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY));
117117
let result = Ok((value.value.clone(), value.index));
118118
#[cfg(debug_assertions)]
119119
{
@@ -375,7 +375,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
375375

376376
if dep_node.kind.is_anon() {
377377
profq_msg!(self, ProfileQueriesMsg::ProviderBegin);
378-
self.sess.profiler(|p| p.start_activity(Q::CATEGORY));
378+
self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY));
379379

380380
let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| {
381381
job.start(self, diagnostics, |tcx| {
@@ -385,7 +385,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
385385
})
386386
});
387387

388-
self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
388+
self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY));
389389
profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
390390

391391
self.dep_graph.read_index(dep_node_index);
@@ -452,14 +452,14 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
452452

453453
let result = if let Some(result) = result {
454454
profq_msg!(self, ProfileQueriesMsg::CacheHit);
455-
self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY));
455+
self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY));
456456

457457
result
458458
} else {
459459
// We could not load a result from the on-disk cache, so
460460
// recompute.
461461

462-
self.sess.profiler(|p| p.start_activity(Q::CATEGORY));
462+
self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY));
463463

464464
// The diagnostics for this query have already been
465465
// promoted to the current session during
@@ -472,7 +472,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
472472
})
473473
});
474474

475-
self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
475+
self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY));
476476
result
477477
};
478478

@@ -537,7 +537,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
537537
key, dep_node);
538538

539539
profq_msg!(self, ProfileQueriesMsg::ProviderBegin);
540-
self.sess.profiler(|p| p.start_activity(Q::CATEGORY));
540+
self.sess.profiler(|p| p.start_query(Q::NAME, Q::CATEGORY));
541541

542542
let ((result, dep_node_index), diagnostics) = with_diagnostics(|diagnostics| {
543543
job.start(self, diagnostics, |tcx| {
@@ -557,7 +557,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
557557
})
558558
});
559559

560-
self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
560+
self.sess.profiler(|p| p.end_query(Q::NAME, Q::CATEGORY));
561561
profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
562562

563563
if unlikely!(self.sess.opts.debugging_opts.query_dep_graph) {
@@ -600,7 +600,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
600600
let _ = self.get_query::<Q>(DUMMY_SP, key);
601601
} else {
602602
profq_msg!(self, ProfileQueriesMsg::CacheHit);
603-
self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY));
603+
self.sess.profiler(|p| p.record_query_hit(Q::NAME, Q::CATEGORY));
604604
}
605605
}
606606

@@ -739,6 +739,7 @@ macro_rules! define_queries_inner {
739739
sess.profiler(|p| {
740740
$(
741741
p.record_computed_queries(
742+
<queries::$name<'_> as QueryConfig<'_>>::NAME,
742743
<queries::$name<'_> as QueryConfig<'_>>::CATEGORY,
743744
self.$name.lock().results.len()
744745
);

‎src/librustc/util/profiling.rs

Lines changed: 353 additions & 173 deletions
Original file line numberDiff line numberDiff line change
@@ -1,251 +1,431 @@
1-
use crate::session::config::Options;
2-
1+
use std::collections::{BTreeMap, HashMap};
32
use std::fs;
4-
use std::io::{self, StderrLock, Write};
3+
use std::io::{self, Write};
4+
use std::thread::ThreadId;
55
use std::time::Instant;
66

7-
macro_rules! define_categories {
8-
($($name:ident,)*) => {
9-
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
10-
pub enum ProfileCategory {
11-
$($name),*
7+
use crate::session::config::{Options, OptLevel};
8+
9+
#[derive(Clone, Copy, Debug, PartialEq, Eq, Ord, PartialOrd)]
10+
pub enum ProfileCategory {
11+
Parsing,
12+
Expansion,
13+
TypeChecking,
14+
BorrowChecking,
15+
Codegen,
16+
Linking,
17+
Other,
18+
}
19+
20+
#[derive(Clone, Copy, Debug, Eq, PartialEq)]
21+
pub enum ProfilerEvent {
22+
QueryStart { query_name: &'static str, category: ProfileCategory, time: Instant },
23+
QueryEnd { query_name: &'static str, category: ProfileCategory, time: Instant },
24+
GenericActivityStart { category: ProfileCategory, time: Instant },
25+
GenericActivityEnd { category: ProfileCategory, time: Instant },
26+
QueryCacheHit { query_name: &'static str, category: ProfileCategory },
27+
QueryCount { query_name: &'static str, category: ProfileCategory, count: usize },
28+
}
29+
30+
impl ProfilerEvent {
31+
fn is_start_event(&self) -> bool {
32+
use self::ProfilerEvent::*;
33+
34+
match self {
35+
QueryStart { .. } | GenericActivityStart { .. } => true,
36+
QueryEnd { .. } | GenericActivityEnd { .. } |
37+
QueryCacheHit { .. } | QueryCount { .. } => false,
1238
}
39+
}
40+
}
1341

14-
#[allow(nonstandard_style)]
15-
struct Categories<T> {
16-
$($name: T),*
42+
pub struct SelfProfiler {
43+
events: HashMap<ThreadId, Vec<ProfilerEvent>>,
44+
}
45+
46+
struct CategoryResultData {
47+
query_times: BTreeMap<&'static str, u64>,
48+
query_cache_stats: BTreeMap<&'static str, (u64, u64)>, //(hits, total)
49+
}
50+
51+
impl CategoryResultData {
52+
fn new() -> CategoryResultData {
53+
CategoryResultData {
54+
query_times: BTreeMap::new(),
55+
query_cache_stats: BTreeMap::new(),
1756
}
57+
}
1858

19-
impl<T: Default> Categories<T> {
20-
fn new() -> Categories<T> {
21-
Categories {
22-
$($name: T::default()),*
23-
}
24-
}
59+
fn total_time(&self) -> u64 {
60+
let mut total = 0;
61+
for (_, time) in &self.query_times {
62+
total += time;
2563
}
2664

27-
impl<T> Categories<T> {
28-
fn get(&self, category: ProfileCategory) -> &T {
29-
match category {
30-
$(ProfileCategory::$name => &self.$name),*
31-
}
32-
}
65+
total
66+
}
3367

34-
fn set(&mut self, category: ProfileCategory, value: T) {
35-
match category {
36-
$(ProfileCategory::$name => self.$name = value),*
37-
}
38-
}
39-
}
68+
fn total_cache_data(&self) -> (u64, u64) {
69+
let (mut hits, mut total) = (0, 0);
4070

41-
struct CategoryData {
42-
times: Categories<u64>,
43-
query_counts: Categories<(u64, u64)>,
71+
for (_, (h, t)) in &self.query_cache_stats {
72+
hits += h;
73+
total += t;
4474
}
4575

46-
impl CategoryData {
47-
fn new() -> CategoryData {
48-
CategoryData {
49-
times: Categories::new(),
50-
query_counts: Categories::new(),
51-
}
52-
}
76+
(hits, total)
77+
}
78+
}
5379

54-
fn print(&self, lock: &mut StderrLock<'_>) {
55-
writeln!(lock, "| Phase | Time (ms) \
56-
| Time (%) | Queries | Hits (%)")
57-
.unwrap();
58-
writeln!(lock, "| ---------------- | -------------- \
59-
| -------- | -------------- | --------")
60-
.unwrap();
61-
62-
let total_time = ($(self.times.$name + )* 0) as f32;
63-
64-
$(
65-
let (hits, computed) = self.query_counts.$name;
66-
let total = hits + computed;
67-
let (hits, total) = if total > 0 {
68-
(format!("{:.2}",
69-
(((hits as f32) / (total as f32)) * 100.0)), total.to_string())
70-
} else {
71-
(String::new(), String::new())
72-
};
80+
impl Default for CategoryResultData {
81+
fn default() -> CategoryResultData {
82+
CategoryResultData::new()
83+
}
84+
}
7385

74-
writeln!(
75-
lock,
76-
"| {0: <16} | {1: <14} | {2: <8.2} | {3: <14} | {4: <8}",
77-
stringify!($name),
78-
self.times.$name / 1_000_000,
79-
((self.times.$name as f32) / total_time) * 100.0,
80-
total,
81-
hits,
82-
).unwrap();
83-
)*
84-
}
86+
struct CalculatedResults {
87+
categories: BTreeMap<ProfileCategory, CategoryResultData>,
88+
crate_name: Option<String>,
89+
optimization_level: OptLevel,
90+
incremental: bool,
91+
verbose: bool,
92+
}
8593

86-
fn json(&self) -> String {
87-
let mut json = String::from("[");
88-
89-
$(
90-
let (hits, computed) = self.query_counts.$name;
91-
let total = hits + computed;
92-
93-
//normalize hits to 0%
94-
let hit_percent =
95-
if total > 0 {
96-
((hits as f32) / (total as f32)) * 100.0
97-
} else {
98-
0.0
99-
};
100-
101-
json.push_str(&format!(
102-
"{{ \"category\": \"{}\", \"time_ms\": {},\
103-
\"query_count\": {}, \"query_hits\": {} }},",
104-
stringify!($name),
105-
self.times.$name / 1_000_000,
106-
total,
107-
format!("{:.2}", hit_percent)
108-
));
109-
)*
94+
impl CalculatedResults {
95+
fn new() -> CalculatedResults {
96+
CalculatedResults {
97+
categories: BTreeMap::new(),
98+
crate_name: None,
99+
optimization_level: OptLevel::No,
100+
incremental: false,
101+
verbose: false,
102+
}
103+
}
110104

111-
//remove the trailing ',' character
112-
json.pop();
105+
fn consolidate(mut cr1: CalculatedResults, cr2: CalculatedResults) -> CalculatedResults {
106+
for (category, data) in cr2.categories {
107+
let cr1_data = cr1.categories.entry(category).or_default();
113108

114-
json.push(']');
109+
for (query, time) in data.query_times {
110+
*cr1_data.query_times.entry(query).or_default() += time;
111+
}
115112

116-
json
113+
for (query, (hits, total)) in data.query_cache_stats {
114+
let (h, t) = cr1_data.query_cache_stats.entry(query).or_insert((0, 0));
115+
*h += hits;
116+
*t += total;
117117
}
118118
}
119+
120+
cr1
121+
}
122+
123+
fn total_time(&self) -> u64 {
124+
let mut total = 0;
125+
126+
for (_, data) in &self.categories {
127+
total += data.total_time();
128+
}
129+
130+
total
131+
}
132+
133+
fn with_options(mut self, opts: &Options) -> CalculatedResults {
134+
self.crate_name = opts.crate_name.clone();
135+
self.optimization_level = opts.optimize;
136+
self.incremental = opts.incremental.is_some();
137+
self.verbose = opts.debugging_opts.verbose;
138+
139+
self
119140
}
120141
}
121142

122-
define_categories! {
123-
Parsing,
124-
Expansion,
125-
TypeChecking,
126-
BorrowChecking,
127-
Codegen,
128-
Linking,
129-
Other,
143+
fn time_between_ns(start: Instant, end: Instant) -> u64 {
144+
if start < end {
145+
let time = end - start;
146+
(time.as_secs() * 1_000_000_000) + (time.subsec_nanos() as u64)
147+
} else {
148+
debug!("time_between_ns: ignorning instance of end < start");
149+
0
150+
}
130151
}
131152

132-
pub struct SelfProfiler {
133-
timer_stack: Vec<ProfileCategory>,
134-
data: CategoryData,
135-
current_timer: Instant,
153+
fn calculate_percent(numerator: u64, denominator: u64) -> f32 {
154+
if denominator > 0 {
155+
((numerator as f32) / (denominator as f32)) * 100.0
156+
} else {
157+
0.0
158+
}
136159
}
137160

138161
impl SelfProfiler {
139162
pub fn new() -> SelfProfiler {
140163
let mut profiler = SelfProfiler {
141-
timer_stack: Vec::new(),
142-
data: CategoryData::new(),
143-
current_timer: Instant::now(),
164+
events: HashMap::new(),
144165
};
145166

146167
profiler.start_activity(ProfileCategory::Other);
147168

148169
profiler
149170
}
150171

172+
#[inline]
151173
pub fn start_activity(&mut self, category: ProfileCategory) {
152-
match self.timer_stack.last().cloned() {
153-
None => {
154-
self.current_timer = Instant::now();
155-
},
156-
Some(current_category) if current_category == category => {
157-
//since the current category is the same as the new activity's category,
158-
//we don't need to do anything with the timer, we just need to push it on the stack
159-
}
160-
Some(current_category) => {
161-
let elapsed = self.stop_timer();
174+
self.record(ProfilerEvent::GenericActivityStart {
175+
category,
176+
time: Instant::now(),
177+
})
178+
}
162179

163-
//record the current category's time
164-
let new_time = self.data.times.get(current_category) + elapsed;
165-
self.data.times.set(current_category, new_time);
166-
}
167-
}
180+
#[inline]
181+
pub fn end_activity(&mut self, category: ProfileCategory) {
182+
self.record(ProfilerEvent::GenericActivityEnd {
183+
category,
184+
time: Instant::now(),
185+
})
186+
}
168187

169-
//push the new category
170-
self.timer_stack.push(category);
188+
#[inline]
189+
pub fn record_computed_queries(
190+
&mut self,
191+
query_name: &'static str,
192+
category: ProfileCategory,
193+
count: usize)
194+
{
195+
self.record(ProfilerEvent::QueryCount {
196+
query_name,
197+
category,
198+
count,
199+
})
171200
}
172201

173-
pub fn record_computed_queries(&mut self, category: ProfileCategory, count: usize) {
174-
let (hits, computed) = *self.data.query_counts.get(category);
175-
self.data.query_counts.set(category, (hits, computed + count as u64));
202+
#[inline]
203+
pub fn record_query_hit(&mut self, query_name: &'static str, category: ProfileCategory) {
204+
self.record(ProfilerEvent::QueryCacheHit {
205+
query_name,
206+
category,
207+
})
176208
}
177209

178-
pub fn record_query_hit(&mut self, category: ProfileCategory) {
179-
let (hits, computed) = *self.data.query_counts.get(category);
180-
self.data.query_counts.set(category, (hits + 1, computed));
210+
#[inline]
211+
pub fn start_query(&mut self, query_name: &'static str, category: ProfileCategory) {
212+
self.record(ProfilerEvent::QueryStart {
213+
query_name,
214+
category,
215+
time: Instant::now(),
216+
});
181217
}
182218

183-
pub fn end_activity(&mut self, category: ProfileCategory) {
184-
match self.timer_stack.pop() {
185-
None => bug!("end_activity() was called but there was no running activity"),
186-
Some(c) =>
187-
assert!(
188-
c == category,
189-
"end_activity() was called but a different activity was running"),
219+
#[inline]
220+
pub fn end_query(&mut self, query_name: &'static str, category: ProfileCategory) {
221+
self.record(ProfilerEvent::QueryEnd {
222+
query_name,
223+
category,
224+
time: Instant::now(),
225+
})
226+
}
227+
228+
#[inline]
229+
fn record(&mut self, event: ProfilerEvent) {
230+
let thread_id = std::thread::current().id();
231+
let events = self.events.entry(thread_id).or_default();
232+
233+
events.push(event);
234+
}
235+
236+
fn calculate_thread_results(events: &Vec<ProfilerEvent>) -> CalculatedResults {
237+
use self::ProfilerEvent::*;
238+
239+
assert!(
240+
events.last().map(|e| !e.is_start_event()).unwrap_or(true),
241+
"there was an event running when calculate_reslts() was called"
242+
);
243+
244+
let mut results = CalculatedResults::new();
245+
246+
//(event, child time to subtract)
247+
let mut query_stack = Vec::new();
248+
249+
for event in events {
250+
match event {
251+
QueryStart { .. } | GenericActivityStart { .. } => {
252+
query_stack.push((event, 0));
253+
},
254+
QueryEnd { query_name, category, time: end_time } => {
255+
let previous_query = query_stack.pop();
256+
if let Some((QueryStart {
257+
query_name: p_query_name,
258+
time: start_time,
259+
category: _ }, child_time_to_subtract)) = previous_query {
260+
assert_eq!(
261+
p_query_name,
262+
query_name,
263+
"Saw a query end but the previous query wasn't the corresponding start"
264+
);
265+
266+
let time_ns = time_between_ns(*start_time, *end_time);
267+
let self_time_ns = time_ns - child_time_to_subtract;
268+
let result_data = results.categories.entry(*category).or_default();
269+
270+
*result_data.query_times.entry(query_name).or_default() += self_time_ns;
271+
272+
if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
273+
*child_time_to_subtract += time_ns;
274+
}
275+
} else {
276+
bug!("Saw a query end but the previous event wasn't a query start");
277+
}
278+
}
279+
GenericActivityEnd { category, time: end_time } => {
280+
let previous_event = query_stack.pop();
281+
if let Some((GenericActivityStart {
282+
category: previous_category,
283+
time: start_time }, child_time_to_subtract)) = previous_event {
284+
assert_eq!(
285+
previous_category,
286+
category,
287+
"Saw an end but the previous event wasn't the corresponding start"
288+
);
289+
290+
let time_ns = time_between_ns(*start_time, *end_time);
291+
let self_time_ns = time_ns - child_time_to_subtract;
292+
let result_data = results.categories.entry(*category).or_default();
293+
294+
*result_data.query_times
295+
.entry("{time spent not running queries}")
296+
.or_default() += self_time_ns;
297+
298+
if let Some((_, child_time_to_subtract)) = query_stack.last_mut() {
299+
*child_time_to_subtract += time_ns;
300+
}
301+
} else {
302+
bug!("Saw an activity end but the previous event wasn't an activity start");
303+
}
304+
},
305+
QueryCacheHit { category, query_name } => {
306+
let result_data = results.categories.entry(*category).or_default();
307+
308+
let (hits, total) =
309+
result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
310+
*hits += 1;
311+
*total += 1;
312+
},
313+
QueryCount { category, query_name, count } => {
314+
let result_data = results.categories.entry(*category).or_default();
315+
316+
let (_, totals) =
317+
result_data.query_cache_stats.entry(query_name).or_insert((0, 0));
318+
*totals += *count as u64;
319+
},
320+
}
190321
}
191322

192-
//check if the new running timer is in the same category as this one
193-
//if it is, we don't need to do anything
194-
if let Some(c) = self.timer_stack.last() {
195-
if *c == category {
196-
return;
323+
//normalize the times to ms
324+
for (_, data) in &mut results.categories {
325+
for (_, time) in &mut data.query_times {
326+
*time = *time / 1_000_000;
197327
}
198328
}
199329

200-
//the new timer is different than the previous,
201-
//so record the elapsed time and start a new timer
202-
let elapsed = self.stop_timer();
203-
let new_time = self.data.times.get(category) + elapsed;
204-
self.data.times.set(category, new_time);
330+
results
205331
}
206332

207-
fn stop_timer(&mut self) -> u64 {
208-
let elapsed = self.current_timer.elapsed();
209-
210-
self.current_timer = Instant::now();
211-
212-
(elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64)
333+
fn get_results(&self, opts: &Options) -> CalculatedResults {
334+
self.events
335+
.iter()
336+
.map(|(_, r)| SelfProfiler::calculate_thread_results(r))
337+
.fold(CalculatedResults::new(), CalculatedResults::consolidate)
338+
.with_options(opts)
213339
}
214340

215341
pub fn print_results(&mut self, opts: &Options) {
216342
self.end_activity(ProfileCategory::Other);
217343

218-
assert!(
219-
self.timer_stack.is_empty(),
220-
"there were timers running when print_results() was called");
344+
let results = self.get_results(opts);
345+
346+
let total_time = results.total_time() as f32;
221347

222348
let out = io::stderr();
223349
let mut lock = out.lock();
224350

225-
let crate_name =
226-
opts.crate_name
227-
.as_ref()
228-
.map(|n| format!(" for {}", n))
229-
.unwrap_or_default();
351+
let crate_name = results.crate_name.map(|n| format!(" for {}", n)).unwrap_or_default();
230352

231353
writeln!(lock, "Self profiling results{}:", crate_name).unwrap();
232354
writeln!(lock).unwrap();
233355

234-
self.data.print(&mut lock);
356+
writeln!(lock, "| Phase | Time (ms) \
357+
| Time (%) | Queries | Hits (%)")
358+
.unwrap();
359+
writeln!(lock, "| ----------------------------------------- | -------------- \
360+
| -------- | -------------- | --------")
361+
.unwrap();
362+
363+
let mut categories: Vec<_> = results.categories.iter().collect();
364+
categories.sort_by(|(_, data1), (_, data2)| data2.total_time().cmp(&data1.total_time()));
365+
366+
for (category, data) in categories {
367+
let (category_hits, category_total) = data.total_cache_data();
368+
let category_hit_percent = calculate_percent(category_hits, category_total);
369+
370+
writeln!(
371+
lock,
372+
"| {0: <41} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
373+
format!("{:?}", category),
374+
data.total_time(),
375+
((data.total_time() as f32) / total_time) * 100.0,
376+
category_total,
377+
format!("{:.2}", category_hit_percent),
378+
).unwrap();
379+
380+
//in verbose mode, show individual query data
381+
if results.verbose {
382+
//don't show queries that took less than 1ms
383+
let mut times: Vec<_> = data.query_times.iter().filter(|(_, t)| **t > 0).collect();
384+
times.sort_by(|(_, time1), (_, time2)| time2.cmp(time1));
385+
386+
for (query, time) in times {
387+
let (hits, total) = data.query_cache_stats.get(query).unwrap_or(&(0, 0));
388+
let hit_percent = calculate_percent(*hits, *total);
389+
390+
writeln!(
391+
lock,
392+
"| - {0: <39} | {1: >14} | {2: >8.2} | {3: >14} | {4: >8}",
393+
query,
394+
time,
395+
((*time as f32) / total_time) * 100.0,
396+
total,
397+
format!("{:.2}", hit_percent),
398+
).unwrap();
399+
}
400+
}
401+
}
235402

236403
writeln!(lock).unwrap();
237404
writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap();
238-
239-
let incremental = if opts.incremental.is_some() { "on" } else { "off" };
240-
writeln!(lock, "Incremental: {}", incremental).unwrap();
405+
writeln!(lock, "Incremental: {}", if results.incremental { "on" } else { "off" }).unwrap();
241406
}
242407

243408
pub fn save_results(&self, opts: &Options) {
244-
let category_data = self.data.json();
409+
let results = self.get_results(opts);
410+
245411
let compilation_options =
246412
format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}",
247-
opts.optimize,
248-
if opts.incremental.is_some() { "true" } else { "false" });
413+
results.optimization_level,
414+
if results.incremental { "true" } else { "false" });
415+
416+
let mut category_data = String::new();
417+
418+
for (category, data) in &results.categories {
419+
let (hits, total) = data.total_cache_data();
420+
let hit_percent = calculate_percent(hits, total);
421+
422+
category_data.push_str(&format!("{{ \"category\": \"{:?}\", \"time_ms\": {}, \
423+
\"query_count\": {}, \"query_hits\": {} }}",
424+
category,
425+
data.total_time(),
426+
total,
427+
format!("{:.2}", hit_percent)));
428+
}
249429

250430
let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}",
251431
category_data,

0 commit comments

Comments
 (0)
Please sign in to comment.