diff options
author | Aleksey Kladov <[email protected]> | 2020-04-25 20:04:04 +0100 |
---|---|---|
committer | Aleksey Kladov <[email protected]> | 2020-04-25 20:22:40 +0100 |
commit | bd9ede0ec9fb76c8cc0b572ef0405811e1cb666e (patch) | |
tree | 723ee0cd16b656a8db5c65ac65b16cc841608126 /crates/ra_prof/src | |
parent | 0f099ead8893fa9551e385b030a4239ea1338451 (diff) |
Extract messy tree handling out of profiling code
Diffstat (limited to 'crates/ra_prof/src')
-rw-r--r-- | crates/ra_prof/src/hprof.rs | 179 | ||||
-rw-r--r-- | crates/ra_prof/src/lib.rs | 1 | ||||
-rw-r--r-- | crates/ra_prof/src/tree.rs | 84 |
3 files changed, 114 insertions, 150 deletions
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs index 4bbe5cb12..2b8a90363 100644 --- a/crates/ra_prof/src/hprof.rs +++ b/crates/ra_prof/src/hprof.rs | |||
@@ -1,4 +1,5 @@ | |||
1 | //! Simple hierarchical profiler | 1 | //! Simple hierarchical profiler |
2 | use once_cell::sync::Lazy; | ||
2 | use std::{ | 3 | use std::{ |
3 | cell::RefCell, | 4 | cell::RefCell, |
4 | collections::{BTreeMap, HashSet}, | 5 | collections::{BTreeMap, HashSet}, |
@@ -10,7 +11,7 @@ use std::{ | |||
10 | time::{Duration, Instant}, | 11 | time::{Duration, Instant}, |
11 | }; | 12 | }; |
12 | 13 | ||
13 | use once_cell::sync::Lazy; | 14 | use crate::tree::{Idx, Tree}; |
14 | 15 | ||
15 | /// Filtering syntax | 16 | /// Filtering syntax |
16 | /// env RA_PROFILE=* // dump everything | 17 | /// env RA_PROFILE=* // dump everything |
@@ -138,12 +139,12 @@ impl Filter { | |||
138 | 139 | ||
139 | struct ProfileStack { | 140 | struct ProfileStack { |
140 | starts: Vec<Instant>, | 141 | starts: Vec<Instant>, |
141 | messages: Vec<Message>, | ||
142 | filter: Filter, | 142 | filter: Filter, |
143 | messages: Tree<Message>, | ||
143 | } | 144 | } |
144 | 145 | ||
146 | #[derive(Default)] | ||
145 | struct Message { | 147 | struct Message { |
146 | level: usize, | ||
147 | duration: Duration, | 148 | duration: Duration, |
148 | label: Label, | 149 | label: Label, |
149 | detail: Option<String>, | 150 | detail: Option<String>, |
@@ -151,7 +152,7 @@ struct Message { | |||
151 | 152 | ||
152 | impl ProfileStack { | 153 | impl ProfileStack { |
153 | fn new() -> ProfileStack { | 154 | fn new() -> ProfileStack { |
154 | ProfileStack { starts: Vec::new(), messages: Vec::new(), filter: Default::default() } | 155 | ProfileStack { starts: Vec::new(), messages: Tree::default(), filter: Default::default() } |
155 | } | 156 | } |
156 | 157 | ||
157 | fn push(&mut self, label: Label) -> bool { | 158 | fn push(&mut self, label: Label) -> bool { |
@@ -171,6 +172,7 @@ impl ProfileStack { | |||
171 | } | 172 | } |
172 | 173 | ||
173 | self.starts.push(Instant::now()); | 174 | self.starts.push(Instant::now()); |
175 | self.messages.start(); | ||
174 | true | 176 | true |
175 | } | 177 | } |
176 | 178 | ||
@@ -178,7 +180,7 @@ impl ProfileStack { | |||
178 | let start = self.starts.pop().unwrap(); | 180 | let start = self.starts.pop().unwrap(); |
179 | let duration = start.elapsed(); | 181 | let duration = start.elapsed(); |
180 | let level = self.starts.len(); | 182 | let level = self.starts.len(); |
181 | self.messages.push(Message { level, duration, label, detail }); | 183 | self.messages.finish(Message { duration, label, detail }); |
182 | if level == 0 { | 184 | if level == 0 { |
183 | let longer_than = self.filter.longer_than; | 185 | let longer_than = self.filter.longer_than; |
184 | // Convert to millis for comparison to avoid problems with rounding | 186 | // Convert to millis for comparison to avoid problems with rounding |
@@ -186,7 +188,9 @@ impl ProfileStack { | |||
186 | // `duration` is just a few nanos). | 188 | // `duration` is just a few nanos). |
187 | if duration.as_millis() > longer_than.as_millis() { | 189 | if duration.as_millis() > longer_than.as_millis() { |
188 | let stderr = stderr(); | 190 | let stderr = stderr(); |
189 | print(&self.messages, longer_than, &mut stderr.lock()); | 191 | if let Some(root) = self.messages.root() { |
192 | print(&self.messages, root, 0, longer_than, &mut stderr.lock()); | ||
193 | } | ||
190 | } | 194 | } |
191 | self.messages.clear(); | 195 | self.messages.clear(); |
192 | assert!(self.starts.is_empty()) | 196 | assert!(self.starts.is_empty()) |
@@ -194,50 +198,38 @@ impl ProfileStack { | |||
194 | } | 198 | } |
195 | } | 199 | } |
196 | 200 | ||
197 | fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) { | 201 | fn print( |
198 | if msgs.is_empty() { | 202 | tree: &Tree<Message>, |
199 | return; | 203 | curr: Idx<Message>, |
200 | } | 204 | level: u32, |
201 | let children_map = idx_to_children(msgs); | ||
202 | let root_idx = msgs.len() - 1; | ||
203 | print_for_idx(root_idx, &children_map, msgs, longer_than, out); | ||
204 | } | ||
205 | |||
206 | fn print_for_idx( | ||
207 | current_idx: usize, | ||
208 | children_map: &[Vec<usize>], | ||
209 | msgs: &[Message], | ||
210 | longer_than: Duration, | 205 | longer_than: Duration, |
211 | out: &mut impl Write, | 206 | out: &mut impl Write, |
212 | ) { | 207 | ) { |
213 | let current = &msgs[current_idx]; | 208 | let current_indent = " ".repeat(level as usize); |
214 | let current_indent = " ".repeat(current.level); | 209 | let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); |
215 | let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); | ||
216 | writeln!( | 210 | writeln!( |
217 | out, | 211 | out, |
218 | "{}{:5}ms - {}{}", | 212 | "{}{:5}ms - {}{}", |
219 | current_indent, | 213 | current_indent, |
220 | current.duration.as_millis(), | 214 | tree[curr].duration.as_millis(), |
221 | current.label, | 215 | tree[curr].label, |
222 | detail, | 216 | detail, |
223 | ) | 217 | ) |
224 | .expect("printing profiling info"); | 218 | .expect("printing profiling info"); |
225 | 219 | ||
226 | let longer_than_millis = longer_than.as_millis(); | ||
227 | let children_indices = &children_map[current_idx]; | ||
228 | let mut accounted_for = Duration::default(); | 220 | let mut accounted_for = Duration::default(); |
229 | let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output. | 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; | ||
230 | 224 | ||
231 | for child_idx in children_indices.iter() { | 225 | if tree[child].duration.as_millis() > longer_than.as_millis() { |
232 | let child = &msgs[*child_idx]; | 226 | print(tree, child, level + 1, longer_than, out) |
233 | if child.duration.as_millis() > longer_than_millis { | ||
234 | print_for_idx(*child_idx, children_map, msgs, longer_than, out); | ||
235 | } else { | 227 | } else { |
236 | let pair = short_children.entry(child.label).or_insert((Duration::default(), 0)); | 228 | let (total_duration, cnt) = |
237 | pair.0 += child.duration; | 229 | short_children.entry(tree[child].label).or_insert((Duration::default(), 0)); |
238 | pair.1 += 1; | 230 | *total_duration += tree[child].duration; |
231 | *cnt += 1; | ||
239 | } | 232 | } |
240 | accounted_for += child.duration; | ||
241 | } | 233 | } |
242 | 234 | ||
243 | for (child_msg, (duration, count)) in short_children.iter() { | 235 | for (child_msg, (duration, count)) in short_children.iter() { |
@@ -246,122 +238,9 @@ fn print_for_idx( | |||
246 | .expect("printing profiling info"); | 238 | .expect("printing profiling info"); |
247 | } | 239 | } |
248 | 240 | ||
249 | let unaccounted_millis = (current.duration - accounted_for).as_millis(); | 241 | let unaccounted = tree[curr].duration - accounted_for; |
250 | if !children_indices.is_empty() | 242 | if tree.children(curr).next().is_some() && unaccounted > longer_than { |
251 | && unaccounted_millis > 0 | 243 | writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted.as_millis()) |
252 | && unaccounted_millis > longer_than_millis | ||
253 | { | ||
254 | writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis) | ||
255 | .expect("printing profiling info"); | 244 | .expect("printing profiling info"); |
256 | } | 245 | } |
257 | } | 246 | } |
258 | |||
259 | /// Returns a mapping from an index in the `msgs` to the vector with the indices of its children. | ||
260 | /// | ||
261 | /// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish. | ||
262 | /// In other words, a postorder of the call graph. In particular, the root is the last element of | ||
263 | /// `msgs`. | ||
264 | fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> { | ||
265 | // Initialize with the index of the root; `msgs` and `ancestors` should be never empty. | ||
266 | assert!(!msgs.is_empty()); | ||
267 | let mut ancestors = vec![msgs.len() - 1]; | ||
268 | let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()]; | ||
269 | for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() { | ||
270 | // We need to find the parent of the current message, i.e., the last ancestor that has a | ||
271 | // level lower than the current message. | ||
272 | while msgs[*ancestors.last().unwrap()].level >= msg.level { | ||
273 | ancestors.pop(); | ||
274 | } | ||
275 | result[*ancestors.last().unwrap()].push(idx); | ||
276 | ancestors.push(idx); | ||
277 | } | ||
278 | // Note that above we visited all children from the last to the first one. Let's reverse vectors | ||
279 | // to get the more natural order where the first element is the first child. | ||
280 | for vec in result.iter_mut() { | ||
281 | vec.reverse(); | ||
282 | } | ||
283 | result | ||
284 | } | ||
285 | |||
286 | #[cfg(test)] | ||
287 | mod tests { | ||
288 | use super::*; | ||
289 | |||
290 | #[test] | ||
291 | fn test_basic_profile() { | ||
292 | let s = vec!["profile1".to_string(), "profile2".to_string()]; | ||
293 | let f = Filter::new(2, s, Duration::new(0, 0)); | ||
294 | set_filter(f); | ||
295 | profiling_function1(); | ||
296 | } | ||
297 | |||
298 | fn profiling_function1() { | ||
299 | let _p = profile("profile1"); | ||
300 | profiling_function2(); | ||
301 | } | ||
302 | |||
303 | fn profiling_function2() { | ||
304 | let _p = profile("profile2"); | ||
305 | } | ||
306 | |||
307 | #[test] | ||
308 | fn test_longer_than() { | ||
309 | let mut result = vec![]; | ||
310 | let msgs = vec![ | ||
311 | Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None }, | ||
312 | Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None }, | ||
313 | Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None }, | ||
314 | ]; | ||
315 | print(&msgs, Duration::from_millis(0), &mut result); | ||
316 | // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed | ||
317 | // when printing. | ||
318 | assert_eq!( | ||
319 | std::str::from_utf8(&result).unwrap(), | ||
320 | " 1ms - foo\n 0ms - bar (2 calls)\n" | ||
321 | ); | ||
322 | } | ||
323 | |||
324 | #[test] | ||
325 | fn test_unaccounted_for_topmost() { | ||
326 | let mut result = vec![]; | ||
327 | let msgs = vec![ | ||
328 | Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None }, | ||
329 | Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None }, | ||
330 | ]; | ||
331 | print(&msgs, Duration::from_millis(0), &mut result); | ||
332 | assert_eq!( | ||
333 | std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), | ||
334 | vec![ | ||
335 | " 5ms - foo", | ||
336 | " 2ms - bar", | ||
337 | " 3ms - ???", | ||
338 | // Dummy comment to improve formatting | ||
339 | ] | ||
340 | ); | ||
341 | } | ||
342 | |||
343 | #[test] | ||
344 | fn test_unaccounted_for_multiple_levels() { | ||
345 | let mut result = vec![]; | ||
346 | let msgs = vec![ | ||
347 | Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None }, | ||
348 | Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None }, | ||
349 | Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None }, | ||
350 | Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None }, | ||
351 | Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None }, | ||
352 | ]; | ||
353 | print(&msgs, Duration::from_millis(0), &mut result); | ||
354 | assert_eq!( | ||
355 | std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(), | ||
356 | vec![ | ||
357 | " 9ms - foo", | ||
358 | " 5ms - bar", | ||
359 | " 3ms - baz", | ||
360 | " 2ms - ???", | ||
361 | " 4ms - bar", | ||
362 | " 2ms - baz", | ||
363 | " 2ms - ???", | ||
364 | ] | ||
365 | ); | ||
366 | } | ||
367 | } | ||
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index e6d672ef5..89df7f04b 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs | |||
@@ -4,6 +4,7 @@ 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; | 6 | mod hprof; |
7 | mod tree; | ||
7 | 8 | ||
8 | use std::cell::RefCell; | 9 | use std::cell::RefCell; |
9 | 10 | ||
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 | } | ||