diff options
Diffstat (limited to 'crates')
-rw-r--r-- | crates/ra_arena/src/lib.rs | 3 | ||||
-rw-r--r-- | crates/ra_hir_ty/src/infer.rs | 5 | ||||
-rw-r--r-- | crates/ra_prof/Cargo.toml | 1 | ||||
-rw-r--r-- | crates/ra_prof/src/hprof.rs | 246 | ||||
-rw-r--r-- | crates/ra_prof/src/lib.rs | 398 | ||||
-rw-r--r-- | crates/ra_prof/src/tree.rs | 84 | ||||
-rw-r--r-- | crates/rust-analyzer/tests/heavy_tests/support.rs | 6 |
7 files changed, 345 insertions, 398 deletions
diff --git a/crates/ra_arena/src/lib.rs b/crates/ra_arena/src/lib.rs index ea98d5444..441fbb3cb 100644 --- a/crates/ra_arena/src/lib.rs +++ b/crates/ra_arena/src/lib.rs | |||
@@ -96,6 +96,9 @@ impl<T> Arena<T> { | |||
96 | pub const fn new() -> Arena<T> { | 96 | pub const fn new() -> Arena<T> { |
97 | Arena { data: Vec::new() } | 97 | Arena { data: Vec::new() } |
98 | } | 98 | } |
99 | pub fn clear(&mut self) { | ||
100 | self.data.clear(); | ||
101 | } | ||
99 | 102 | ||
100 | pub fn len(&self) -> usize { | 103 | pub fn len(&self) -> usize { |
101 | self.data.len() | 104 | self.data.len() |
diff --git a/crates/ra_hir_ty/src/infer.rs b/crates/ra_hir_ty/src/infer.rs index 6a53be621..bd4ef69a0 100644 --- a/crates/ra_hir_ty/src/infer.rs +++ b/crates/ra_hir_ty/src/infer.rs | |||
@@ -667,7 +667,7 @@ impl Expectation { | |||
667 | } | 667 | } |
668 | 668 | ||
669 | mod diagnostics { | 669 | mod diagnostics { |
670 | use hir_def::{expr::ExprId, src::HasSource, FunctionId, Lookup}; | 670 | use hir_def::{expr::ExprId, FunctionId}; |
671 | use hir_expand::diagnostics::DiagnosticSink; | 671 | use hir_expand::diagnostics::DiagnosticSink; |
672 | 672 | ||
673 | use crate::{db::HirDatabase, diagnostics::NoSuchField}; | 673 | use crate::{db::HirDatabase, diagnostics::NoSuchField}; |
@@ -686,10 +686,9 @@ mod diagnostics { | |||
686 | ) { | 686 | ) { |
687 | match self { | 687 | match self { |
688 | InferenceDiagnostic::NoSuchField { expr, field } => { | 688 | InferenceDiagnostic::NoSuchField { expr, field } => { |
689 | let source = owner.lookup(db.upcast()).source(db.upcast()); | ||
690 | let (_, source_map) = db.body_with_source_map(owner.into()); | 689 | let (_, source_map) = db.body_with_source_map(owner.into()); |
691 | let field = source_map.field_syntax(*expr, *field); | 690 | let field = source_map.field_syntax(*expr, *field); |
692 | sink.push(NoSuchField { file: source.file_id, field: field.value }) | 691 | sink.push(NoSuchField { file: field.file_id, field: field.value }) |
693 | } | 692 | } |
694 | } | 693 | } |
695 | } | 694 | } |
diff --git a/crates/ra_prof/Cargo.toml b/crates/ra_prof/Cargo.toml index d15b08992..c33b5121a 100644 --- a/crates/ra_prof/Cargo.toml +++ b/crates/ra_prof/Cargo.toml | |||
@@ -9,6 +9,7 @@ publish = false | |||
9 | doctest = false | 9 | doctest = false |
10 | 10 | ||
11 | [dependencies] | 11 | [dependencies] |
12 | ra_arena = { path = "../ra_arena" } | ||
12 | once_cell = "1.3.1" | 13 | once_cell = "1.3.1" |
13 | backtrace = { version = "0.3.44", optional = true } | 14 | backtrace = { version = "0.3.44", optional = true } |
14 | 15 | ||
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs new file mode 100644 index 000000000..2b8a90363 --- /dev/null +++ b/crates/ra_prof/src/hprof.rs | |||
@@ -0,0 +1,246 @@ | |||
1 | //! Simple hierarchical profiler | ||
2 | use once_cell::sync::Lazy; | ||
3 | use std::{ | ||
4 | cell::RefCell, | ||
5 | collections::{BTreeMap, HashSet}, | ||
6 | io::{stderr, Write}, | ||
7 | sync::{ | ||
8 | atomic::{AtomicBool, Ordering}, | ||
9 | RwLock, | ||
10 | }, | ||
11 | time::{Duration, Instant}, | ||
12 | }; | ||
13 | |||
14 | use crate::tree::{Idx, Tree}; | ||
15 | |||
16 | /// Filtering syntax | ||
17 | /// env RA_PROFILE=* // dump everything | ||
18 | /// env RA_PROFILE=foo|bar|baz // enabled only selected entries | ||
19 | /// env RA_PROFILE=*@3>10 // dump everything, up to depth 3, if it takes more than 10 ms | ||
20 | pub fn init() { | ||
21 | let spec = std::env::var("RA_PROFILE").unwrap_or_default(); | ||
22 | init_from(&spec); | ||
23 | } | ||
24 | |||
25 | pub fn init_from(spec: &str) { | ||
26 | let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) }; | ||
27 | filter.install(); | ||
28 | } | ||
29 | |||
30 | pub type Label = &'static str; | ||
31 | |||
32 | /// This function starts a profiling scope in the current execution stack with a given description. | ||
33 | /// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop. | ||
34 | /// 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. | ||
35 | /// Profiling information is being printed in the stderr. | ||
36 | /// | ||
37 | /// # Example | ||
38 | /// ``` | ||
39 | /// use ra_prof::{profile, set_filter, Filter}; | ||
40 | /// | ||
41 | /// let f = Filter::from_spec("profile1|profile2@2"); | ||
42 | /// set_filter(f); | ||
43 | /// profiling_function1(); | ||
44 | /// | ||
45 | /// fn profiling_function1() { | ||
46 | /// let _p = profile("profile1"); | ||
47 | /// profiling_function2(); | ||
48 | /// } | ||
49 | /// | ||
50 | /// fn profiling_function2() { | ||
51 | /// let _p = profile("profile2"); | ||
52 | /// } | ||
53 | /// ``` | ||
54 | /// This will print in the stderr the following: | ||
55 | /// ```text | ||
56 | /// 0ms - profile | ||
57 | /// 0ms - profile2 | ||
58 | /// ``` | ||
59 | pub fn profile(label: Label) -> Profiler { | ||
60 | assert!(!label.is_empty()); | ||
61 | let enabled = PROFILING_ENABLED.load(Ordering::Relaxed) | ||
62 | && PROFILE_STACK.with(|stack| stack.borrow_mut().push(label)); | ||
63 | let label = if enabled { Some(label) } else { None }; | ||
64 | Profiler { label, detail: None } | ||
65 | } | ||
66 | |||
67 | pub struct Profiler { | ||
68 | label: Option<Label>, | ||
69 | detail: Option<String>, | ||
70 | } | ||
71 | |||
72 | impl Profiler { | ||
73 | pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler { | ||
74 | if self.label.is_some() { | ||
75 | self.detail = Some(detail()) | ||
76 | } | ||
77 | self | ||
78 | } | ||
79 | } | ||
80 | |||
81 | impl Drop for Profiler { | ||
82 | fn drop(&mut self) { | ||
83 | match self { | ||
84 | Profiler { label: Some(label), detail } => { | ||
85 | PROFILE_STACK.with(|stack| { | ||
86 | stack.borrow_mut().pop(label, detail.take()); | ||
87 | }); | ||
88 | } | ||
89 | Profiler { label: None, .. } => (), | ||
90 | } | ||
91 | } | ||
92 | } | ||
93 | |||
94 | static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false); | ||
95 | static FILTER: Lazy<RwLock<Filter>> = Lazy::new(Default::default); | ||
96 | thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new())); | ||
97 | |||
98 | #[derive(Default, Clone, Debug)] | ||
99 | struct Filter { | ||
100 | depth: usize, | ||
101 | allowed: HashSet<String>, | ||
102 | longer_than: Duration, | ||
103 | version: usize, | ||
104 | } | ||
105 | |||
106 | impl Filter { | ||
107 | fn disabled() -> Filter { | ||
108 | Filter::default() | ||
109 | } | ||
110 | |||
111 | fn from_spec(mut spec: &str) -> Filter { | ||
112 | let longer_than = if let Some(idx) = spec.rfind('>') { | ||
113 | let longer_than = spec[idx + 1..].parse().expect("invalid profile longer_than"); | ||
114 | spec = &spec[..idx]; | ||
115 | Duration::from_millis(longer_than) | ||
116 | } else { | ||
117 | Duration::new(0, 0) | ||
118 | }; | ||
119 | |||
120 | let depth = if let Some(idx) = spec.rfind('@') { | ||
121 | let depth: usize = spec[idx + 1..].parse().expect("invalid profile depth"); | ||
122 | spec = &spec[..idx]; | ||
123 | depth | ||
124 | } else { | ||
125 | 999 | ||
126 | }; | ||
127 | let allowed = | ||
128 | if spec == "*" { HashSet::new() } else { spec.split('|').map(String::from).collect() }; | ||
129 | Filter { depth, allowed, longer_than, version: 0 } | ||
130 | } | ||
131 | |||
132 | fn install(mut self) { | ||
133 | PROFILING_ENABLED.store(self.depth > 0, Ordering::SeqCst); | ||
134 | let mut old = FILTER.write().unwrap(); | ||
135 | self.version = old.version + 1; | ||
136 | *old = self; | ||
137 | } | ||
138 | } | ||
139 | |||
140 | struct ProfileStack { | ||
141 | starts: Vec<Instant>, | ||
142 | filter: Filter, | ||
143 | messages: Tree<Message>, | ||
144 | } | ||
145 | |||
146 | #[derive(Default)] | ||
147 | struct Message { | ||
148 | duration: Duration, | ||
149 | label: Label, | ||
150 | detail: Option<String>, | ||
151 | } | ||
152 | |||
153 | impl ProfileStack { | ||
154 | fn new() -> ProfileStack { | ||
155 | ProfileStack { starts: Vec::new(), messages: Tree::default(), filter: Default::default() } | ||
156 | } | ||
157 | |||
158 | fn push(&mut self, label: Label) -> bool { | ||
159 | if self.starts.is_empty() { | ||
160 | if let Ok(f) = FILTER.try_read() { | ||
161 | if f.version > self.filter.version { | ||
162 | self.filter = f.clone(); | ||
163 | } | ||
164 | }; | ||
165 | } | ||
166 | if self.starts.len() > self.filter.depth { | ||
167 | return false; | ||
168 | } | ||
169 | let allowed = &self.filter.allowed; | ||
170 | if self.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) { | ||
171 | return false; | ||
172 | } | ||
173 | |||
174 | self.starts.push(Instant::now()); | ||
175 | self.messages.start(); | ||
176 | true | ||
177 | } | ||
178 | |||
179 | pub fn pop(&mut self, label: Label, detail: Option<String>) { | ||
180 | let start = self.starts.pop().unwrap(); | ||
181 | let duration = start.elapsed(); | ||
182 | let level = self.starts.len(); | ||
183 | self.messages.finish(Message { duration, label, detail }); | ||
184 | if level == 0 { | ||
185 | let longer_than = self.filter.longer_than; | ||
186 | // Convert to millis for comparison to avoid problems with rounding | ||
187 | // (otherwise we could print `0ms` despite user's `>0` filter when | ||
188 | // `duration` is just a few nanos). | ||
189 | if duration.as_millis() > longer_than.as_millis() { | ||
190 | let stderr = stderr(); | ||
191 | if let Some(root) = self.messages.root() { | ||
192 | print(&self.messages, root, 0, longer_than, &mut stderr.lock()); | ||
193 | } | ||
194 | } | ||
195 | self.messages.clear(); | ||
196 | assert!(self.starts.is_empty()) | ||
197 | } | ||
198 | } | ||
199 | } | ||
200 | |||
201 | fn print( | ||
202 | tree: &Tree<Message>, | ||
203 | curr: Idx<Message>, | ||
204 | level: u32, | ||
205 | longer_than: Duration, | ||
206 | out: &mut impl Write, | ||
207 | ) { | ||
208 | let current_indent = " ".repeat(level as usize); | ||
209 | let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); | ||
210 | writeln!( | ||
211 | out, | ||
212 | "{}{:5}ms - {}{}", | ||
213 | current_indent, | ||
214 | tree[curr].duration.as_millis(), | ||
215 | tree[curr].label, | ||
216 | detail, | ||
217 | ) | ||
218 | .expect("printing profiling info"); | ||
219 | |||
220 | let mut accounted_for = Duration::default(); | ||
221 | let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output. | ||
222 | for child in tree.children(curr) { | ||
223 | accounted_for += tree[child].duration; | ||
224 | |||
225 | if tree[child].duration.as_millis() > longer_than.as_millis() { | ||
226 | print(tree, child, level + 1, longer_than, out) | ||
227 | } else { | ||
228 | let (total_duration, cnt) = | ||
229 | short_children.entry(tree[child].label).or_insert((Duration::default(), 0)); | ||
230 | *total_duration += tree[child].duration; | ||
231 | *cnt += 1; | ||
232 | } | ||
233 | } | ||
234 | |||
235 | for (child_msg, (duration, count)) in short_children.iter() { | ||
236 | let millis = duration.as_millis(); | ||
237 | writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count) | ||
238 | .expect("printing profiling info"); | ||
239 | } | ||
240 | |||
241 | let unaccounted = tree[curr].duration - accounted_for; | ||
242 | if tree.children(curr).next().is_some() && unaccounted > longer_than { | ||
243 | writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted.as_millis()) | ||
244 | .expect("printing profiling info"); | ||
245 | } | ||
246 | } | ||
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index 2d4f68f5e..89df7f04b 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs | |||
@@ -1,24 +1,17 @@ | |||
1 | //! FIXME: write short doc here | 1 | //! A collection of tools for profiling rust-analyzer. |
2 | 2 | ||
3 | mod memory_usage; | 3 | mod memory_usage; |
4 | #[cfg(feature = "cpu_profiler")] | 4 | #[cfg(feature = "cpu_profiler")] |
5 | mod google_cpu_profiler; | 5 | mod google_cpu_profiler; |
6 | mod hprof; | ||
7 | mod tree; | ||
6 | 8 | ||
7 | use std::{ | 9 | use std::cell::RefCell; |
8 | cell::RefCell, | ||
9 | collections::BTreeMap, | ||
10 | collections::HashSet, | ||
11 | io::{stderr, Write}, | ||
12 | sync::{ | ||
13 | atomic::{AtomicBool, Ordering}, | ||
14 | RwLock, | ||
15 | }, | ||
16 | time::{Duration, Instant}, | ||
17 | }; | ||
18 | |||
19 | use once_cell::sync::Lazy; | ||
20 | 10 | ||
21 | pub use crate::memory_usage::{Bytes, MemoryUsage}; | 11 | pub use crate::{ |
12 | hprof::{init, init_from, profile}, | ||
13 | memory_usage::{Bytes, MemoryUsage}, | ||
14 | }; | ||
22 | 15 | ||
23 | // We use jemalloc mainly to get heap usage statistics, actual performance | 16 | // We use jemalloc mainly to get heap usage statistics, actual performance |
24 | // difference is not measures. | 17 | // difference is not measures. |
@@ -26,298 +19,6 @@ pub use crate::memory_usage::{Bytes, MemoryUsage}; | |||
26 | #[global_allocator] | 19 | #[global_allocator] |
27 | static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc; | 20 | static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc; |
28 | 21 | ||
29 | pub fn init() { | ||
30 | set_filter(match std::env::var("RA_PROFILE") { | ||
31 | Ok(spec) => Filter::from_spec(&spec), | ||
32 | Err(_) => Filter::disabled(), | ||
33 | }); | ||
34 | } | ||
35 | |||
36 | /// Set profiling filter. It specifies descriptions allowed to profile. | ||
37 | /// This is helpful when call stack has too many nested profiling scopes. | ||
38 | /// Additionally filter can specify maximum depth of profiling scopes nesting. | ||
39 | /// | ||
40 | /// #Example | ||
41 | /// ``` | ||
42 | /// use ra_prof::{set_filter, Filter}; | ||
43 | /// let f = Filter::from_spec("profile1|profile2@2"); | ||
44 | /// set_filter(f); | ||
45 | /// ``` | ||
46 | pub fn set_filter(f: Filter) { | ||
47 | PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst); | ||
48 | let set: HashSet<_> = f.allowed.iter().cloned().collect(); | ||
49 | let mut old = FILTER.write().unwrap(); | ||
50 | let filter_data = FilterData { | ||
51 | depth: f.depth, | ||
52 | allowed: set, | ||
53 | longer_than: f.longer_than, | ||
54 | version: old.version + 1, | ||
55 | }; | ||
56 | *old = filter_data; | ||
57 | } | ||
58 | |||
59 | pub type Label = &'static str; | ||
60 | |||
61 | /// This function starts a profiling scope in the current execution stack with a given description. | ||
62 | /// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop. | ||
63 | /// 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. | ||
64 | /// Profiling information is being printed in the stderr. | ||
65 | /// | ||
66 | /// # Example | ||
67 | /// ``` | ||
68 | /// use ra_prof::{profile, set_filter, Filter}; | ||
69 | /// | ||
70 | /// let f = Filter::from_spec("profile1|profile2@2"); | ||
71 | /// set_filter(f); | ||
72 | /// profiling_function1(); | ||
73 | /// | ||
74 | /// fn profiling_function1() { | ||
75 | /// let _p = profile("profile1"); | ||
76 | /// profiling_function2(); | ||
77 | /// } | ||
78 | /// | ||
79 | /// fn profiling_function2() { | ||
80 | /// let _p = profile("profile2"); | ||
81 | /// } | ||
82 | /// ``` | ||
83 | /// This will print in the stderr the following: | ||
84 | /// ```text | ||
85 | /// 0ms - profile | ||
86 | /// 0ms - profile2 | ||
87 | /// ``` | ||
88 | pub fn profile(label: Label) -> Profiler { | ||
89 | assert!(!label.is_empty()); | ||
90 | if !PROFILING_ENABLED.load(Ordering::Relaxed) { | ||
91 | return Profiler { label: None, detail: None }; | ||
92 | } | ||
93 | |||
94 | PROFILE_STACK.with(|stack| { | ||
95 | let mut stack = stack.borrow_mut(); | ||
96 | if stack.starts.is_empty() { | ||
97 | if let Ok(f) = FILTER.try_read() { | ||
98 | if f.version > stack.filter_data.version { | ||
99 | stack.filter_data = f.clone(); | ||
100 | } | ||
101 | }; | ||
102 | } | ||
103 | if stack.starts.len() > stack.filter_data.depth { | ||
104 | return Profiler { label: None, detail: None }; | ||
105 | } | ||
106 | let allowed = &stack.filter_data.allowed; | ||
107 | if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) { | ||
108 | return Profiler { label: None, detail: None }; | ||
109 | } | ||
110 | |||
111 | stack.starts.push(Instant::now()); | ||
112 | Profiler { label: Some(label), detail: None } | ||
113 | }) | ||
114 | } | ||
115 | |||
116 | pub struct Profiler { | ||
117 | label: Option<Label>, | ||
118 | detail: Option<String>, | ||
119 | } | ||
120 | |||
121 | impl Profiler { | ||
122 | pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler { | ||
123 | if self.label.is_some() { | ||
124 | self.detail = Some(detail()) | ||
125 | } | ||
126 | self | ||
127 | } | ||
128 | } | ||
129 | |||
130 | pub struct Filter { | ||
131 | depth: usize, | ||
132 | allowed: Vec<String>, | ||
133 | longer_than: Duration, | ||
134 | } | ||
135 | |||
136 | impl Filter { | ||
137 | // Filtering syntax | ||
138 | // env RA_PROFILE=* // dump everything | ||
139 | // env RA_PROFILE=foo|bar|baz // enabled only selected entries | ||
140 | // env RA_PROFILE=*@3>10 // dump everything, up to depth 3, if it takes more than 10 ms | ||
141 | pub fn from_spec(mut spec: &str) -> Filter { | ||
142 | let longer_than = if let Some(idx) = spec.rfind('>') { | ||
143 | let longer_than = spec[idx + 1..].parse().expect("invalid profile longer_than"); | ||
144 | spec = &spec[..idx]; | ||
145 | Duration::from_millis(longer_than) | ||
146 | } else { | ||
147 | Duration::new(0, 0) | ||
148 | }; | ||
149 | |||
150 | let depth = if let Some(idx) = spec.rfind('@') { | ||
151 | let depth: usize = spec[idx + 1..].parse().expect("invalid profile depth"); | ||
152 | spec = &spec[..idx]; | ||
153 | depth | ||
154 | } else { | ||
155 | 999 | ||
156 | }; | ||
157 | let allowed = | ||
158 | if spec == "*" { Vec::new() } else { spec.split('|').map(String::from).collect() }; | ||
159 | Filter::new(depth, allowed, longer_than) | ||
160 | } | ||
161 | |||
162 | pub fn disabled() -> Filter { | ||
163 | Filter::new(0, Vec::new(), Duration::new(0, 0)) | ||
164 | } | ||
165 | |||
166 | pub fn new(depth: usize, allowed: Vec<String>, longer_than: Duration) -> Filter { | ||
167 | Filter { depth, allowed, longer_than } | ||
168 | } | ||
169 | } | ||
170 | |||
171 | struct ProfileStack { | ||
172 | starts: Vec<Instant>, | ||
173 | messages: Vec<Message>, | ||
174 | filter_data: FilterData, | ||
175 | } | ||
176 | |||
177 | struct Message { | ||
178 | level: usize, | ||
179 | duration: Duration, | ||
180 | label: Label, | ||
181 | detail: Option<String>, | ||
182 | } | ||
183 | |||
184 | impl ProfileStack { | ||
185 | fn new() -> ProfileStack { | ||
186 | ProfileStack { starts: Vec::new(), messages: Vec::new(), filter_data: Default::default() } | ||
187 | } | ||
188 | } | ||
189 | |||
190 | #[derive(Default, Clone)] | ||
191 | struct FilterData { | ||
192 | depth: usize, | ||
193 | version: usize, | ||
194 | allowed: HashSet<String>, | ||
195 | longer_than: Duration, | ||
196 | } | ||
197 | |||
198 | static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false); | ||
199 | |||
200 | static FILTER: Lazy<RwLock<FilterData>> = Lazy::new(Default::default); | ||
201 | |||
202 | thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new())); | ||
203 | |||
204 | impl Drop for Profiler { | ||
205 | fn drop(&mut self) { | ||
206 | match self { | ||
207 | Profiler { label: Some(label), detail } => { | ||
208 | PROFILE_STACK.with(|stack| { | ||
209 | let mut stack = stack.borrow_mut(); | ||
210 | let start = stack.starts.pop().unwrap(); | ||
211 | let duration = start.elapsed(); | ||
212 | let level = stack.starts.len(); | ||
213 | stack.messages.push(Message { level, duration, label, detail: detail.take() }); | ||
214 | if level == 0 { | ||
215 | let stdout = stderr(); | ||
216 | let longer_than = stack.filter_data.longer_than; | ||
217 | // Convert to millis for comparison to avoid problems with rounding | ||
218 | // (otherwise we could print `0ms` despite user's `>0` filter when | ||
219 | // `duration` is just a few nanos). | ||
220 | if duration.as_millis() > longer_than.as_millis() { | ||
221 | print(&stack.messages, longer_than, &mut stdout.lock()); | ||
222 | } | ||
223 | stack.messages.clear(); | ||
224 | } | ||
225 | }); | ||
226 | } | ||
227 | Profiler { label: None, .. } => (), | ||
228 | } | ||
229 | } | ||
230 | } | ||
231 | |||
232 | fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) { | ||
233 | if msgs.is_empty() { | ||
234 | return; | ||
235 | } | ||
236 | let children_map = idx_to_children(msgs); | ||
237 | let root_idx = msgs.len() - 1; | ||
238 | print_for_idx(root_idx, &children_map, msgs, longer_than, out); | ||
239 | } | ||
240 | |||
241 | fn print_for_idx( | ||
242 | current_idx: usize, | ||
243 | children_map: &[Vec<usize>], | ||
244 | msgs: &[Message], | ||
245 | longer_than: Duration, | ||
246 | out: &mut impl Write, | ||
247 | ) { | ||
248 | let current = &msgs[current_idx]; | ||
249 | let current_indent = " ".repeat(current.level); | ||
250 | let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); | ||
251 | writeln!( | ||
252 | out, | ||
253 | "{}{:5}ms - {}{}", | ||
254 | current_indent, | ||
255 | current.duration.as_millis(), | ||
256 | current.label, | ||
257 | detail, | ||
258 | ) | ||
259 | .expect("printing profiling info"); | ||
260 | |||
261 | let longer_than_millis = longer_than.as_millis(); | ||
262 | let children_indices = &children_map[current_idx]; | ||
263 | let mut accounted_for = Duration::default(); | ||
264 | let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output. | ||
265 | |||
266 | for child_idx in children_indices.iter() { | ||
267 | let child = &msgs[*child_idx]; | ||
268 | if child.duration.as_millis() > longer_than_millis { | ||
269 | print_for_idx(*child_idx, children_map, msgs, longer_than, out); | ||
270 | } else { | ||
271 | let pair = short_children.entry(child.label).or_insert((Duration::default(), 0)); | ||
272 | pair.0 += child.duration; | ||
273 | pair.1 += 1; | ||
274 | } | ||
275 | accounted_for += child.duration; | ||
276 | } | ||
277 | |||
278 | for (child_msg, (duration, count)) in short_children.iter() { | ||
279 | let millis = duration.as_millis(); | ||
280 | writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count) | ||
281 | .expect("printing profiling info"); | ||
282 | } | ||
283 | |||
284 | let unaccounted_millis = (current.duration - accounted_for).as_millis(); | ||
285 | if !children_indices.is_empty() | ||
286 | && unaccounted_millis > 0 | ||
287 | && unaccounted_millis > longer_than_millis | ||
288 | { | ||
289 | writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis) | ||
290 | .expect("printing profiling info"); | ||
291 | } | ||
292 | } | ||
293 | |||
294 | /// Returns a mapping from an index in the `msgs` to the vector with the indices of its children. | ||
295 | /// | ||
296 | /// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish. | ||
297 | /// In other words, a postorder of the call graph. In particular, the root is the last element of | ||
298 | /// `msgs`. | ||
299 | fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> { | ||
300 | // Initialize with the index of the root; `msgs` and `ancestors` should be never empty. | ||
301 | assert!(!msgs.is_empty()); | ||
302 | let mut ancestors = vec![msgs.len() - 1]; | ||
303 | let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()]; | ||
304 | for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() { | ||
305 | // We need to find the parent of the current message, i.e., the last ancestor that has a | ||
306 | // level lower than the current message. | ||
307 | while msgs[*ancestors.last().unwrap()].level >= msg.level { | ||
308 | ancestors.pop(); | ||
309 | } | ||
310 | result[*ancestors.last().unwrap()].push(idx); | ||
311 | ancestors.push(idx); | ||
312 | } | ||
313 | // Note that above we visited all children from the last to the first one. Let's reverse vectors | ||
314 | // to get the more natural order where the first element is the first child. | ||
315 | for vec in result.iter_mut() { | ||
316 | vec.reverse(); | ||
317 | } | ||
318 | result | ||
319 | } | ||
320 | |||
321 | /// Prints backtrace to stderr, useful for debugging. | 22 | /// Prints backtrace to stderr, useful for debugging. |
322 | #[cfg(feature = "backtrace")] | 23 | #[cfg(feature = "backtrace")] |
323 | pub fn print_backtrace() { | 24 | pub fn print_backtrace() { |
@@ -403,86 +104,3 @@ impl Drop for CpuProfiler { | |||
403 | pub fn memory_usage() -> MemoryUsage { | 104 | pub fn memory_usage() -> MemoryUsage { |
404 | MemoryUsage::current() | 105 | MemoryUsage::current() |
405 | } | 106 | } |
406 | |||
407 | #[cfg(test)] | ||
408 | mod tests { | ||
409 | use super::*; | ||
410 | |||
411 | #[test] | ||
412 | fn test_basic_profile() { | ||
413 | let s = vec!["profile1".to_string(), "profile2".to_string()]; | ||
414 | let f = Filter::new(2, s, Duration::new(0, 0)); | ||
415 | set_filter(f); | ||
416 | profiling_function1(); | ||
417 | } | ||
418 | |||
419 | fn profiling_function1() { | ||
420 | let _p = profile("profile1"); | ||
421 | profiling_function2(); | ||
422 | } | ||
423 | |||
424 | fn profiling_function2() { | ||
425 | let _p = profile("profile2"); | ||
426 | } | ||
427 | |||
428 | #[test] | ||
429 | fn test_longer_than() { | ||
430 | let mut result = vec![]; | ||
431 | let msgs = vec![ | ||
432 | Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None }, | ||
433 | Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None }, | ||
434 | Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None }, | ||
435 | ]; | ||
436 | print(&msgs, Duration::from_millis(0), &mut result); | ||
437 | // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed | ||
438 | // when printing. | ||
439 | assert_eq!( | ||
440 | std::str::from_utf8(&result).unwrap(), | ||
441 | " 1ms - foo\n 0ms - bar (2 calls)\n" | ||
442 | ); | ||
443 | } | ||
444 | |||
445 | #[test] | ||
446 | fn test_unaccounted_for_topmost() { | ||
447 | let mut result = vec![]; | ||
448 | let msgs = vec![ | ||
449 | Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None }, | ||
450 | Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None }, | ||
451 | ]; | ||
452 | print(&msgs, Duration::from_millis(0), &mut result); | ||
453 | assert_eq!( | ||
454 | std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), | ||
455 | vec![ | ||
456 | " 5ms - foo", | ||
457 | " 2ms - bar", | ||
458 | " 3ms - ???", | ||
459 | // Dummy comment to improve formatting | ||
460 | ] | ||
461 | ); | ||
462 | } | ||
463 | |||
464 | #[test] | ||
465 | fn test_unaccounted_for_multiple_levels() { | ||
466 | let mut result = vec![]; | ||
467 | let msgs = vec![ | ||
468 | Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None }, | ||
469 | Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None }, | ||
470 | Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None }, | ||
471 | Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None }, | ||
472 | Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None }, | ||
473 | ]; | ||
474 | print(&msgs, Duration::from_millis(0), &mut result); | ||
475 | assert_eq!( | ||
476 | std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), | ||
477 | vec![ | ||
478 | " 9ms - foo", | ||
479 | " 5ms - bar", | ||
480 | " 3ms - baz", | ||
481 | " 2ms - ???", | ||
482 | " 4ms - bar", | ||
483 | " 2ms - baz", | ||
484 | " 2ms - ???", | ||
485 | ] | ||
486 | ); | ||
487 | } | ||
488 | } | ||
diff --git a/crates/ra_prof/src/tree.rs b/crates/ra_prof/src/tree.rs new file mode 100644 index 000000000..9ea5b5db8 --- /dev/null +++ b/crates/ra_prof/src/tree.rs | |||
@@ -0,0 +1,84 @@ | |||
1 | //! A simple tree implementation which tries to not allocate all over the place. | ||
2 | use std::ops; | ||
3 | |||
4 | use ra_arena::Arena; | ||
5 | |||
6 | #[derive(Default)] | ||
7 | pub struct Tree<T> { | ||
8 | nodes: Arena<Node<T>>, | ||
9 | current_path: Vec<(Idx<T>, Option<Idx<T>>)>, | ||
10 | } | ||
11 | |||
12 | pub type Idx<T> = ra_arena::Idx<Node<T>>; | ||
13 | |||
14 | impl<T> Tree<T> { | ||
15 | pub fn start(&mut self) | ||
16 | where | ||
17 | T: Default, | ||
18 | { | ||
19 | let me = self.nodes.alloc(Node::new(T::default())); | ||
20 | if let Some((parent, last_child)) = self.current_path.last_mut() { | ||
21 | let slot = match *last_child { | ||
22 | Some(last_child) => &mut self.nodes[last_child].next_sibling, | ||
23 | None => &mut self.nodes[*parent].first_child, | ||
24 | }; | ||
25 | let prev = slot.replace(me); | ||
26 | assert!(prev.is_none()); | ||
27 | *last_child = Some(me); | ||
28 | } | ||
29 | |||
30 | self.current_path.push((me, None)); | ||
31 | } | ||
32 | |||
33 | pub fn finish(&mut self, data: T) { | ||
34 | let (me, _last_child) = self.current_path.pop().unwrap(); | ||
35 | self.nodes[me].data = data; | ||
36 | } | ||
37 | |||
38 | pub fn root(&self) -> Option<Idx<T>> { | ||
39 | self.nodes.iter().next().map(|(idx, _)| idx) | ||
40 | } | ||
41 | |||
42 | pub fn children(&self, idx: Idx<T>) -> impl Iterator<Item = Idx<T>> + '_ { | ||
43 | NodeIter { nodes: &self.nodes, next: self.nodes[idx].first_child } | ||
44 | } | ||
45 | pub fn clear(&mut self) { | ||
46 | self.nodes.clear(); | ||
47 | self.current_path.clear(); | ||
48 | } | ||
49 | } | ||
50 | |||
51 | impl<T> ops::Index<Idx<T>> for Tree<T> { | ||
52 | type Output = T; | ||
53 | fn index(&self, index: Idx<T>) -> &T { | ||
54 | &self.nodes[index].data | ||
55 | } | ||
56 | } | ||
57 | |||
58 | pub struct Node<T> { | ||
59 | data: T, | ||
60 | first_child: Option<Idx<T>>, | ||
61 | next_sibling: Option<Idx<T>>, | ||
62 | } | ||
63 | |||
64 | impl<T> Node<T> { | ||
65 | fn new(data: T) -> Node<T> { | ||
66 | Node { data, first_child: None, next_sibling: None } | ||
67 | } | ||
68 | } | ||
69 | |||
70 | struct NodeIter<'a, T> { | ||
71 | nodes: &'a Arena<Node<T>>, | ||
72 | next: Option<Idx<T>>, | ||
73 | } | ||
74 | |||
75 | impl<'a, T> Iterator for NodeIter<'a, T> { | ||
76 | type Item = Idx<T>; | ||
77 | |||
78 | fn next(&mut self) -> Option<Idx<T>> { | ||
79 | self.next.map(|next| { | ||
80 | self.next = self.nodes[next].next_sibling; | ||
81 | next | ||
82 | }) | ||
83 | } | ||
84 | } | ||
diff --git a/crates/rust-analyzer/tests/heavy_tests/support.rs b/crates/rust-analyzer/tests/heavy_tests/support.rs index 7eebedff7..e4fe3411a 100644 --- a/crates/rust-analyzer/tests/heavy_tests/support.rs +++ b/crates/rust-analyzer/tests/heavy_tests/support.rs | |||
@@ -62,11 +62,7 @@ impl<'a> Project<'a> { | |||
62 | static INIT: Once = Once::new(); | 62 | static INIT: Once = Once::new(); |
63 | INIT.call_once(|| { | 63 | INIT.call_once(|| { |
64 | env_logger::builder().is_test(true).try_init().unwrap(); | 64 | env_logger::builder().is_test(true).try_init().unwrap(); |
65 | ra_prof::set_filter(if crate::PROFILE.is_empty() { | 65 | ra_prof::init_from(crate::PROFILE); |
66 | ra_prof::Filter::disabled() | ||
67 | } else { | ||
68 | ra_prof::Filter::from_spec(&crate::PROFILE) | ||
69 | }); | ||
70 | }); | 66 | }); |
71 | 67 | ||
72 | let mut paths = vec![]; | 68 | let mut paths = vec![]; |