Expand description
Log “request x-rays” for rust programs instrumented with tracing. This includes aggregated wall/own times as frequently found in flame graphs in a human-friendly text format. Example:
2022-02-06T20:01:57.103747Z INFO Call summary of request@examples/nested.rs:51
# calls │ ∑ alive ms │ ∑ busy ms │ ∑ own busy ms │ span tree
────────────┼──────────────┼──────────────┼────────────-──┼───────────────────────
0 001 ┊ 258.910 ┊ 258.890 ┊ 0.106 ┊ ┬ request
0 001 ┊ 87.204 ┊ 87.190 ┊ 19.299 ┊ ├┬ nested
0 001 ┊ 0.036 ┊ 0.021 ┊ 0.021 ┊ ┊├─ random
1 000 ┊ 75.738 ┊ 61.912 ┊ 61.912 ┊ ┊╰─ repeated
0 002 ┊ 0.051 ┊ 0.027 ┊ 0.027 ┊ ├─ repeated
0 001 ┊ 1.644 ┊ 1.632 ┊ 0.019 ┊ ├┬ nest_deeply
0 001 ┊ 1.619 ┊ 1.607 ┊ 0.025 ┊ ┊╰┬ nest_deeply
0 001 ┊ 1.593 ┊ 1.577 ┊ 0.024 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.561 ┊ 1.547 ┊ 0.022 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.532 ┊ 1.520 ┊ 0.023 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.504 ┊ 1.492 ┊ 0.023 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.476 ┊ 1.463 ┊ 0.025 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.446 ┊ 1.433 ┊ 0.025 ┊ ┊ ╰┬ nest_deeply
0 001 ┊ 1.415 ┊ 1.402 ┊ 1.402 ┊ ┊ ╰─ nest_deeply
0 001 ┊ 169.915 ┊ 169.905 ┊ 17.883 ┊ ╰┬ nested2
0 001 ┊ 0.010 ┊ 0.001 ┊ 0.001 ┊ ├─ random
1 000 ┊ 88.793 ┊ 76.081 ┊ 76.081 ┊ ├─ repeated
0 001 ┊ 70.386 ┊ 70.377 ┊ 19.332 ┊ ╰┬ nested
0 001 ┊ 0.011 ┊ 0.001 ┊ 0.001 ┊ ├─ random
1 000 ┊ 58.468 ┊ 45.280 ┊ 45.280 ┊ ╰─ repeated
- calls: The total number of spans created at this call path.
- ∑ alive ms: The total time spans at this call path were alive i.e. sum of times between new and close events.
- ∑ busy ms: The total time spans at this call path were entered i.e. sum of times between enter and leave events.
- ∑ own busy ms: The total time spans at this call path were entered without any children entered.
Under the hood, reqray
provides a CallTreeCollector tracing Layer
which, unsurprisingly, collects call trees. Once the root span (e.g. the top
most span = the top most instrumented call) has been closed, the finished
call tree is handed over to a FinishedCallTreeProcessor.
LoggingCallTreeCollector implements FinishedCallTreeProcessor and logs
each call tree in human-friendly way as shown above.
Let’s assume that you already have an explicit setup for tracing
like
this, then you simply need to add the highlighted line:
use reqray::CallTreeCollector;
use tracing_subscriber::{EnvFilter, util::SubscriberInitExt, fmt, prelude::*};
let fmt_layer = fmt::layer()
.with_target(false);
let filter_layer = EnvFilter::try_from_default_env()
.or_else(|_| EnvFilter::try_new("info"))
.unwrap();
tracing_subscriber::registry()
// -----------------------------------------------
.with(CallTreeCollector::default())
// -----------------------------------------------
.with(filter_layer)
.with(fmt_layer)
.init();
Instead of CallTreeCollector::default()
you can chose a more explicit
config using CallTreeCollectorBuilder and
LoggingCallTreeCollectorBuilder.
use reqray::{CallTreeCollectorBuilder, display::LoggingCallTreeCollectorBuilder};
use tracing_subscriber::{EnvFilter, util::SubscriberInitExt, fmt, prelude::*};
// ...
let call_tree_collector = CallTreeCollectorBuilder::default()
.max_call_depth(10)
.build_with_collector(
LoggingCallTreeCollectorBuilder::default()
.left_margin(20)
.build(),
);
tracing_subscriber::registry()
.with(call_tree_collector)
// ...
Modules
Structs
A CallPathPool contains all CallPathTimings of a call tree indexed by CallPathPoolIds.
Use a CallPathPoolId to index a CallPathTiming in a CallPathPool.
A CallPathTiming is an aggregation of all spans with the same
call path. That means that their callsite::Identifier
is
the same and all the callsite::Identifier
s of their ancestor
spans are also the same.
A tracing::Subscriber which collects call trees and hands finished trees to a FinishedCallTreeProcessor.
Configure & Build CallTreeCollectors.
Traits
A FinishedCallTreeProcessor uses the aggregated call tree for something useful.