Inter-event timing metrics on top of tracing
.
This crate provides a tracing::Subscriber
that keeps statistics on
inter-event timing information. More concretely, given code like this:
use tracing::*;
use tracing_timing::{Builder, Histogram};
let subscriber = Builder::from(|| Histogram::new_with_max(1_000_000, 2).unwrap()).build();
let dispatcher = Dispatch::new(subscriber);
dispatcher::with_default(&dispatcher, || {
trace_span!("request").in_scope(|| {
// do a little bit of work
trace!("fast");
// do a lot of work
trace!("slow");
})
});
You can produce something like this:
fast:
mean: 173.2µs, p50: 172µs, p90: 262µs, p99: 327µs, p999: 450µs, max: 778µs
25µs | * | 2.2th %-ile
50µs | * | 2.2th %-ile
75µs | * | 4.7th %-ile
100µs | *** | 11.5th %-ile
125µs | ***** | 24.0th %-ile
150µs | ******* | 41.1th %-ile
175µs | ******** | 59.2th %-ile
200µs | ******* | 75.4th %-ile
225µs | ** | 80.1th %-ile
250µs | *** | 87.3th %-ile
275µs | *** | 94.4th %-ile
300µs | ** | 97.8th %-ile
slow:
mean: 623.3µs, p50: 630µs, p90: 696µs, p99: 770µs, p999: 851µs, max: 950µs
500µs | * | 1.6th %-ile
525µs | ** | 4.8th %-ile
550µs | *** | 10.9th %-ile
575µs | ***** | 22.2th %-ile
600µs | ******* | 37.9th %-ile
625µs | ******** | 55.9th %-ile
650µs | ******* | 72.9th %-ile
675µs | ****** | 85.6th %-ile
700µs | **** | 93.5th %-ile
725µs | ** | 97.1th %-ile
When TimingSubscriber
is used as the tracing::Dispatch
, the time
between each event in a span is measured using quanta
, and is
recorded in "high dynamic range histograms" using hdrhistogram
's
multi-threaded recording facilities. The recorded timing information is
grouped using the SpanGroup
and EventGroup
traits, allowing you to
combine recorded statistics across spans and events.