Struct tracing_forest::printer::Pretty

source ·

pub struct Pretty;

Expand description

Format logs for pretty printing.

Interpreting span times

Spans have the following format:

<NAME> [ <DURATION> | <BODY> / <ROOT> ]

DURATION represents the total time the span was entered for. If the span was used to instrument a Future that sleeps, then that time won’t be counted since the Future won’t be polled during that time, and so the span won’t enter.
BODY represents the percent time the span is entered relative to the root span, excluding time that any child spans are entered.
ROOT represents the percent time the span is entered relative to the root span, including time that any child spans are entered.

As a mental model, look at ROOT to quickly narrow down which branches are costly, and look at BASE to pinpoint exactly which spans are expensive.

Spans without any child spans would have the same BASE and ROOT, so the redundency is omitted.

Examples

An arbitrarily complex example:

INFO     try_from_entry_ro [ 324µs | 8.47% / 100.00% ]
INFO     ┝━ server::internal_search [ 296µs | 19.02% / 91.53% ]
INFO     │  ┝━ ｉ [filter.info]: Some filter info...
INFO     │  ┝━ server::search [ 226µs | 10.11% / 70.01% ]
INFO     │  │  ┝━ be::search [ 181µs | 6.94% / 55.85% ]
INFO     │  │  │  ┕━ be::search -> filter2idl [ 158µs | 19.65% / 48.91% ]
INFO     │  │  │     ┝━ be::idl_arc_sqlite::get_idl [ 20.4µs | 6.30% ]
INFO     │  │  │     │  ┕━ ｉ [filter.info]: Some filter info...
INFO     │  │  │     ┕━ be::idl_arc_sqlite::get_idl [ 74.3µs | 22.96% ]
ERROR    │  │  │        ┝━ 🚨 [admin.error]: On no, an admin error occurred :(
DEBUG    │  │  │        ┝━ 🐛 [debug]: An untagged debug log
INFO     │  │  │        ┕━ ｉ [admin.info]: there's been a big mistake | alive: false | status: "very sad"
INFO     │  │  ┕━ be::idl_arc_sqlite::get_identry [ 13.1µs | 4.04% ]
ERROR    │  │     ┝━ 🔐 [security.critical]: A security critical log
INFO     │  │     ┕━ 🔓 [security.access]: A security access log
INFO     │  ┕━ server::search<filter_resolve> [ 8.08µs | 2.50% ]
WARN     │     ┕━ 🚧 [filter.warn]: Some filter warning
TRACE    ┕━ 📍 [trace]: Finished!