diff options
author | Kevin DeLorey <[email protected]> | 2020-02-09 16:25:47 +0000 |
---|---|---|
committer | Kevin DeLorey <[email protected]> | 2020-02-09 16:37:43 +0000 |
commit | a957c473fdb79880c39b73dc9e0c923093cf16ac (patch) | |
tree | f998b548f530ce604651e0e6af314ed2ec74b3b5 /crates/ra_prof/src/lib.rs | |
parent | 22caf982b99c54058e2e9200aeea0e61cada284a (diff) | |
parent | 1b9b13b4b4a75b5531c3f046ce6bf72d681f2732 (diff) |
Merge branch 'master' into kdelorey/complete-trait-impl
Diffstat (limited to 'crates/ra_prof/src/lib.rs')
-rw-r--r-- | crates/ra_prof/src/lib.rs | 180 |
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 | ||
7 | use std::{ | 7 | use 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 | ||
20 | use itertools::Itertools; | ||
21 | use once_cell::sync::Lazy; | 19 | use once_cell::sync::Lazy; |
22 | 20 | ||
23 | pub use crate::memory_usage::{Bytes, MemoryUsage}; | 21 | pub 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 | ||
52 | pub 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 | /// ``` |
81 | pub fn profile(desc: &str) -> Profiler { | 81 | pub 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 | ||
109 | pub 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 | |||
109 | pub struct Profiler { | 124 | pub struct Profiler { |
110 | desc: Option<String>, | 125 | label: Option<Label>, |
111 | } | 126 | } |
112 | 127 | ||
113 | pub struct Filter { | 128 | pub struct Filter { |
@@ -160,7 +175,7 @@ struct ProfileStack { | |||
160 | struct Message { | 175 | struct Message { |
161 | level: usize, | 176 | level: usize, |
162 | duration: Duration, | 177 | duration: Duration, |
163 | message: String, | 178 | label: Label, |
164 | } | 179 | } |
165 | 180 | ||
166 | impl ProfileStack { | 181 | impl ProfileStack { |
@@ -186,14 +201,13 @@ thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(Profile | |||
186 | impl Drop for Profiler { | 201 | impl 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 | ||
215 | fn print( | 229 | fn 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 | |
238 | fn 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"); | 288 | fn 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![ |