aboutsummaryrefslogtreecommitdiff
path: root/crates/ra_prof/src
diff options
context:
space:
mode:
authorKevin DeLorey <[email protected]>2020-02-09 16:25:47 +0000
committerKevin DeLorey <[email protected]>2020-02-09 16:37:43 +0000
commita957c473fdb79880c39b73dc9e0c923093cf16ac (patch)
treef998b548f530ce604651e0e6af314ed2ec74b3b5 /crates/ra_prof/src
parent22caf982b99c54058e2e9200aeea0e61cada284a (diff)
parent1b9b13b4b4a75b5531c3f046ce6bf72d681f2732 (diff)
Merge branch 'master' into kdelorey/complete-trait-impl
Diffstat (limited to 'crates/ra_prof/src')
-rw-r--r--crates/ra_prof/src/lib.rs180
1 files changed, 110 insertions, 70 deletions
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index da541005a..d38ff397e 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -6,10 +6,9 @@ mod google_cpu_profiler;
6 6
7use std::{ 7use std::{
8 cell::RefCell, 8 cell::RefCell,
9 collections::BTreeMap,
9 collections::HashSet, 10 collections::HashSet,
10 io::{stderr, Write}, 11 io::{stderr, Write},
11 iter::repeat,
12 mem,
13 sync::{ 12 sync::{
14 atomic::{AtomicBool, Ordering}, 13 atomic::{AtomicBool, Ordering},
15 RwLock, 14 RwLock,
@@ -17,7 +16,6 @@ use std::{
17 time::{Duration, Instant}, 16 time::{Duration, Instant},
18}; 17};
19 18
20use itertools::Itertools;
21use once_cell::sync::Lazy; 19use once_cell::sync::Lazy;
22 20
23pub use crate::memory_usage::{Bytes, MemoryUsage}; 21pub use crate::memory_usage::{Bytes, MemoryUsage};
@@ -51,6 +49,8 @@ pub fn set_filter(f: Filter) {
51 *old = filter_data; 49 *old = filter_data;
52} 50}
53 51
52pub type Label = &'static str;
53
54/// This function starts a profiling scope in the current execution stack with a given description. 54/// This function starts a profiling scope in the current execution stack with a given description.
55/// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop. 55/// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop.
56/// It supports nested profiling scopes in case when this function invoked multiple times at the execution stack. In this case the profiling information will be nested at the output. 56/// It supports nested profiling scopes in case when this function invoked multiple times at the execution stack. In this case the profiling information will be nested at the output.
@@ -78,10 +78,10 @@ pub fn set_filter(f: Filter) {
78/// 0ms - profile 78/// 0ms - profile
79/// 0ms - profile2 79/// 0ms - profile2
80/// ``` 80/// ```
81pub fn profile(desc: &str) -> Profiler { 81pub fn profile(label: Label) -> Profiler {
82 assert!(!desc.is_empty()); 82 assert!(!label.is_empty());
83 if !PROFILING_ENABLED.load(Ordering::Relaxed) { 83 if !PROFILING_ENABLED.load(Ordering::Relaxed) {
84 return Profiler { desc: None }; 84 return Profiler { label: None };
85 } 85 }
86 86
87 PROFILE_STACK.with(|stack| { 87 PROFILE_STACK.with(|stack| {
@@ -94,20 +94,35 @@ pub fn profile(desc: &str) -> Profiler {
94 }; 94 };
95 } 95 }
96 if stack.starts.len() > stack.filter_data.depth { 96 if stack.starts.len() > stack.filter_data.depth {
97 return Profiler { desc: None }; 97 return Profiler { label: None };
98 } 98 }
99 let allowed = &stack.filter_data.allowed; 99 let allowed = &stack.filter_data.allowed;
100 if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(desc) { 100 if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) {
101 return Profiler { desc: None }; 101 return Profiler { label: None };
102 } 102 }
103 103
104 stack.starts.push(Instant::now()); 104 stack.starts.push(Instant::now());
105 Profiler { desc: Some(desc.to_string()) } 105 Profiler { label: Some(label) }
106 }) 106 })
107} 107}
108 108
109pub fn print_time(label: Label) -> impl Drop {
110 struct Guard {
111 label: Label,
112 start: Instant,
113 }
114
115 impl Drop for Guard {
116 fn drop(&mut self) {
117 eprintln!("{}: {:?}", self.label, self.start.elapsed())
118 }
119 }
120
121 Guard { label, start: Instant::now() }
122}
123
109pub struct Profiler { 124pub struct Profiler {
110 desc: Option<String>, 125 label: Option<Label>,
111} 126}
112 127
113pub struct Filter { 128pub struct Filter {
@@ -160,7 +175,7 @@ struct ProfileStack {
160struct Message { 175struct Message {
161 level: usize, 176 level: usize,
162 duration: Duration, 177 duration: Duration,
163 message: String, 178 label: Label,
164} 179}
165 180
166impl ProfileStack { 181impl ProfileStack {
@@ -186,14 +201,13 @@ thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(Profile
186impl Drop for Profiler { 201impl Drop for Profiler {
187 fn drop(&mut self) { 202 fn drop(&mut self) {
188 match self { 203 match self {
189 Profiler { desc: Some(desc) } => { 204 Profiler { label: Some(label) } => {
190 PROFILE_STACK.with(|stack| { 205 PROFILE_STACK.with(|stack| {
191 let mut stack = stack.borrow_mut(); 206 let mut stack = stack.borrow_mut();
192 let start = stack.starts.pop().unwrap(); 207 let start = stack.starts.pop().unwrap();
193 let duration = start.elapsed(); 208 let duration = start.elapsed();
194 let level = stack.starts.len(); 209 let level = stack.starts.len();
195 let message = mem::replace(desc, String::new()); 210 stack.messages.push(Message { level, duration, label: label });
196 stack.messages.push(Message { level, duration, message });
197 if level == 0 { 211 if level == 0 {
198 let stdout = stderr(); 212 let stdout = stderr();
199 let longer_than = stack.filter_data.longer_than; 213 let longer_than = stack.filter_data.longer_than;
@@ -201,70 +215,96 @@ impl Drop for Profiler {
201 // (otherwise we could print `0ms` despite user's `>0` filter when 215 // (otherwise we could print `0ms` despite user's `>0` filter when
202 // `duration` is just a few nanos). 216 // `duration` is just a few nanos).
203 if duration.as_millis() > longer_than.as_millis() { 217 if duration.as_millis() > longer_than.as_millis() {
204 print(0, &stack.messages, &mut stdout.lock(), longer_than, None); 218 print(&stack.messages, longer_than, &mut stdout.lock());
205 } 219 }
206 stack.messages.clear(); 220 stack.messages.clear();
207 } 221 }
208 }); 222 });
209 } 223 }
210 Profiler { desc: None } => (), 224 Profiler { label: None } => (),
211 } 225 }
212 } 226 }
213} 227}
214 228
215fn print( 229fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) {
216 lvl: usize,
217 msgs: &[Message],
218 out: &mut impl Write,
219 longer_than: Duration,
220 total: Option<Duration>,
221) {
222 if msgs.is_empty() { 230 if msgs.is_empty() {
223 return; 231 return;
224 } 232 }
225 // The index of the first element that will be included in the slice when we recurse. 233 let children_map = idx_to_children(msgs);
226 let mut next_start = 0; 234 let root_idx = msgs.len() - 1;
227 let indent = repeat(" ").take(lvl).collect::<String>(); 235 print_for_idx(root_idx, &children_map, msgs, longer_than, out);
228 // We output hierarchy for long calls, but sum up all short calls 236}
229 let mut short = Vec::new(); 237
238fn print_for_idx(
239 current_idx: usize,
240 children_map: &[Vec<usize>],
241 msgs: &[Message],
242 longer_than: Duration,
243 out: &mut impl Write,
244) {
245 let current = &msgs[current_idx];
246 let current_indent = " ".repeat(current.level);
247 writeln!(out, "{}{:5}ms - {}", current_indent, current.duration.as_millis(), current.label)
248 .expect("printing profiling info");
249
250 let longer_than_millis = longer_than.as_millis();
251 let children_indices = &children_map[current_idx];
230 let mut accounted_for = Duration::default(); 252 let mut accounted_for = Duration::default();
231 for (i, &Message { level, duration, message: ref msg }) in msgs.iter().enumerate() { 253 let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output.
232 if level != lvl {
233 continue;
234 }
235 accounted_for += duration;
236 if duration.as_millis() > longer_than.as_millis() {
237 writeln!(out, "{}{:5}ms - {}", indent, duration.as_millis(), msg)
238 .expect("printing profiling info to stdout");
239 254
240 print(lvl + 1, &msgs[next_start..i], out, longer_than, Some(duration)); 255 for child_idx in children_indices.iter() {
256 let child = &msgs[*child_idx];
257 if child.duration.as_millis() > longer_than_millis {
258 print_for_idx(*child_idx, children_map, msgs, longer_than, out);
241 } else { 259 } else {
242 short.push((msg, duration)) 260 let pair = short_children.entry(child.label).or_insert((Duration::default(), 0));
261 pair.0 += child.duration;
262 pair.1 += 1;
243 } 263 }
264 accounted_for += child.duration;
265 }
244 266
245 next_start = i + 1; 267 for (child_msg, (duration, count)) in short_children.iter() {
268 let millis = duration.as_millis();
269 writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count)
270 .expect("printing profiling info");
246 } 271 }
247 short.sort_by_key(|(msg, _time)| *msg); 272
248 for (msg, entires) in short.iter().group_by(|(msg, _time)| msg).into_iter() { 273 let unaccounted_millis = (current.duration - accounted_for).as_millis();
249 let mut count = 0; 274 if !children_indices.is_empty()
250 let mut total_duration = Duration::default(); 275 && unaccounted_millis > 0
251 entires.for_each(|(_msg, time)| { 276 && unaccounted_millis > longer_than_millis
252 count += 1; 277 {
253 total_duration += *time; 278 writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis)
254 }); 279 .expect("printing profiling info");
255 writeln!(out, "{}{:5}ms - {} ({} calls)", indent, total_duration.as_millis(), msg, count)
256 .expect("printing profiling info to stdout");
257 } 280 }
281}
258 282
259 if let Some(total) = total { 283/// Returns a mapping from an index in the `msgs` to the vector with the indices of its children.
260 if let Some(unaccounted) = total.checked_sub(accounted_for) { 284///
261 let unaccounted_millis = unaccounted.as_millis(); 285/// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish.
262 if unaccounted_millis > longer_than.as_millis() && unaccounted_millis > 0 { 286/// In other words, a postorder of the call graph. In particular, the root is the last element of
263 writeln!(out, "{}{:5}ms - ???", indent, unaccounted_millis) 287/// `msgs`.
264 .expect("printing profiling info to stdout"); 288fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> {
265 } 289 // Initialize with the index of the root; `msgs` and `ancestors` should be never empty.
290 assert!(!msgs.is_empty());
291 let mut ancestors = vec![msgs.len() - 1];
292 let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()];
293 for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() {
294 // We need to find the parent of the current message, i.e., the last ancestor that has a
295 // level lower than the current message.
296 while msgs[*ancestors.last().unwrap()].level >= msg.level {
297 ancestors.pop();
266 } 298 }
299 result[*ancestors.last().unwrap()].push(idx);
300 ancestors.push(idx);
301 }
302 // Note that above we visited all children from the last to the first one. Let's reverse vectors
303 // to get the more natural order where the first element is the first child.
304 for vec in result.iter_mut() {
305 vec.reverse();
267 } 306 }
307 result
268} 308}
269 309
270/// Prints backtrace to stderr, useful for debugging. 310/// Prints backtrace to stderr, useful for debugging.
@@ -369,11 +409,11 @@ mod tests {
369 fn test_longer_than() { 409 fn test_longer_than() {
370 let mut result = vec![]; 410 let mut result = vec![];
371 let msgs = vec![ 411 let msgs = vec![
372 Message { level: 1, duration: Duration::from_nanos(3), message: "bar".to_owned() }, 412 Message { level: 1, duration: Duration::from_nanos(3), label: "bar" },
373 Message { level: 1, duration: Duration::from_nanos(2), message: "bar".to_owned() }, 413 Message { level: 1, duration: Duration::from_nanos(2), label: "bar" },
374 Message { level: 0, duration: Duration::from_millis(1), message: "foo".to_owned() }, 414 Message { level: 0, duration: Duration::from_millis(1), label: "foo" },
375 ]; 415 ];
376 print(0, &msgs, &mut result, Duration::from_millis(0), Some(Duration::from_millis(1))); 416 print(&msgs, Duration::from_millis(0), &mut result);
377 // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed 417 // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed
378 // when printing. 418 // when printing.
379 assert_eq!( 419 assert_eq!(
@@ -386,10 +426,10 @@ mod tests {
386 fn test_unaccounted_for_topmost() { 426 fn test_unaccounted_for_topmost() {
387 let mut result = vec![]; 427 let mut result = vec![];
388 let msgs = vec![ 428 let msgs = vec![
389 Message { level: 1, duration: Duration::from_millis(2), message: "bar".to_owned() }, 429 Message { level: 1, duration: Duration::from_millis(2), label: "bar" },
390 Message { level: 0, duration: Duration::from_millis(5), message: "foo".to_owned() }, 430 Message { level: 0, duration: Duration::from_millis(5), label: "foo" },
391 ]; 431 ];
392 print(0, &msgs, &mut result, Duration::from_millis(0), Some(Duration::from_millis(1))); 432 print(&msgs, Duration::from_millis(0), &mut result);
393 assert_eq!( 433 assert_eq!(
394 std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), 434 std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
395 vec![ 435 vec![
@@ -405,13 +445,13 @@ mod tests {
405 fn test_unaccounted_for_multiple_levels() { 445 fn test_unaccounted_for_multiple_levels() {
406 let mut result = vec![]; 446 let mut result = vec![];
407 let msgs = vec![ 447 let msgs = vec![
408 Message { level: 2, duration: Duration::from_millis(3), message: "baz".to_owned() }, 448 Message { level: 2, duration: Duration::from_millis(3), label: "baz" },
409 Message { level: 1, duration: Duration::from_millis(5), message: "bar".to_owned() }, 449 Message { level: 1, duration: Duration::from_millis(5), label: "bar" },
410 Message { level: 2, duration: Duration::from_millis(2), message: "baz".to_owned() }, 450 Message { level: 2, duration: Duration::from_millis(2), label: "baz" },
411 Message { level: 1, duration: Duration::from_millis(4), message: "bar".to_owned() }, 451 Message { level: 1, duration: Duration::from_millis(4), label: "bar" },
412 Message { level: 0, duration: Duration::from_millis(9), message: "foo".to_owned() }, 452 Message { level: 0, duration: Duration::from_millis(9), label: "foo" },
413 ]; 453 ];
414 print(0, &msgs, &mut result, Duration::from_millis(0), None); 454 print(&msgs, Duration::from_millis(0), &mut result);
415 assert_eq!( 455 assert_eq!(
416 std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), 456 std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
417 vec![ 457 vec![