diff options
author | Aleksey Kladov <[email protected]> | 2020-08-12 15:32:36 +0100 |
---|---|---|
committer | Aleksey Kladov <[email protected]> | 2020-08-12 15:35:29 +0100 |
commit | 208b7bd7ba687fb570feb1b89219f14c63712ce8 (patch) | |
tree | c39749d1b71b73b4017c2d0d848ebdc85e570c39 /crates/ra_prof/src/hprof.rs | |
parent | 98baa9b569b49162392ed4149dd435854fe941b8 (diff) |
Rename ra_prof -> profile
Diffstat (limited to 'crates/ra_prof/src/hprof.rs')
-rw-r--r-- | crates/ra_prof/src/hprof.rs | 243 |
1 files changed, 0 insertions, 243 deletions
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs deleted file mode 100644 index a3f5321fb..000000000 --- a/crates/ra_prof/src/hprof.rs +++ /dev/null | |||
@@ -1,243 +0,0 @@ | |||
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` struct that measures elapsed time between this method invocation and `Profile` struct drop. | ||
34 | /// It supports nested profiling scopes in case when this function is invoked multiple times at the execution stack. | ||
35 | /// In this case the profiling information will be nested at the output. | ||
36 | /// Profiling information is being printed in the stderr. | ||
37 | /// | ||
38 | /// # Example | ||
39 | /// ``` | ||
40 | /// use ra_prof::{profile, set_filter, Filter}; | ||
41 | /// | ||
42 | /// let f = Filter::from_spec("profile1|profile2@2"); | ||
43 | /// set_filter(f); | ||
44 | /// profiling_function1(); | ||
45 | /// | ||
46 | /// fn profiling_function1() { | ||
47 | /// let _p = profile("profile1"); | ||
48 | /// profiling_function2(); | ||
49 | /// } | ||
50 | /// | ||
51 | /// fn profiling_function2() { | ||
52 | /// let _p = profile("profile2"); | ||
53 | /// } | ||
54 | /// ``` | ||
55 | /// This will print in the stderr the following: | ||
56 | /// ```text | ||
57 | /// 0ms - profile | ||
58 | /// 0ms - profile2 | ||
59 | /// ``` | ||
60 | pub fn profile(label: Label) -> Profiler { | ||
61 | assert!(!label.is_empty()); | ||
62 | |||
63 | if PROFILING_ENABLED.load(Ordering::Relaxed) | ||
64 | && PROFILE_STACK.with(|stack| stack.borrow_mut().push(label)) | ||
65 | { | ||
66 | Profiler(Some(ProfilerImpl { label, detail: None })) | ||
67 | } else { | ||
68 | Profiler(None) | ||
69 | } | ||
70 | } | ||
71 | |||
72 | pub struct Profiler(Option<ProfilerImpl>); | ||
73 | |||
74 | struct ProfilerImpl { | ||
75 | label: Label, | ||
76 | detail: Option<String>, | ||
77 | } | ||
78 | |||
79 | impl Profiler { | ||
80 | pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler { | ||
81 | if let Some(profiler) = &mut self.0 { | ||
82 | profiler.detail = Some(detail()) | ||
83 | } | ||
84 | self | ||
85 | } | ||
86 | } | ||
87 | |||
88 | impl Drop for ProfilerImpl { | ||
89 | fn drop(&mut self) { | ||
90 | PROFILE_STACK.with(|it| it.borrow_mut().pop(self.label, self.detail.take())); | ||
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 | self.messages.finish(Message { duration, label, detail }); | ||
183 | if self.starts.is_empty() { | ||
184 | let longer_than = self.filter.longer_than; | ||
185 | // Convert to millis for comparison to avoid problems with rounding | ||
186 | // (otherwise we could print `0ms` despite user's `>0` filter when | ||
187 | // `duration` is just a few nanos). | ||
188 | if duration.as_millis() > longer_than.as_millis() { | ||
189 | if let Some(root) = self.messages.root() { | ||
190 | print(&self.messages, root, 0, longer_than, &mut stderr().lock()); | ||
191 | } | ||
192 | } | ||
193 | self.messages.clear(); | ||
194 | } | ||
195 | } | ||
196 | } | ||
197 | |||
198 | fn print( | ||
199 | tree: &Tree<Message>, | ||
200 | curr: Idx<Message>, | ||
201 | level: u32, | ||
202 | longer_than: Duration, | ||
203 | out: &mut impl Write, | ||
204 | ) { | ||
205 | let current_indent = " ".repeat(level as usize); | ||
206 | let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default(); | ||
207 | writeln!( | ||
208 | out, | ||
209 | "{}{:5}ms - {}{}", | ||
210 | current_indent, | ||
211 | tree[curr].duration.as_millis(), | ||
212 | tree[curr].label, | ||
213 | detail, | ||
214 | ) | ||
215 | .expect("printing profiling info"); | ||
216 | |||
217 | let mut accounted_for = Duration::default(); | ||
218 | let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output. | ||
219 | for child in tree.children(curr) { | ||
220 | accounted_for += tree[child].duration; | ||
221 | |||
222 | if tree[child].duration.as_millis() > longer_than.as_millis() { | ||
223 | print(tree, child, level + 1, longer_than, out) | ||
224 | } else { | ||
225 | let (total_duration, cnt) = | ||
226 | short_children.entry(tree[child].label).or_insert((Duration::default(), 0)); | ||
227 | *total_duration += tree[child].duration; | ||
228 | *cnt += 1; | ||
229 | } | ||
230 | } | ||
231 | |||
232 | for (child_msg, (duration, count)) in short_children.iter() { | ||
233 | let millis = duration.as_millis(); | ||
234 | writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count) | ||
235 | .expect("printing profiling info"); | ||
236 | } | ||
237 | |||
238 | let unaccounted = tree[curr].duration - accounted_for; | ||
239 | if tree.children(curr).next().is_some() && unaccounted > longer_than { | ||
240 | writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted.as_millis()) | ||
241 | .expect("printing profiling info"); | ||
242 | } | ||
243 | } | ||