rg3d_core/
profiler.rs

1//! Built-in scoped profiler. You must compile with feature "enable_profiler" to
2//! force profiler gather info! It is disabled by default because it is not cheap
3//! and takes 3-5% of performance for internal needs.
4
5#![allow(dead_code)]
6
7use fxhash::{FxHashMap, FxHashSet, FxHasher};
8use std::{
9    fmt,
10    fmt::Write,
11    hash::{Hash, Hasher},
12    sync::{Arc, Mutex},
13};
14
15pub fn print() -> Result<String, fmt::Error> {
16    #[cfg(feature = "enable_profiler")]
17    {
18        let mut buffer = String::new();
19        PROFILER.lock().unwrap().print(&mut buffer)?;
20        Ok(buffer)
21    }
22
23    #[cfg(not(feature = "enable_profiler"))]
24    {
25        Ok("Performance profiling results are not available, because feature 'enable_profiler' wasn't defined!".to_owned())
26    }
27}
28
29pub fn print_hot_path() -> Result<String, fmt::Error> {
30    #[cfg(feature = "enable_profiler")]
31    {
32        let mut buffer = String::new();
33        PROFILER.lock().unwrap().print_hot_path(&mut buffer)?;
34        Ok(buffer)
35    }
36
37    #[cfg(not(feature = "enable_profiler"))]
38    {
39        Ok("Performance profiling results are not available, because feature 'enable_profiler' wasn't defined!".to_owned())
40    }
41}
42
43struct Sample {
44    count: u64,
45    time: f64,
46    children: FxHashSet<ScopeMark>,
47}
48
49impl Sample {
50    pub fn collect(&mut self, time: f64) {
51        self.time += time;
52        self.count += 1;
53    }
54}
55
56impl Default for Sample {
57    fn default() -> Self {
58        Self {
59            count: 0,
60            time: 0.0,
61            children: Default::default(),
62        }
63    }
64}
65
66#[derive(Hash, PartialEq, Eq, Copy, Clone, Debug)]
67struct ScopeMark {
68    parent_scope_hash: u64,
69    function_name: &'static str,
70    line: u32,
71}
72
73struct Profiler {
74    start_time: std::time::Instant,
75    samples: FxHashMap<ScopeMark, Sample>,
76    scope_stack: Vec<ScopeMark>,
77}
78
79const ENTRY_SCOPE_MARK: ScopeMark = ScopeMark {
80    parent_scope_hash: 0,
81    function_name: "EntryPoint",
82    line: 0,
83};
84
85impl Default for Profiler {
86    #[inline]
87    fn default() -> Self {
88        let entry_sample = Sample {
89            count: 0,
90            time: 0.0,
91            children: FxHashSet::default(),
92        };
93        let mut samples = FxHashMap::default();
94        samples.insert(ENTRY_SCOPE_MARK, entry_sample);
95        Self {
96            start_time: std::time::Instant::now(),
97            samples,
98            scope_stack: vec![ENTRY_SCOPE_MARK],
99        }
100    }
101}
102
103fn calculate_hash<T: Hash>(t: &T) -> u64 {
104    let mut s = FxHasher::default();
105    t.hash(&mut s);
106    s.finish()
107}
108
109impl Profiler {
110    fn enter_scope(&mut self, scope: &mut ScopeMark) {
111        let parent_scope_mark = *self.scope_stack.last().unwrap();
112        scope.parent_scope_hash = calculate_hash(&parent_scope_mark);
113        self.scope_stack.push(*scope);
114        self.samples.entry(*scope).or_default();
115        self.samples
116            .get_mut(&parent_scope_mark)
117            .unwrap()
118            .children
119            .insert(*scope);
120    }
121
122    fn leave_scope(&mut self, scope: ScopeMark, elapsed: f64) {
123        self.scope_stack.pop();
124        self.samples.get_mut(&scope).unwrap().collect(elapsed);
125    }
126
127    fn print(&self, buffer: &mut String) -> fmt::Result {
128        let full_time = (std::time::Instant::now() - self.start_time).as_secs_f64();
129        self.recursive_print(buffer, &ENTRY_SCOPE_MARK, 0, full_time)?;
130        writeln!(buffer,"=========================================================================================================")?;
131        Ok(())
132    }
133
134    fn recursive_print(
135        &self,
136        buffer: &mut String,
137        scope_mark: &ScopeMark,
138        offset: usize,
139        full_time: f64,
140    ) -> fmt::Result {
141        let sample = self.samples.get(scope_mark).unwrap();
142
143        if scope_mark == &ENTRY_SCOPE_MARK {
144            writeln!(buffer, "=========================================================================================================")?;
145            writeln!(buffer,"Profiling took {} seconds. Please note that profiling itself takes time so results are not 100% accurate.", full_time)?;
146            writeln!(buffer, "Entry Point")?;
147        } else {
148            writeln!(
149                buffer,
150                "{}{:.4}% - {} at line {} was called {} times and took {} seconds individually.",
151                "\t".repeat(offset),
152                (sample.time / full_time) * 100.0,
153                scope_mark.function_name,
154                scope_mark.line,
155                sample.count,
156                sample.time
157            )?;
158        }
159
160        for child_scope in self
161            .samples
162            .get(scope_mark)
163            .as_ref()
164            .unwrap()
165            .children
166            .iter()
167        {
168            self.recursive_print(buffer, child_scope, offset + 1, full_time)?;
169        }
170
171        Ok(())
172    }
173
174    fn print_hot_path(&self, buffer: &mut String) -> fmt::Result {
175        let full_time = (std::time::Instant::now() - self.start_time).as_secs_f64();
176        self.print_hot_path_recursive(buffer, &ENTRY_SCOPE_MARK, 0, full_time)?;
177        writeln!(buffer, "=========================================================================================================")?;
178        Ok(())
179    }
180
181    fn print_hot_path_recursive(
182        &self,
183        buffer: &mut String,
184        scope_mark: &ScopeMark,
185        offset: usize,
186        full_time: f64,
187    ) -> fmt::Result {
188        let sample = self.samples.get(scope_mark).unwrap();
189
190        if scope_mark == &ENTRY_SCOPE_MARK {
191            writeln!(buffer,"=========================================================================================================")?;
192            writeln!(buffer,"Showing hot path only! Profiling took {} seconds. Please note that profiling itself takes time so results are not 100% accurate.", full_time)?;
193            writeln!(buffer, "Entry Point")?;
194        } else {
195            writeln!(
196                buffer,
197                "{}{:.4}% - {} at line {} was called {} times and took {} seconds individually.",
198                "\t".repeat(offset),
199                (sample.time / full_time) * 100.0,
200                scope_mark.function_name,
201                scope_mark.line,
202                sample.count,
203                sample.time
204            )?;
205        }
206
207        let mut hot = None;
208        let mut hot_time = 0.0;
209        for child_scope in self
210            .samples
211            .get(scope_mark)
212            .as_ref()
213            .unwrap()
214            .children
215            .iter()
216        {
217            let time = self.samples.get(child_scope).as_ref().unwrap().time;
218            if time > hot_time {
219                hot_time = time;
220                hot = Some(*child_scope);
221            }
222        }
223
224        if let Some(hot) = hot.as_ref() {
225            self.print_hot_path_recursive(buffer, hot, offset + 1, full_time)?;
226        }
227
228        Ok(())
229    }
230}
231
232lazy_static! {
233    static ref PROFILER: Arc<Mutex<Profiler>> = Arc::new(Mutex::new(Profiler::default()));
234}
235
236pub struct ScopeDefinition {
237    scope: ScopeMark,
238    start_time: std::time::Instant,
239}
240
241impl ScopeDefinition {
242    #[cfg(feature = "enable_profiler")]
243    #[inline]
244    pub fn new(function_name: &'static str, line: u32) -> Self {
245        let mut scope = ScopeMark {
246            parent_scope_hash: 0,
247            function_name,
248            line,
249        };
250
251        PROFILER.lock().unwrap().enter_scope(&mut scope);
252
253        Self {
254            scope,
255            start_time: std::time::Instant::now(),
256        }
257    }
258
259    #[inline]
260    fn elapsed(&self) -> f64 {
261        (std::time::Instant::now() - self.start_time).as_secs_f64()
262    }
263}
264
265impl Drop for ScopeDefinition {
266    fn drop(&mut self) {
267        let elapsed = self.elapsed();
268        PROFILER.lock().unwrap().leave_scope(self.scope, elapsed);
269    }
270}
271
272#[inline]
273pub fn type_name_of<T>(_: T) -> &'static str {
274    std::any::type_name::<T>()
275}
276
277#[cfg(feature = "enable_profiler")]
278#[macro_export]
279macro_rules! scope_profile {
280    () => {
281        let function_name = {
282            fn scope() {}
283            $crate::profiler::type_name_of(scope)
284        };
285        let _scope_guard = $crate::profiler::ScopeDefinition::new(function_name, line!());
286    };
287}
288
289#[cfg(not(feature = "enable_profiler"))]
290#[macro_export]
291macro_rules! scope_profile {
292    () => {};
293}
294
295#[cfg(test)]
296mod test {
297    use crate::profiler;
298    use std::time::Duration;
299
300    fn nested_func() {
301        scope_profile!();
302        std::thread::sleep(Duration::from_millis(1000));
303    }
304
305    fn some_func() {
306        scope_profile!();
307        nested_func();
308    }
309
310    fn other_func() {
311        scope_profile!();
312        std::thread::sleep(Duration::from_millis(1000));
313        nested_func();
314        some_func();
315    }
316
317    #[test]
318    fn test_scope_perf() {
319        {
320            scope_profile!();
321            other_func();
322        }
323
324        println!("{:?}", profiler::print());
325    }
326}
rg3d_core/profiler.rs

rg3d_core/
profiler.rs
