diff options
author | Aleksey Kladov <[email protected]> | 2020-02-02 17:54:26 +0000 |
---|---|---|
committer | Aleksey Kladov <[email protected]> | 2020-02-02 17:56:37 +0000 |
commit | 24ad1cce2c3cf2c0ce8288fc02c4c55529598990 (patch) | |
tree | 04241d931e7d2f57799a4ff28a11f020090def74 | |
parent | 856e4ba126ae776753f38c00593c02c4f43be510 (diff) |
Avoid premature pessimization
The extra allocation for message should not matter here at all, but
using a static string is just as ergonomic, if not more, and there's
no reason to write deliberately slow code
-rw-r--r-- | crates/ra_ide/src/change.rs | 2 | ||||
-rw-r--r-- | crates/ra_lsp_server/src/main_loop.rs | 1 | ||||
-rw-r--r-- | crates/ra_prof/src/lib.rs | 64 |
3 files changed, 34 insertions, 33 deletions
diff --git a/crates/ra_ide/src/change.rs b/crates/ra_ide/src/change.rs index 45a58690b..18dad2ea3 100644 --- a/crates/ra_ide/src/change.rs +++ b/crates/ra_ide/src/change.rs | |||
@@ -145,6 +145,8 @@ impl LibraryData { | |||
145 | root_id: SourceRootId, | 145 | root_id: SourceRootId, |
146 | files: Vec<(FileId, RelativePathBuf, Arc<String>)>, | 146 | files: Vec<(FileId, RelativePathBuf, Arc<String>)>, |
147 | ) -> LibraryData { | 147 | ) -> LibraryData { |
148 | let _p = profile("LibraryData::prepare"); | ||
149 | |||
148 | #[cfg(not(feature = "wasm"))] | 150 | #[cfg(not(feature = "wasm"))] |
149 | let iter = files.par_iter(); | 151 | let iter = files.par_iter(); |
150 | #[cfg(feature = "wasm")] | 152 | #[cfg(feature = "wasm")] |
diff --git a/crates/ra_lsp_server/src/main_loop.rs b/crates/ra_lsp_server/src/main_loop.rs index d850ded37..508fe08c0 100644 --- a/crates/ra_lsp_server/src/main_loop.rs +++ b/crates/ra_lsp_server/src/main_loop.rs | |||
@@ -403,7 +403,6 @@ fn loop_turn( | |||
403 | let sender = libdata_sender.clone(); | 403 | let sender = libdata_sender.clone(); |
404 | pool.execute(move || { | 404 | pool.execute(move || { |
405 | log::info!("indexing {:?} ... ", root); | 405 | log::info!("indexing {:?} ... ", root); |
406 | let _p = profile(&format!("indexed {:?}", root)); | ||
407 | let data = LibraryData::prepare(root, files); | 406 | let data = LibraryData::prepare(root, files); |
408 | sender.send(data).unwrap(); | 407 | sender.send(data).unwrap(); |
409 | }); | 408 | }); |
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index 4a49e9f95..d38ff397e 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs | |||
@@ -9,7 +9,6 @@ use std::{ | |||
9 | collections::BTreeMap, | 9 | collections::BTreeMap, |
10 | collections::HashSet, | 10 | collections::HashSet, |
11 | io::{stderr, Write}, | 11 | io::{stderr, Write}, |
12 | mem, | ||
13 | sync::{ | 12 | sync::{ |
14 | atomic::{AtomicBool, Ordering}, | 13 | atomic::{AtomicBool, Ordering}, |
15 | RwLock, | 14 | RwLock, |
@@ -50,6 +49,8 @@ pub fn set_filter(f: Filter) { | |||
50 | *old = filter_data; | 49 | *old = filter_data; |
51 | } | 50 | } |
52 | 51 | ||
52 | pub type Label = &'static str; | ||
53 | |||
53 | /// 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. |
54 | /// 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. |
55 | /// 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. |
@@ -77,10 +78,10 @@ pub fn set_filter(f: Filter) { | |||
77 | /// 0ms - profile | 78 | /// 0ms - profile |
78 | /// 0ms - profile2 | 79 | /// 0ms - profile2 |
79 | /// ``` | 80 | /// ``` |
80 | pub fn profile(desc: &str) -> Profiler { | 81 | pub fn profile(label: Label) -> Profiler { |
81 | assert!(!desc.is_empty()); | 82 | assert!(!label.is_empty()); |
82 | if !PROFILING_ENABLED.load(Ordering::Relaxed) { | 83 | if !PROFILING_ENABLED.load(Ordering::Relaxed) { |
83 | return Profiler { desc: None }; | 84 | return Profiler { label: None }; |
84 | } | 85 | } |
85 | 86 | ||
86 | PROFILE_STACK.with(|stack| { | 87 | PROFILE_STACK.with(|stack| { |
@@ -93,35 +94,35 @@ pub fn profile(desc: &str) -> Profiler { | |||
93 | }; | 94 | }; |
94 | } | 95 | } |
95 | if stack.starts.len() > stack.filter_data.depth { | 96 | if stack.starts.len() > stack.filter_data.depth { |
96 | return Profiler { desc: None }; | 97 | return Profiler { label: None }; |
97 | } | 98 | } |
98 | let allowed = &stack.filter_data.allowed; | 99 | let allowed = &stack.filter_data.allowed; |
99 | if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(desc) { | 100 | if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) { |
100 | return Profiler { desc: None }; | 101 | return Profiler { label: None }; |
101 | } | 102 | } |
102 | 103 | ||
103 | stack.starts.push(Instant::now()); | 104 | stack.starts.push(Instant::now()); |
104 | Profiler { desc: Some(desc.to_string()) } | 105 | Profiler { label: Some(label) } |
105 | }) | 106 | }) |
106 | } | 107 | } |
107 | 108 | ||
108 | pub fn print_time(desc: &str) -> impl Drop + '_ { | 109 | pub fn print_time(label: Label) -> impl Drop { |
109 | struct Guard<'a> { | 110 | struct Guard { |
110 | desc: &'a str, | 111 | label: Label, |
111 | start: Instant, | 112 | start: Instant, |
112 | } | 113 | } |
113 | 114 | ||
114 | impl Drop for Guard<'_> { | 115 | impl Drop for Guard { |
115 | fn drop(&mut self) { | 116 | fn drop(&mut self) { |
116 | eprintln!("{}: {:?}", self.desc, self.start.elapsed()) | 117 | eprintln!("{}: {:?}", self.label, self.start.elapsed()) |
117 | } | 118 | } |
118 | } | 119 | } |
119 | 120 | ||
120 | Guard { desc, start: Instant::now() } | 121 | Guard { label, start: Instant::now() } |
121 | } | 122 | } |
122 | 123 | ||
123 | pub struct Profiler { | 124 | pub struct Profiler { |
124 | desc: Option<String>, | 125 | label: Option<Label>, |
125 | } | 126 | } |
126 | 127 | ||
127 | pub struct Filter { | 128 | pub struct Filter { |
@@ -174,7 +175,7 @@ struct ProfileStack { | |||
174 | struct Message { | 175 | struct Message { |
175 | level: usize, | 176 | level: usize, |
176 | duration: Duration, | 177 | duration: Duration, |
177 | message: String, | 178 | label: Label, |
178 | } | 179 | } |
179 | 180 | ||
180 | impl ProfileStack { | 181 | impl ProfileStack { |
@@ -200,14 +201,13 @@ thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(Profile | |||
200 | impl Drop for Profiler { | 201 | impl Drop for Profiler { |
201 | fn drop(&mut self) { | 202 | fn drop(&mut self) { |
202 | match self { | 203 | match self { |
203 | Profiler { desc: Some(desc) } => { | 204 | Profiler { label: Some(label) } => { |
204 | PROFILE_STACK.with(|stack| { | 205 | PROFILE_STACK.with(|stack| { |
205 | let mut stack = stack.borrow_mut(); | 206 | let mut stack = stack.borrow_mut(); |
206 | let start = stack.starts.pop().unwrap(); | 207 | let start = stack.starts.pop().unwrap(); |
207 | let duration = start.elapsed(); | 208 | let duration = start.elapsed(); |
208 | let level = stack.starts.len(); | 209 | let level = stack.starts.len(); |
209 | let message = mem::replace(desc, String::new()); | 210 | stack.messages.push(Message { level, duration, label: label }); |
210 | stack.messages.push(Message { level, duration, message }); | ||
211 | if level == 0 { | 211 | if level == 0 { |
212 | let stdout = stderr(); | 212 | let stdout = stderr(); |
213 | let longer_than = stack.filter_data.longer_than; | 213 | let longer_than = stack.filter_data.longer_than; |
@@ -221,7 +221,7 @@ impl Drop for Profiler { | |||
221 | } | 221 | } |
222 | }); | 222 | }); |
223 | } | 223 | } |
224 | Profiler { desc: None } => (), | 224 | Profiler { label: None } => (), |
225 | } | 225 | } |
226 | } | 226 | } |
227 | } | 227 | } |
@@ -244,7 +244,7 @@ fn print_for_idx( | |||
244 | ) { | 244 | ) { |
245 | let current = &msgs[current_idx]; | 245 | let current = &msgs[current_idx]; |
246 | let current_indent = " ".repeat(current.level); | 246 | let current_indent = " ".repeat(current.level); |
247 | writeln!(out, "{}{:5}ms - {}", current_indent, current.duration.as_millis(), current.message) | 247 | writeln!(out, "{}{:5}ms - {}", current_indent, current.duration.as_millis(), current.label) |
248 | .expect("printing profiling info"); | 248 | .expect("printing profiling info"); |
249 | 249 | ||
250 | let longer_than_millis = longer_than.as_millis(); | 250 | let longer_than_millis = longer_than.as_millis(); |
@@ -257,7 +257,7 @@ fn print_for_idx( | |||
257 | if child.duration.as_millis() > longer_than_millis { | 257 | if child.duration.as_millis() > longer_than_millis { |
258 | print_for_idx(*child_idx, children_map, msgs, longer_than, out); | 258 | print_for_idx(*child_idx, children_map, msgs, longer_than, out); |
259 | } else { | 259 | } else { |
260 | let pair = short_children.entry(&child.message).or_insert((Duration::default(), 0)); | 260 | let pair = short_children.entry(child.label).or_insert((Duration::default(), 0)); |
261 | pair.0 += child.duration; | 261 | pair.0 += child.duration; |
262 | pair.1 += 1; | 262 | pair.1 += 1; |
263 | } | 263 | } |
@@ -409,9 +409,9 @@ mod tests { | |||
409 | fn test_longer_than() { | 409 | fn test_longer_than() { |
410 | let mut result = vec![]; | 410 | let mut result = vec![]; |
411 | let msgs = vec![ | 411 | let msgs = vec![ |
412 | Message { level: 1, duration: Duration::from_nanos(3), message: "bar".to_owned() }, | 412 | Message { level: 1, duration: Duration::from_nanos(3), label: "bar" }, |
413 | Message { level: 1, duration: Duration::from_nanos(2), message: "bar".to_owned() }, | 413 | Message { level: 1, duration: Duration::from_nanos(2), label: "bar" }, |
414 | Message { level: 0, duration: Duration::from_millis(1), message: "foo".to_owned() }, | 414 | Message { level: 0, duration: Duration::from_millis(1), label: "foo" }, |
415 | ]; | 415 | ]; |
416 | print(&msgs, Duration::from_millis(0), &mut result); | 416 | print(&msgs, Duration::from_millis(0), &mut result); |
417 | // 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 |
@@ -426,8 +426,8 @@ mod tests { | |||
426 | fn test_unaccounted_for_topmost() { | 426 | fn test_unaccounted_for_topmost() { |
427 | let mut result = vec![]; | 427 | let mut result = vec![]; |
428 | let msgs = vec![ | 428 | let msgs = vec![ |
429 | Message { level: 1, duration: Duration::from_millis(2), message: "bar".to_owned() }, | 429 | Message { level: 1, duration: Duration::from_millis(2), label: "bar" }, |
430 | Message { level: 0, duration: Duration::from_millis(5), message: "foo".to_owned() }, | 430 | Message { level: 0, duration: Duration::from_millis(5), label: "foo" }, |
431 | ]; | 431 | ]; |
432 | print(&msgs, Duration::from_millis(0), &mut result); | 432 | print(&msgs, Duration::from_millis(0), &mut result); |
433 | assert_eq!( | 433 | assert_eq!( |
@@ -445,11 +445,11 @@ mod tests { | |||
445 | fn test_unaccounted_for_multiple_levels() { | 445 | fn test_unaccounted_for_multiple_levels() { |
446 | let mut result = vec![]; | 446 | let mut result = vec![]; |
447 | let msgs = vec![ | 447 | let msgs = vec![ |
448 | Message { level: 2, duration: Duration::from_millis(3), message: "baz".to_owned() }, | 448 | Message { level: 2, duration: Duration::from_millis(3), label: "baz" }, |
449 | Message { level: 1, duration: Duration::from_millis(5), message: "bar".to_owned() }, | 449 | Message { level: 1, duration: Duration::from_millis(5), label: "bar" }, |
450 | Message { level: 2, duration: Duration::from_millis(2), message: "baz".to_owned() }, | 450 | Message { level: 2, duration: Duration::from_millis(2), label: "baz" }, |
451 | Message { level: 1, duration: Duration::from_millis(4), message: "bar".to_owned() }, | 451 | Message { level: 1, duration: Duration::from_millis(4), label: "bar" }, |
452 | Message { level: 0, duration: Duration::from_millis(9), message: "foo".to_owned() }, | 452 | Message { level: 0, duration: Duration::from_millis(9), label: "foo" }, |
453 | ]; | 453 | ]; |
454 | print(&msgs, Duration::from_millis(0), &mut result); | 454 | print(&msgs, Duration::from_millis(0), &mut result); |
455 | assert_eq!( | 455 | assert_eq!( |