diff options
Diffstat (limited to 'crates/ra_prof')
-rw-r--r-- | crates/ra_prof/src/lib.rs | 57 |
1 files changed, 38 insertions, 19 deletions
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index 6853a4794..9e167db96 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs | |||
@@ -88,7 +88,7 @@ pub type Label = &'static str; | |||
88 | pub fn profile(label: Label) -> Profiler { | 88 | pub fn profile(label: Label) -> Profiler { |
89 | assert!(!label.is_empty()); | 89 | assert!(!label.is_empty()); |
90 | if !PROFILING_ENABLED.load(Ordering::Relaxed) { | 90 | if !PROFILING_ENABLED.load(Ordering::Relaxed) { |
91 | return Profiler { label: None }; | 91 | return Profiler { label: None, detail: None }; |
92 | } | 92 | } |
93 | 93 | ||
94 | PROFILE_STACK.with(|stack| { | 94 | PROFILE_STACK.with(|stack| { |
@@ -101,15 +101,15 @@ pub fn profile(label: Label) -> Profiler { | |||
101 | }; | 101 | }; |
102 | } | 102 | } |
103 | if stack.starts.len() > stack.filter_data.depth { | 103 | if stack.starts.len() > stack.filter_data.depth { |
104 | return Profiler { label: None }; | 104 | return Profiler { label: None, detail: None }; |
105 | } | 105 | } |
106 | let allowed = &stack.filter_data.allowed; | 106 | let allowed = &stack.filter_data.allowed; |
107 | if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) { | 107 | if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) { |
108 | return Profiler { label: None }; | 108 | return Profiler { label: None, detail: None }; |
109 | } | 109 | } |
110 | 110 | ||
111 | stack.starts.push(Instant::now()); | 111 | stack.starts.push(Instant::now()); |
112 | Profiler { label: Some(label) } | 112 | Profiler { label: Some(label), detail: None } |
113 | }) | 113 | }) |
114 | } | 114 | } |
115 | 115 | ||
@@ -130,6 +130,16 @@ pub fn print_time(label: Label) -> impl Drop { | |||
130 | 130 | ||
131 | pub struct Profiler { | 131 | pub struct Profiler { |
132 | label: Option<Label>, | 132 | label: Option<Label>, |
133 | detail: Option<String>, | ||
134 | } | ||
135 | |||
136 | impl Profiler { | ||
137 | pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler { | ||
138 | if self.label.is_some() { | ||
139 | self.detail = Some(detail()) | ||
140 | } | ||
141 | self | ||
142 | } | ||
133 | } | 143 | } |
134 | 144 | ||
135 | pub struct Filter { | 145 | pub struct Filter { |
@@ -183,6 +193,7 @@ struct Message { | |||
183 | level: usize, | 193 | level: usize, |
184 | duration: Duration, | 194 | duration: Duration, |
185 | label: Label, | 195 | label: Label, |
196 | detail: Option<String>, | ||
186 | } | 197 | } |
187 | 198 | ||
188 | impl ProfileStack { | 199 | impl ProfileStack { |
@@ -208,13 +219,13 @@ thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(Profile | |||
208 | impl Drop for Profiler { | 219 | impl Drop for Profiler { |
209 | fn drop(&mut self) { | 220 | fn drop(&mut self) { |
210 | match self { | 221 | match self { |
211 | Profiler { label: Some(label) } => { | 222 | Profiler { label: Some(label), detail } => { |
212 | PROFILE_STACK.with(|stack| { | 223 | PROFILE_STACK.with(|stack| { |
213 | let mut stack = stack.borrow_mut(); | 224 | let mut stack = stack.borrow_mut(); |
214 | let start = stack.starts.pop().unwrap(); | 225 | let start = stack.starts.pop().unwrap(); |
215 | let duration = start.elapsed(); | 226 | let duration = start.elapsed(); |
216 | let level = stack.starts.len(); | 227 | let level = stack.starts.len(); |
217 | stack.messages.push(Message { level, duration, label }); | 228 | stack.messages.push(Message { level, duration, label, detail: detail.take() }); |
218 | if level == 0 { | 229 | if level == 0 { |
219 | let stdout = stderr(); | 230 | let stdout = stderr(); |
220 | let longer_than = stack.filter_data.longer_than; | 231 | let longer_than = stack.filter_data.longer_than; |
@@ -228,7 +239,7 @@ impl Drop for Profiler { | |||
228 | } | 239 | } |
229 | }); | 240 | }); |
230 | } | 241 | } |
231 | Profiler { label: None } => (), | 242 | Profiler { label: None, .. } => (), |
232 | } | 243 | } |
233 | } | 244 | } |
234 | } | 245 | } |
@@ -251,8 +262,16 @@ fn print_for_idx( | |||
251 | ) { | 262 | ) { |
252 | let current = &msgs[current_idx]; | 263 | let current = &msgs[current_idx]; |
253 | let current_indent = " ".repeat(current.level); | 264 | let current_indent = " ".repeat(current.level); |
254 | writeln!(out, "{}{:5}ms - {}", current_indent, current.duration.as_millis(), current.label) | 265 | let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); |
255 | .expect("printing profiling info"); | 266 | writeln!( |
267 | out, | ||
268 | "{}{:5}ms - {}{}", | ||
269 | current_indent, | ||
270 | current.duration.as_millis(), | ||
271 | current.label, | ||
272 | detail, | ||
273 | ) | ||
274 | .expect("printing profiling info"); | ||
256 | 275 | ||
257 | let longer_than_millis = longer_than.as_millis(); | 276 | let longer_than_millis = longer_than.as_millis(); |
258 | let children_indices = &children_map[current_idx]; | 277 | let children_indices = &children_map[current_idx]; |
@@ -417,9 +436,9 @@ mod tests { | |||
417 | fn test_longer_than() { | 436 | fn test_longer_than() { |
418 | let mut result = vec![]; | 437 | let mut result = vec![]; |
419 | let msgs = vec![ | 438 | let msgs = vec![ |
420 | Message { level: 1, duration: Duration::from_nanos(3), label: "bar" }, | 439 | Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None }, |
421 | Message { level: 1, duration: Duration::from_nanos(2), label: "bar" }, | 440 | Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None }, |
422 | Message { level: 0, duration: Duration::from_millis(1), label: "foo" }, | 441 | Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None }, |
423 | ]; | 442 | ]; |
424 | print(&msgs, Duration::from_millis(0), &mut result); | 443 | print(&msgs, Duration::from_millis(0), &mut result); |
425 | // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed | 444 | // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed |
@@ -434,8 +453,8 @@ mod tests { | |||
434 | fn test_unaccounted_for_topmost() { | 453 | fn test_unaccounted_for_topmost() { |
435 | let mut result = vec![]; | 454 | let mut result = vec![]; |
436 | let msgs = vec![ | 455 | let msgs = vec![ |
437 | Message { level: 1, duration: Duration::from_millis(2), label: "bar" }, | 456 | Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None }, |
438 | Message { level: 0, duration: Duration::from_millis(5), label: "foo" }, | 457 | Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None }, |
439 | ]; | 458 | ]; |
440 | print(&msgs, Duration::from_millis(0), &mut result); | 459 | print(&msgs, Duration::from_millis(0), &mut result); |
441 | assert_eq!( | 460 | assert_eq!( |
@@ -453,11 +472,11 @@ mod tests { | |||
453 | fn test_unaccounted_for_multiple_levels() { | 472 | fn test_unaccounted_for_multiple_levels() { |
454 | let mut result = vec![]; | 473 | let mut result = vec![]; |
455 | let msgs = vec![ | 474 | let msgs = vec![ |
456 | Message { level: 2, duration: Duration::from_millis(3), label: "baz" }, | 475 | Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None }, |
457 | Message { level: 1, duration: Duration::from_millis(5), label: "bar" }, | 476 | Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None }, |
458 | Message { level: 2, duration: Duration::from_millis(2), label: "baz" }, | 477 | Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None }, |
459 | Message { level: 1, duration: Duration::from_millis(4), label: "bar" }, | 478 | Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None }, |
460 | Message { level: 0, duration: Duration::from_millis(9), label: "foo" }, | 479 | Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None }, |
461 | ]; | 480 | ]; |
462 | print(&msgs, Duration::from_millis(0), &mut result); | 481 | print(&msgs, Duration::from_millis(0), &mut result); |
463 | assert_eq!( | 482 | assert_eq!( |