tracing_forest/printer/
pretty.rs

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                // This needs to be called before all other actions are taken. If we don't
91                // do this now, we end up rendering every shared item of defered spans, but
92                // they are incomplete and we end up with a lot of junk on screen.
93                if !span.should_render() {
94                    return Ok(());
95                }
96
97                Pretty::format_shared(&span.shared, writer)?;
98                Pretty::format_indent(indent, writer)?;
99                Pretty::format_span(span, duration_root, indent, writer)
100            }
101        }
102    }
103
104    fn format_shared(shared: &Shared, writer: &mut String) -> fmt::Result {
105        #[cfg(feature = "uuid")]
106        write!(writer, "{} ", shared.uuid)?;
107
108        #[cfg(feature = "chrono")]
109        write!(writer, "{:<36} ", shared.timestamp.to_rfc3339())?;
110
111        #[cfg(feature = "ansi")]
112        return write!(writer, "{:<8} ", ColorLevel(shared.level));
113
114        #[cfg(not(feature = "ansi"))]
115        return write!(writer, "{:<8} ", shared.level);
116    }
117
118    fn format_indent(indent: &[Indent], writer: &mut String) -> fmt::Result {
119        for indent in indent {
120            writer.write_str(indent.repr())?;
121        }
122        Ok(())
123    }
124
125    fn format_event(event: &Event, writer: &mut String) -> fmt::Result {
126        let tag = event.tag().unwrap_or_else(|| Tag::from(event.level()));
127
128        write!(writer, "{} [{}]: ", tag.icon(), tag)?;
129
130        if let Some(message) = event.message() {
131            writer.write_str(message)?;
132        }
133
134        for field in event.fields() {
135            write!(writer, " | {}: {}", FieldKey(field.key()), field.value())?;
136        }
137
138        writeln!(writer)
139    }
140
141    fn format_span(
142        span: &Span,
143        duration_root: Option<f64>,
144        indent: &mut IndentVec,
145        writer: &mut String,
146    ) -> fmt::Result {
147        let total_duration = span.total_duration().as_nanos() as f64;
148        let inner_duration = span.inner_duration().as_nanos() as f64;
149        let root_duration = duration_root.unwrap_or(total_duration);
150        let percent_total_of_root_duration = 100.0 * total_duration / root_duration;
151
152        write!(
153            writer,
154            "{} [ {} | ",
155            span.name(),
156            DurationDisplay(total_duration)
157        )?;
158
159        if inner_duration > 0.0 {
160            let base_duration = span.base_duration().as_nanos() as f64;
161            let percent_base_of_root_duration = 100.0 * base_duration / root_duration;
162            write!(writer, "{percent_base_of_root_duration:.2}% / ")?;
163        }
164
165        write!(writer, "{percent_total_of_root_duration:.2}% ]")?;
166
167        for (n, field) in span.shared.fields.iter().enumerate() {
168            write!(
169                writer,
170                "{} {}: {}",
171                if n == 0 { "" } else { " |" },
172                FieldKey(field.key()),
173                field.value()
174            )?;
175        }
176        writeln!(writer)?;
177
178        // We need to limit our nodes to those that *will* render, else we
179        // end up printing ghost indents.
180        let nodes: Vec<_> = span
181            .nodes()
182            .iter()
183            .filter(|node| node.should_render())
184            .collect();
185
186        if let Some((last, remaining)) = nodes.split_last() {
187            match indent.last_mut() {
188                Some(edge @ Indent::Turn) => *edge = Indent::Null,
189                Some(edge @ Indent::Fork) => *edge = Indent::Line,
190                _ => {}
191            }
192
193            indent.push(Indent::Fork);
194
195            for tree in remaining {
196                if let Some(edge) = indent.last_mut() {
197                    *edge = Indent::Fork;
198                }
199                Pretty::format_tree(tree, Some(root_duration), indent, writer)?;
200            }
201
202            if let Some(edge) = indent.last_mut() {
203                *edge = Indent::Turn;
204            }
205            Pretty::format_tree(last, Some(root_duration), indent, writer)?;
206
207            indent.pop();
208        }
209
210        Ok(())
211    }
212}
213
214enum Indent {
215    Null,
216    Line,
217    Fork,
218    Turn,
219}
220
221impl Indent {
222    fn repr(&self) -> &'static str {
223        match self {
224            Self::Null => "   ",
225            Self::Line => "│  ",
226            Self::Fork => "┝━ ",
227            Self::Turn => "┕━ ",
228        }
229    }
230}
231
232struct DurationDisplay(f64);
233
234// Taken from chrono
235impl fmt::Display for DurationDisplay {
236    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
237        let mut t = self.0;
238        for unit in ["ns", "µs", "ms", "s"] {
239            if t < 10.0 {
240                return write!(f, "{t:.2}{unit}");
241            } else if t < 100.0 {
242                return write!(f, "{t:.1}{unit}");
243            } else if t < 1000.0 {
244                return write!(f, "{t:.0}{unit}");
245            }
246            t /= 1000.0;
247        }
248        write!(f, "{:.0}s", t * 1000.0)
249    }
250}
251
252/// Implements colored formatting for a field if enabled
253struct FieldKey<'a>(&'a str);
254
255impl fmt::Display for FieldKey<'_> {
256    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
257        #[cfg(feature = "ansi")]
258        {
259            let color = Color::White.dimmed();
260
261            write!(f, "{}{}{}", color.prefix(), self.0, color.suffix())
262        }
263        #[cfg(not(feature = "ansi"))]
264        {
265            f.write_str(self.0)
266        }
267    }
268}
269
270// From tracing-tree
271#[cfg(feature = "ansi")]
272struct ColorLevel(Level);
273
274#[cfg(feature = "ansi")]
275impl fmt::Display for ColorLevel {
276    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
277        let color = match self.0 {
278            Level::TRACE => Color::Purple,
279            Level::DEBUG => Color::Blue,
280            Level::INFO => Color::Green,
281            Level::WARN => Color::RGB(252, 234, 160), // orange
282            Level::ERROR => Color::Red,
283        };
284        let style = color.bold();
285        write!(f, "{}", style.prefix())?;
286        f.pad(self.0.as_str())?;
287        write!(f, "{}", style.suffix())
288    }
289}
tracing_forest/printer/pretty.rs

tracing_forest/printer/
pretty.rs
