tracing-calltree 0.1.1

Always-on hierarchical profiling for Rust tracing spans with rolling latency statistics.
Documentation
use crate::snapshot::{CallTreeSnapshot, NodeSnapshot};
use std::fmt;
use std::time::Duration;

pub struct SnapshotDisplay<'a>(pub(crate) &'a CallTreeSnapshot);

impl fmt::Display for SnapshotDisplay<'_> {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        for (index, root) in self.0.roots.iter().enumerate() {
            let is_last = index + 1 == self.0.roots.len();
            write_node(f, root, "", "", true, is_last)?;
            if !is_last {
                writeln!(f)?;
            }
        }

        Ok(())
    }
}

impl fmt::Display for CallTreeSnapshot {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        self.display().fmt(f)
    }
}

fn write_node(
    f: &mut fmt::Formatter<'_>,
    node: &NodeSnapshot,
    print_prefix: &str,
    children_prefix: &str,
    is_root: bool,
    is_last: bool,
) -> fmt::Result {
    let branch = if is_root {
        ""
    } else if is_last {
        "└── "
    } else {
        "├── "
    };

    write!(
        f,
        "{print_prefix}{branch}{:<28} {:>8} avg {:>8} p95 n={}",
        node.name,
        format_duration(node.wall.mean),
        format_duration(node.wall.p95),
        node.wall.samples,
    )?;

    if !node.children.is_empty() {
        for (index, child) in node.children.iter().enumerate() {
            writeln!(f)?;
            let last = index + 1 == node.children.len();

            let child_print_prefix = if is_root { "" } else { children_prefix };

            let grand_children_prefix = format!(
                "{}{}",
                children_prefix,
                if last { "    " } else { "" }
            );

            write_node(
                f,
                child,
                child_print_prefix,
                &grand_children_prefix,
                false,
                last,
            )?;
        }
    }

    Ok(())
}

fn format_duration(duration: Duration) -> String {
    let nanos = duration.as_nanos();

    if nanos >= 1_000_000_000 {
        format!("{:.1}s", nanos as f64 / 1_000_000_000.0)
    } else if nanos >= 1_000_000 {
        format!("{:.1}ms", nanos as f64 / 1_000_000.0)
    } else if nanos >= 1_000 {
        format!("{:.1}us", nanos as f64 / 1_000.0)
    } else {
        format!("{nanos}ns")
    }
}

#[cfg(test)]
mod tests {
    use crate::snapshot::{CallTreeSnapshot};
    use crate::stats::TimingStats;
    use std::time::Duration;

    #[test]
    fn renders_tree_display() {
        use crate::snapshot::NodeSnapshot;
        use super::format_duration;

        let snapshot = CallTreeSnapshot {
            roots: vec![NodeSnapshot {
                name: "request".to_string(),
                target: "app".to_string(),
                module_path: None,
                line: None,
                total_calls: 4,
                wall: TimingStats {
                    samples: 4,
                    min: Duration::from_millis(8),
                    max: Duration::from_millis(12),
                    mean: Duration::from_millis(10),
                    p95: Duration::from_millis(12),
                },
                active: TimingStats {
                    samples: 4,
                    min: Duration::from_millis(4),
                    max: Duration::from_millis(8),
                    mean: Duration::from_millis(6),
                    p95: Duration::from_millis(8),
                },
                suspended: TimingStats {
                    samples: 4,
                    min: Duration::from_millis(2),
                    max: Duration::from_millis(4),
                    mean: Duration::from_millis(3),
                    p95: Duration::from_millis(4),
                },
                children: vec![
                    NodeSnapshot {
                        name: "authenticate".to_string(),
                        target: "app".to_string(),
                        module_path: None,
                        line: None,
                        total_calls: 1,
                        wall: TimingStats {
                            samples: 1,
                            min: Duration::from_millis(5),
                            max: Duration::from_millis(5),
                            mean: Duration::from_millis(5),
                            p95: Duration::from_millis(5),
                        },
                        active: TimingStats::from_nanos(std::iter::empty()),
                        suspended: TimingStats::from_nanos(std::iter::empty()),
                        children: vec![],
                    },
                    NodeSnapshot {
                        name: "database".to_string(),
                        target: "app".to_string(),
                        module_path: None,
                        line: None,
                        total_calls: 1,
                        wall: TimingStats {
                            samples: 1,
                            min: Duration::from_millis(20),
                            max: Duration::from_millis(20),
                            mean: Duration::from_millis(20),
                            p95: Duration::from_millis(20),
                        },
                        active: TimingStats::from_nanos(std::iter::empty()),
                        suspended: TimingStats::from_nanos(std::iter::empty()),
                        children: vec![NodeSnapshot {
                            name: "query".to_string(),
                            target: "app".to_string(),
                            module_path: None,
                            line: None,
                            total_calls: 1,
                            wall: TimingStats {
                                samples: 1,
                                min: Duration::from_millis(1),
                                max: Duration::from_millis(1),
                                mean: Duration::from_millis(1),
                                p95: Duration::from_millis(1),
                            },
                            active: TimingStats::from_nanos(std::iter::empty()),
                            suspended: TimingStats::from_nanos(std::iter::empty()),
                            children: vec![],
                        }],
                    },
                ],
            }],
        };

        let rendered = snapshot.to_string();

        let line_root = format!("{:<28} {:>8} avg {:>8} p95 n={}",
            "request",
            format_duration(Duration::from_millis(10)),
            format_duration(Duration::from_millis(12)),
            4
        );

        let line_auth = format!("├── {:<28} {:>8} avg {:>8} p95 n={}",
            "authenticate",
            format_duration(Duration::from_millis(5)),
            format_duration(Duration::from_millis(5)),
            1
        );

        let line_db = format!("└── {:<28} {:>8} avg {:>8} p95 n={}",
            "database",
            format_duration(Duration::from_millis(20)),
            format_duration(Duration::from_millis(20)),
            1
        );

        let line_query = format!("    └── {:<28} {:>8} avg {:>8} p95 n={}",
            "query",
            format_duration(Duration::from_millis(1)),
            format_duration(Duration::from_millis(1)),
            1
        );

        let expected = format!("{}\n{}\n{}\n{}", line_root, line_auth, line_db, line_query);

        assert_eq!(rendered, expected);
    }
}