aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorAleksey Kladov <[email protected]>2020-02-02 17:54:26 +0000
committerAleksey Kladov <[email protected]>2020-02-02 17:56:37 +0000
commit24ad1cce2c3cf2c0ce8288fc02c4c55529598990 (patch)
tree04241d931e7d2f57799a4ff28a11f020090def74
parent856e4ba126ae776753f38c00593c02c4f43be510 (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.rs2
-rw-r--r--crates/ra_lsp_server/src/main_loop.rs1
-rw-r--r--crates/ra_prof/src/lib.rs64
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
52pub 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/// ```
80pub fn profile(desc: &str) -> Profiler { 81pub 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
108pub fn print_time(desc: &str) -> impl Drop + '_ { 109pub 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
123pub struct Profiler { 124pub struct Profiler {
124 desc: Option<String>, 125 label: Option<Label>,
125} 126}
126 127
127pub struct Filter { 128pub struct Filter {
@@ -174,7 +175,7 @@ struct ProfileStack {
174struct Message { 175struct Message {
175 level: usize, 176 level: usize,
176 duration: Duration, 177 duration: Duration,
177 message: String, 178 label: Label,
178} 179}
179 180
180impl ProfileStack { 181impl ProfileStack {
@@ -200,14 +201,13 @@ thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(Profile
200impl Drop for Profiler { 201impl 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!(