self_profiles_report/
lib.rs

Help
1// Copyright 2023 The Fuchsia Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5//! Analyze output from fuchsia_inspect_contrib's self profiling feature.
6
7use diagnostics_data::{DiagnosticsHierarchy, ExtendedMoniker, InspectData};
8use std::collections::BTreeMap;
9
10/// If a duration used less than 0.5% of its parent's CPU time, it's probably not that interesting.
11const CHILD_PROPORTION_DISPLAY_THRESHOLD: f64 = 0.005;
12
13#[derive(Debug, PartialEq)]
14pub struct SelfProfilesReport {
15    name: String,
16    root_summary: DurationSummary,
17    custom_rollups: Vec<CustomRollup>,
18}
19
20impl SelfProfilesReport {
21    pub fn from_snapshot(data: &[InspectData]) -> Result<Vec<Self>, AnalysisError> {
22        let mut summaries = vec![];
23        for d in data {
24            if let Some(s) = Self::from_single_snapshot(d) {
25                summaries.push(s?);
26            }
27        }
28        Ok(summaries)
29    }
30
31    pub fn from_single_snapshot(data: &InspectData) -> Option<Result<Self, AnalysisError>> {
32        if let Some(payload) = data.payload.as_ref() {
33            for child_node in &payload.children {
34                if child_node.get_property("__profile_durations_root").and_then(|p| p.boolean())
35                    == Some(true)
36                {
37                    return Some(Self::from_node(&data.moniker, child_node));
38                }
39            }
40        }
41        None
42    }
43
44    fn from_node(
45        name: &ExtendedMoniker,
46        node: &DiagnosticsHierarchy,
47    ) -> Result<Self, AnalysisError> {
48        let root_summary = DurationSummaryBuilder::from_inspect(node)?.build();
49        Ok(Self { name: name.to_string(), root_summary, custom_rollups: vec![] })
50    }
51
52    pub fn name(&self) -> &str {
53        &self.name
54    }
55
56    pub fn root_summary(&self) -> &DurationSummary {
57        &self.root_summary
58    }
59
60    pub fn leaf_durations(&self) -> Vec<(String, DurationSummary)> {
61        let mut leaves = BTreeMap::new();
62        self.root_summary.summarize_leaves(&self.name, &mut leaves);
63
64        let mut leaves = leaves.into_iter().collect::<Vec<_>>();
65        leaves.sort_by_key(|(_, duration)| duration.runtime.cpu_time);
66        leaves.reverse();
67
68        leaves
69    }
70
71    pub fn matching_durations(&self, match_prefixes: &[String]) -> Vec<(String, DurationSummary)> {
72        let mut matches = BTreeMap::new();
73        self.root_summary.summarize_matches(&self.name, match_prefixes, &mut matches);
74
75        let mut matches = matches.into_iter().collect::<Vec<_>>();
76        matches.sort_by_key(|(_, duration)| duration.runtime.cpu_time);
77        matches.reverse();
78
79        matches
80    }
81
82    pub fn delta_from(&self, baseline: &Self) -> Result<Self, ComparisonError> {
83        if self.name != baseline.name {
84            return Err(ComparisonError::MismatchedNames {
85                lhs: self.name.clone(),
86                rhs: baseline.name.clone(),
87            });
88        }
89        Ok(Self {
90            name: self.name.clone(),
91            root_summary: self.root_summary.delta_from(&baseline.root_summary)?,
92            custom_rollups: vec![],
93        })
94    }
95
96    pub fn add_rollup(
97        &mut self,
98        title: impl Into<String>,
99        prefixes: impl IntoIterator<Item = impl Into<String>>,
100    ) {
101        self.custom_rollups.push(CustomRollup {
102            display_title: title.into(),
103            match_prefixes: prefixes.into_iter().map(|s| s.into()).collect(),
104        });
105    }
106}
107
108impl std::fmt::Display for SelfProfilesReport {
109    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
110        writeln!(f, "Profile duration summary for `{}`:\n\n{}\n", self.name, self.root_summary)?;
111
112        let root_runtime = self.root_summary.runtime;
113
114        writeln!(f, "Rolled up leaf durations:\n")?;
115        for (name, duration) in &self.leaf_durations() {
116            let proportion_of_total =
117                duration.runtime.cpu_time as f64 / root_runtime.cpu_time as f64;
118            if proportion_of_total >= CHILD_PROPORTION_DISPLAY_THRESHOLD {
119                write!(f, "{}", duration.display_tree(name, root_runtime))?;
120            }
121        }
122
123        for rollup in &self.custom_rollups {
124            writeln!(f, "Custom rollup: {}\n", rollup.display_title)?;
125
126            for (name, duration) in &self.matching_durations(&rollup.match_prefixes) {
127                write!(f, "{}", duration.display_tree(name, root_runtime))?;
128            }
129        }
130
131        Ok(())
132    }
133}
134
135#[derive(Debug, Default)]
136struct DurationSummaryBuilder {
137    count: u64,
138    runtime: TaskRuntimeInfo,
139    location: String,
140    children: BTreeMap<String, Self>,
141}
142
143impl DurationSummaryBuilder {
144    fn from_inspect(node: &DiagnosticsHierarchy) -> Result<Self, AnalysisError> {
145        let mut children = BTreeMap::new();
146        for child_node in &node.children {
147            let (name, child) = Self::from_inspect_recursive(child_node)?;
148            children.insert(name, child);
149        }
150        let location = node.get_property("location").unwrap().string().unwrap().to_owned();
151
152        // The top-level node doesn't get any metrics recorded, it's just a container for children.
153        let runtime = children.values().map(|c| c.runtime).sum();
154
155        Ok(Self { runtime, count: 0, children, location })
156    }
157
158    fn from_inspect_recursive(
159        node: &DiagnosticsHierarchy,
160    ) -> Result<(String, Self), AnalysisError> {
161        let count = node.get_property("count").unwrap().uint().unwrap();
162        let runtime = TaskRuntimeInfo {
163            cpu_time: get_time_property(node, "cpu_time")?,
164            queue_time: get_time_property(node, "queue_time")?,
165            page_fault_time: get_time_property(node, "page_fault_time")?,
166            lock_contention_time: get_time_property(node, "lock_contention_time")?,
167            wall_time: get_time_property(node, "wall_time")?,
168        };
169        let location = node.get_property("location").unwrap().string().unwrap().to_owned();
170
171        let mut children = BTreeMap::new();
172        for child_node in &node.children {
173            let (name, child) = Self::from_inspect_recursive(child_node)?;
174            children.insert(name, child);
175        }
176
177        Ok((node.name.clone(), Self { count, runtime, children, location }))
178    }
179
180    fn build(&self) -> DurationSummary {
181        let mut children = vec![];
182        for (name, child) in &self.children {
183            children.push((name.clone(), child.build()));
184        }
185
186        // Sort children by how much time they occupied.
187        children.sort_by_key(|(_, analysis)| analysis.runtime.cpu_time);
188        children.reverse();
189
190        DurationSummary {
191            count: self.count,
192            runtime: self.runtime,
193            location: self.location.clone(),
194            children,
195        }
196    }
197}
198
199#[derive(Debug, Clone, PartialEq)]
200pub struct DurationSummary {
201    count: u64,
202    runtime: TaskRuntimeInfo,
203    location: String,
204    children: Vec<(String, Self)>,
205}
206
207impl DurationSummary {
208    /// The source location where this duration was entered.
209    pub fn location(&self) -> &str {
210        self.location.as_str()
211    }
212
213    /// Number of times this duration was exited.
214    pub fn count(&self) -> u64 {
215        self.count
216    }
217
218    /// Sum of time this duration was scheduled on-CPU, in nanoseconds.
219    pub fn cpu_time(&self) -> i64 {
220        self.runtime.cpu_time
221    }
222
223    /// Sum of time this duration was ready to execute and was pending in the scheduler queue,
224    /// in nanoseconds.
225    pub fn queue_time(&self) -> i64 {
226        self.runtime.queue_time
227    }
228
229    /// Sum of time this duration was blocked handling page faults, in nanoseconds.
230    pub fn page_fault_time(&self) -> i64 {
231        self.runtime.page_fault_time
232    }
233
234    /// Sum of time this duration was blocked on contended kernel locks, in nanoseconds.
235    pub fn lock_contention_time(&self) -> i64 {
236        self.runtime.lock_contention_time
237    }
238
239    /// Sum of time this duration was logically executing on the monotonic clock, in nanoseconds.
240    pub fn wall_time(&self) -> i64 {
241        self.runtime.wall_time
242    }
243
244    /// Child durations observed while this was executing.
245    pub fn children(&self) -> impl Iterator<Item = (&str, &Self)> {
246        self.children.iter().map(|(name, summary)| (name.as_str(), summary))
247    }
248
249    fn summarize_leaves(&self, own_name: &str, leaves: &mut BTreeMap<String, Self>) {
250        if self.children.is_empty() {
251            match leaves.entry(own_name.to_string()) {
252                std::collections::btree_map::Entry::Vacant(v) => {
253                    v.insert(DurationSummary {
254                        count: self.count,
255                        runtime: self.runtime,
256                        location: self.location.clone(),
257                        children: vec![],
258                    });
259                }
260                std::collections::btree_map::Entry::Occupied(mut o) => {
261                    let leaf = o.get_mut();
262                    leaf.runtime += self.runtime;
263                    leaf.count += self.count;
264                }
265            }
266        } else {
267            for (name, child) in &self.children {
268                child.summarize_leaves(name, leaves);
269            }
270        }
271    }
272
273    fn summarize_matches(
274        &self,
275        own_name: &str,
276        match_prefixes: &[String],
277        out: &mut BTreeMap<String, Self>,
278    ) {
279        if match_prefixes.iter().any(|prefix| own_name.starts_with(prefix.as_str())) {
280            match out.entry(own_name.to_string()) {
281                std::collections::btree_map::Entry::Vacant(v) => {
282                    v.insert(DurationSummary {
283                        count: self.count,
284                        runtime: self.runtime,
285                        location: self.location.clone(),
286                        children: vec![],
287                    });
288                }
289                std::collections::btree_map::Entry::Occupied(mut o) => {
290                    let leaf = o.get_mut();
291                    leaf.runtime += self.runtime;
292                    leaf.count += self.count;
293                }
294            }
295        }
296
297        for (name, child) in &self.children {
298            child.summarize_matches(name, match_prefixes, out);
299        }
300    }
301
302    fn display_leaf_no_location(
303        &self,
304        name: &str,
305        count: u64,
306        runtime: TaskRuntimeInfo,
307    ) -> termtree::Tree<DurationRuntimeWithPercentage> {
308        let mut leaf = termtree::Tree::new(DurationRuntimeWithPercentage {
309            name: name.to_owned(),
310            count,
311            runtime,
312            location: None,
313            portion_of_parent_cpu_time: runtime.cpu_time as f64 / self.runtime.cpu_time as f64,
314        });
315        leaf.set_multiline(true);
316        leaf
317    }
318
319    fn display_tree(
320        &self,
321        name: &str,
322        parent_total_runtime: TaskRuntimeInfo,
323    ) -> termtree::Tree<DurationRuntimeWithPercentage> {
324        let mut tree = termtree::Tree::new(DurationRuntimeWithPercentage {
325            name: name.to_owned(),
326            count: self.count,
327            runtime: self.runtime,
328            location: Some(self.location.clone()),
329            portion_of_parent_cpu_time: self.runtime.cpu_time as f64
330                / parent_total_runtime.cpu_time as f64,
331        });
332        tree.set_multiline(true);
333
334        let mut etc_time = TaskRuntimeInfo::default();
335        let mut etc_count = 0;
336        for (name, child) in &self.children {
337            let portion_of_self = child.runtime.cpu_time as f64 / self.runtime.cpu_time as f64;
338            if portion_of_self > CHILD_PROPORTION_DISPLAY_THRESHOLD {
339                tree.push(child.display_tree(name, self.runtime));
340            } else {
341                etc_count += child.count;
342                etc_time += child.runtime;
343            }
344        }
345        if !self.children.is_empty() {
346            // Add a bucket for time that was not accounted by the child durations (if any).
347            let unaccounted_runtime =
348                self.runtime - self.children.iter().map(|(_, c)| c.runtime).sum();
349            let portion_unaccounted =
350                unaccounted_runtime.cpu_time as f64 / self.runtime.cpu_time as f64;
351            if portion_unaccounted > CHILD_PROPORTION_DISPLAY_THRESHOLD {
352                tree.push(self.display_leaf_no_location("UNACCOUNTED", 0, unaccounted_runtime));
353            } else {
354                etc_time += unaccounted_runtime;
355            }
356        }
357        if etc_time.cpu_time > 0 {
358            tree.push(self.display_leaf_no_location("BELOW_THRESHOLD", etc_count, etc_time));
359        }
360
361        tree
362    }
363
364    fn delta_from(&self, baseline: &Self) -> Result<Self, ComparisonError> {
365        let count = self.count - baseline.count;
366        let runtime = self.runtime - baseline.runtime;
367        if self.location != baseline.location {
368            return Err(ComparisonError::MismatchedLocations {
369                lhs: self.location.clone(),
370                rhs: baseline.location.clone(),
371            });
372        }
373
374        let mut delta_children = BTreeMap::<String, Self>::new();
375        let baseline_children = baseline
376            .children
377            .iter()
378            .map(/*invoke auto ref */ |(n, s)| (n, s))
379            .collect::<BTreeMap<_, _>>();
380        for (name, summary) in &self.children {
381            if let Some(baseline_summary) = baseline_children.get(name) {
382                delta_children.insert(name.clone(), summary.delta_from(baseline_summary)?);
383            } else {
384                delta_children.insert(name.clone(), summary.clone());
385            }
386        }
387
388        // Sort children by how much time they occupied.
389        let mut children = delta_children.into_iter().collect::<Vec<_>>();
390        children.sort_by_key(|(_, analysis)| analysis.runtime.cpu_time);
391        children.reverse();
392
393        Ok(Self { count, runtime, children, location: self.location.clone() })
394    }
395}
396
397impl std::fmt::Display for DurationSummary {
398    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
399        let total_child_runtime = self.children().map(|(_, c)| c.runtime).sum();
400        write!(f, "{}", self.display_tree("overall", total_child_runtime))
401    }
402}
403
404fn get_time_property(
405    node: &DiagnosticsHierarchy,
406    name: &'static str,
407) -> Result<i64, AnalysisError> {
408    let property = node.get_property(name).ok_or(AnalysisError::MissingTime { name })?;
409    property
410        .number_as_int()
411        .ok_or_else(|| AnalysisError::WrongType { name, property: property.name().to_string() })
412}
413
414#[derive(Debug)]
415pub struct DurationRuntimeWithPercentage {
416    name: String,
417    location: Option<String>,
418    portion_of_parent_cpu_time: f64,
419    count: u64,
420    runtime: TaskRuntimeInfo,
421}
422
423impl std::fmt::Display for DurationRuntimeWithPercentage {
424    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
425        write!(f, "{:^5.3}%: {}", self.portion_of_parent_cpu_time * 100.0, self.name)?;
426        if self.count > 0 {
427            write!(f, ", {}x", self.count)?;
428        }
429        writeln!(
430            f,
431            "\n    cpu: {}, queue: {}, faulting: {}, contended: {}, wall: {}",
432            ns_to_ms(self.runtime.cpu_time),
433            ns_to_ms(self.runtime.queue_time),
434            ns_to_ms(self.runtime.page_fault_time),
435            ns_to_ms(self.runtime.lock_contention_time),
436            ns_to_ms(self.runtime.wall_time),
437        )?;
438        if let Some(location) = &self.location {
439            writeln!(f, "    source: {location}")?;
440        }
441        Ok(())
442    }
443}
444
445fn ns_to_ms(ns: i64) -> String {
446    format!("{:^5.3}ms", ns as f64 / 1_000_000.0)
447}
448
449#[derive(Debug, thiserror::Error)]
450pub enum ComparisonError {
451    #[error("Can't compare profiles from two different sources `{lhs}` and `{rhs}`.")]
452    MismatchedNames { lhs: String, rhs: String },
453
454    #[error("Can't compare profiles which disagree on the source location for a duration: `{lhs}` vs `{rhs}`")]
455    MismatchedLocations { lhs: String, rhs: String },
456}
457
458/// Failures that can occur when analyzing Starnix traces.
459#[derive(Debug, thiserror::Error)]
460pub enum AnalysisError {
461    #[error("Profile duration inspect node without `{name}` property.")]
462    MissingTime { name: &'static str },
463
464    #[error(
465        "Profile duration inspect node's `{name}` property had a non-integer type: {property:?}"
466    )]
467    WrongType { name: &'static str, property: String },
468}
469
470#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)]
471struct TaskRuntimeInfo {
472    cpu_time: i64,
473    queue_time: i64,
474    page_fault_time: i64,
475    lock_contention_time: i64,
476    wall_time: i64,
477}
478
479impl std::ops::Add for TaskRuntimeInfo {
480    type Output = Self;
481    fn add(self, rhs: Self) -> Self::Output {
482        Self {
483            cpu_time: self.cpu_time + rhs.cpu_time,
484            queue_time: self.queue_time + rhs.queue_time,
485            page_fault_time: self.page_fault_time + rhs.page_fault_time,
486            lock_contention_time: self.lock_contention_time + rhs.lock_contention_time,
487            wall_time: self.wall_time + rhs.wall_time,
488        }
489    }
490}
491
492impl std::ops::AddAssign for TaskRuntimeInfo {
493    fn add_assign(&mut self, rhs: Self) {
494        self.cpu_time += rhs.cpu_time;
495        self.queue_time += rhs.queue_time;
496        self.page_fault_time += rhs.page_fault_time;
497        self.lock_contention_time += rhs.lock_contention_time;
498        self.wall_time += rhs.wall_time;
499    }
500}
501
502impl std::ops::Sub for TaskRuntimeInfo {
503    type Output = Self;
504    fn sub(self, rhs: Self) -> Self::Output {
505        Self {
506            cpu_time: self.cpu_time - rhs.cpu_time,
507            queue_time: self.queue_time - rhs.queue_time,
508            page_fault_time: self.page_fault_time - rhs.page_fault_time,
509            lock_contention_time: self.lock_contention_time - rhs.lock_contention_time,
510            wall_time: self.wall_time - rhs.wall_time,
511        }
512    }
513}
514
515impl std::ops::SubAssign for TaskRuntimeInfo {
516    fn sub_assign(&mut self, rhs: Self) {
517        self.cpu_time -= rhs.cpu_time;
518        self.queue_time -= rhs.queue_time;
519        self.page_fault_time -= rhs.page_fault_time;
520        self.lock_contention_time -= rhs.lock_contention_time;
521        self.wall_time -= rhs.wall_time;
522    }
523}
524
525impl std::iter::Sum for TaskRuntimeInfo {
526    fn sum<I: Iterator<Item = Self>>(iter: I) -> Self {
527        iter.fold(Self::default(), |l, r| l + r)
528    }
529}
530
531#[derive(Debug, PartialEq)]
532struct CustomRollup {
533    display_title: String,
534    match_prefixes: Vec<String>,
535}
self_profiles_report/lib.rs

self_profiles_report/
lib.rs
