Crate tracing_timing

Inter-event timing metrics.

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::default().build(|| Histogram::new_with_max(1_000_000, 2).unwrap());
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 (see examples/pretty.rs):

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.

Extracting timing histograms

The crate does not implement a mechanism for recording the resulting histograms. Instead, you can implement this as you see fit using TimingSubscriber::with_histograms. It gives you access to the histograms for all groups. Note that you must call refresh() on each histogram to see its latest values (see hdrhistogram::SyncHistogram).

To access the histograms later, use tracing::Dispatch::downcast_ref. If your type is hard to name, you can use a TimingSubscriber::downcaster instead.

use tracing::*;
use tracing_timing::{Builder, Histogram, TimingSubscriber};
let subscriber = Builder::default().build(|| Histogram::new_with_max(1_000_000, 2).unwrap());
let dispatch = Dispatch::new(subscriber);
// ...
// code that hands off clones of the dispatch
// maybe to other threads
// ...
dispatch.downcast_ref::<TimingSubscriber>().unwrap().with_histograms(|hs| {
    for (span_group, hs) in hs {
        for (event_group, h) in hs {
            // make sure we see the latest samples:
            h.refresh();
            // print the median:
            println!("{} -> {}: {}ns", span_group, event_group, h.value_at_quantile(0.5))
        }
    }
});

See the documentation for hdrhistogram for more on what you can do once you have the histograms.

Grouping samples

By default, TimingSubscriber groups samples by the "name" of the containing span and the "message" of the relevant event. These are the first string parameter you pass to each of the relevant tracing macros. You can override this behavior either by providing your own implementation of SpanGroup and EventGroup to Builder::spans and Builder::events respectively. There are also a number of pre-defined "groupers" in the group module that cover the most common cases.

Timing information over time

Every time you refresh a histogram, it incorporates any new timing samples recorded since the last call to refresh, allowing you to see timing metrics across all time. If you are monitoring the health of a continuously running system, you may instead wish to only see metrics across a limited window of time. You can do this by clearing the histogram in TimingSubscriber::with_histograms before refreshing them, or periodically as you see fit.

Usage notes:

Event timing is per span, not per span per thread. This means that if you emit events for the same span concurrently from multiple threads, you may see weird timing information.

Span creation takes a lock. This means that you will generally want to avoid creating extraneous spans. One technique that works well here is subsampling your application, for example by only creating tracking spans for some of your requests.

Modules

group

Commonly used span and event grouping mechanisms.

Structs

Builder	Builder for TimingSubscriber instances.
Downcaster	A convenience type for getting access to TimingSubscriber through a Dispatch.
Histogram	Histogram is the core data structure in HdrSample. It records values, and performs analytics.
TimingSubscriber	Timing-gathering tracing subscriber.

Traits

EventGroup	Translate attributes from a tracing event into a timing event group.
SpanGroup	Translate attributes from a tracing span into a timing span group.

Type Definitions

HashMap	A standard library HashMap with a faster hasher.
Hasher	A faster hasher for tracing-timing maps.