aboutsummaryrefslogtreecommitdiff
path: root/crates/ra_prof
diff options
context:
space:
mode:
authorAleksey Kladov <[email protected]>2020-04-25 20:04:04 +0100
committerAleksey Kladov <[email protected]>2020-04-25 20:22:40 +0100
commitbd9ede0ec9fb76c8cc0b572ef0405811e1cb666e (patch)
tree723ee0cd16b656a8db5c65ac65b16cc841608126 /crates/ra_prof
parent0f099ead8893fa9551e385b030a4239ea1338451 (diff)
Extract messy tree handling out of profiling code
Diffstat (limited to 'crates/ra_prof')
-rw-r--r--crates/ra_prof/Cargo.toml1
-rw-r--r--crates/ra_prof/src/hprof.rs179
-rw-r--r--crates/ra_prof/src/lib.rs1
-rw-r--r--crates/ra_prof/src/tree.rs84
4 files changed, 115 insertions, 150 deletions
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
9doctest = false 9doctest = false
10 10
11[dependencies] 11[dependencies]
12ra_arena = { path = "../ra_arena" }
12once_cell = "1.3.1" 13once_cell = "1.3.1"
13backtrace = { version = "0.3.44", optional = true } 14backtrace = { version = "0.3.44", optional = true }
14 15
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
2use once_cell::sync::Lazy;
2use std::{ 3use 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
13use once_cell::sync::Lazy; 14use 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
139struct ProfileStack { 140struct 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)]
145struct Message { 147struct 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
152impl ProfileStack { 153impl 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
197fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) { 201fn 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
206fn 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`.
264fn 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)]
287mod 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")]
5mod google_cpu_profiler; 5mod google_cpu_profiler;
6mod hprof; 6mod hprof;
7mod tree;
7 8
8use std::cell::RefCell; 9use 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.
2use std::ops;
3
4use ra_arena::Arena;
5
6#[derive(Default)]
7pub struct Tree<T> {
8 nodes: Arena<Node<T>>,
9 current_path: Vec<(Idx<T>, Option<Idx<T>>)>,
10}
11
12pub type Idx<T> = ra_arena::Idx<Node<T>>;
13
14impl<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
51impl<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
58pub struct Node<T> {
59 data: T,
60 first_child: Option<Idx<T>>,
61 next_sibling: Option<Idx<T>>,
62}
63
64impl<T> Node<T> {
65 fn new(data: T) -> Node<T> {
66 Node { data, first_child: None, next_sibling: None }
67 }
68}
69
70struct NodeIter<'a, T> {
71 nodes: &'a Arena<Node<T>>,
72 next: Option<Idx<T>>,
73}
74
75impl<'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}