tracing_forest/printer/
pretty.rs

Help
1use crate::printer::Formatter;
2use crate::tree::{Event, Shared, Span, Tree};
3use crate::Tag;
4use std::fmt::{self, Write};
5
6#[cfg(feature = "smallvec")]
7type IndentVec = smallvec::SmallVec<[Indent; 32]>;
8#[cfg(not(feature = "smallvec"))]
9type IndentVec = Vec<Indent>;
10
11#[cfg(feature = "ansi")]
12use ansi_term::Color;
13#[cfg(feature = "ansi")]
14use tracing::Level;
15
16/// Format logs for pretty printing.
17///
18/// # Interpreting span times
19///
20/// Spans have the following format:
21/// ```txt
22/// <NAME> [ <DURATION> | <BODY> / <ROOT> ]
23/// ```
24/// * `DURATION` represents the total time the span was entered for. If the span
25/// was used to instrument a `Future` that sleeps, then that time won't be counted
26/// since the `Future` won't be polled during that time, and so the span won't enter.
27/// * `BODY` represents the percent time the span is entered relative to the root
28/// span, *excluding* time that any child spans are entered.
29/// * `ROOT` represents the percent time the span is entered relative to the root
30/// span, *including* time that any child spans are entered.
31///
32/// As a mental model, look at `ROOT` to quickly narrow down which branches are
33/// costly, and look at `BASE` to pinpoint exactly which spans are expensive.
34///
35/// Spans without any child spans would have the same `BASE` and `ROOT`, so the
36/// redundency is omitted.
37///
38/// # Examples
39///
40/// An arbitrarily complex example:
41/// ```log
42/// INFO     try_from_entry_ro [ 324µs | 8.47% / 100.00% ]
43/// INFO     ┝━ server::internal_search [ 296µs | 19.02% / 91.53% ]
44/// INFO     │  ┝━ ｉ [filter.info]: Some filter info...
45/// INFO     │  ┝━ server::search [ 226µs | 10.11% / 70.01% ]
46/// INFO     │  │  ┝━ be::search [ 181µs | 6.94% / 55.85% ]
47/// INFO     │  │  │  ┕━ be::search -> filter2idl [ 158µs | 19.65% / 48.91% ]
48/// INFO     │  │  │     ┝━ be::idl_arc_sqlite::get_idl [ 20.4µs | 6.30% ]
49/// INFO     │  │  │     │  ┕━ ｉ [filter.info]: Some filter info...
50/// INFO     │  │  │     ┕━ be::idl_arc_sqlite::get_idl [ 74.3µs | 22.96% ]
51/// ERROR    │  │  │        ┝━ 🚨 [admin.error]: On no, an admin error occurred :(
52/// DEBUG    │  │  │        ┝━ 🐛 [debug]: An untagged debug log
53/// INFO     │  │  │        ┕━ ｉ [admin.info]: there's been a big mistake | alive: false | status: "very sad"
54/// INFO     │  │  ┕━ be::idl_arc_sqlite::get_identry [ 13.1µs | 4.04% ]
55/// ERROR    │  │     ┝━ 🔐 [security.critical]: A security critical log
56/// INFO     │  │     ┕━ 🔓 [security.access]: A security access log
57/// INFO     │  ┕━ server::search<filter_resolve> [ 8.08µs | 2.50% ]
58/// WARN     │     ┕━ 🚧 [filter.warn]: Some filter warning
59/// TRACE    ┕━ 📍 [trace]: Finished!
60/// ```
61#[derive(Debug)]
62pub struct Pretty;
63
64impl Formatter for Pretty {
65    type Error = fmt::Error;
66
67    fn fmt(&self, tree: &Tree) -> Result<String, fmt::Error> {
68        let mut writer = String::with_capacity(256);
69
70        Pretty::format_tree(tree, None, &mut IndentVec::new(), &mut writer)?;
71
72        Ok(writer)
73    }
74}
75
76impl Pretty {
77    fn format_tree(
78        tree: &Tree,
79        duration_root: Option<f64>,
80        indent: &mut IndentVec,
81        writer: &mut String,
82    ) -> fmt::Result {
83        match tree {
84            Tree::Event(event) => {
85                Pretty::format_shared(&event.shared, writer)?;
86                Pretty::format_indent(indent, writer)?;
87                Pretty::format_event(event, writer)
88            }
89            Tree::Span(span) => {
90                Pretty::format_shared(&span.shared, writer)?;
91                Pretty::format_indent(indent, writer)?;
92                Pretty::format_span(span, duration_root, indent, writer)
93            }
94        }
95    }
96
97    fn format_shared(shared: &Shared, writer: &mut String) -> fmt::Result {
98        #[cfg(feature = "uuid")]
99        write!(writer, "{} ", shared.uuid)?;
100
101        #[cfg(feature = "chrono")]
102        write!(writer, "{:<36} ", shared.timestamp.to_rfc3339())?;
103
104        #[cfg(feature = "ansi")]
105        return write!(writer, "{:<8} ", ColorLevel(shared.level));
106
107        #[cfg(not(feature = "ansi"))]
108        return write!(writer, "{:<8} ", shared.level);
109    }
110
111    fn format_indent(indent: &[Indent], writer: &mut String) -> fmt::Result {
112        for indent in indent {
113            writer.write_str(indent.repr())?;
114        }
115        Ok(())
116    }
117
118    fn format_event(event: &Event, writer: &mut String) -> fmt::Result {
119        let tag = event.tag().unwrap_or_else(|| Tag::from(event.level()));
120
121        write!(writer, "{} [{}]: ", tag.icon(), tag)?;
122
123        if let Some(message) = event.message() {
124            writer.write_str(message)?;
125        }
126
127        for field in event.fields().iter() {
128            write!(writer, " | {}: {}", field.key(), field.value())?;
129        }
130
131        writeln!(writer)
132    }
133
134    fn format_span(
135        span: &Span,
136        duration_root: Option<f64>,
137        indent: &mut IndentVec,
138        writer: &mut String,
139    ) -> fmt::Result {
140        let total_duration = span.total_duration().as_nanos() as f64;
141        let inner_duration = span.inner_duration().as_nanos() as f64;
142        let root_duration = duration_root.unwrap_or(total_duration);
143        let percent_total_of_root_duration = 100.0 * total_duration / root_duration;
144
145        write!(
146            writer,
147            "{} [ {} | ",
148            span.name(),
149            DurationDisplay(total_duration)
150        )?;
151
152        if inner_duration > 0.0 {
153            let base_duration = span.base_duration().as_nanos() as f64;
154            let percent_base_of_root_duration = 100.0 * base_duration / root_duration;
155            write!(writer, "{:.2}% / ", percent_base_of_root_duration)?;
156        }
157
158        write!(writer, "{:.2}% ]", percent_total_of_root_duration)?;
159
160        for (n, field) in span.shared.fields.iter().enumerate() {
161            write!(
162                writer,
163                "{} {}: {}",
164                if n == 0 { "" } else { " |" },
165                field.key(),
166                field.value()
167            )?;
168        }
169        writeln!(writer)?;
170
171        if let Some((last, remaining)) = span.nodes().split_last() {
172            match indent.last_mut() {
173                Some(edge @ Indent::Turn) => *edge = Indent::Null,
174                Some(edge @ Indent::Fork) => *edge = Indent::Line,
175                _ => {}
176            }
177
178            indent.push(Indent::Fork);
179
180            for tree in remaining {
181                if let Some(edge) = indent.last_mut() {
182                    *edge = Indent::Fork;
183                }
184                Pretty::format_tree(tree, Some(root_duration), indent, writer)?;
185            }
186
187            if let Some(edge) = indent.last_mut() {
188                *edge = Indent::Turn;
189            }
190            Pretty::format_tree(last, Some(root_duration), indent, writer)?;
191
192            indent.pop();
193        }
194
195        Ok(())
196    }
197}
198
199enum Indent {
200    Null,
201    Line,
202    Fork,
203    Turn,
204}
205
206impl Indent {
207    fn repr(&self) -> &'static str {
208        match self {
209            Self::Null => "   ",
210            Self::Line => "│  ",
211            Self::Fork => "┝━ ",
212            Self::Turn => "┕━ ",
213        }
214    }
215}
216
217struct DurationDisplay(f64);
218
219// Taken from chrono
220impl fmt::Display for DurationDisplay {
221    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
222        let mut t = self.0;
223        for unit in ["ns", "µs", "ms", "s"] {
224            if t < 10.0 {
225                return write!(f, "{:.2}{}", t, unit);
226            } else if t < 100.0 {
227                return write!(f, "{:.1}{}", t, unit);
228            } else if t < 1000.0 {
229                return write!(f, "{:.0}{}", t, unit);
230            }
231            t /= 1000.0;
232        }
233        write!(f, "{:.0}s", t * 1000.0)
234    }
235}
236
237// From tracing-tree
238#[cfg(feature = "ansi")]
239struct ColorLevel(Level);
240
241#[cfg(feature = "ansi")]
242impl fmt::Display for ColorLevel {
243    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
244        let color = match self.0 {
245            Level::TRACE => Color::Purple,
246            Level::DEBUG => Color::Blue,
247            Level::INFO => Color::Green,
248            Level::WARN => Color::RGB(252, 234, 160), // orange
249            Level::ERROR => Color::Red,
250        };
251        let style = color.bold();
252        write!(f, "{}", style.prefix())?;
253        f.pad(self.0.as_str())?;
254        write!(f, "{}", style.suffix())
255    }
256}
tracing_forest/printer/pretty.rs

tracing_forest/printer/
pretty.rs
