#perf #tracing #profiling

tracing-timing

Inter-event timing metrics on top of tracing

16 releases

✓ Uses Rust 2018 edition

0.2.12 Jul 16, 2019
0.2.11 Jul 16, 2019
0.2.0 Jun 29, 2019
0.1.2 Jun 29, 2019

#11 in Profiling

Download history 11/week @ 2019-06-22 97/week @ 2019-06-29 189/week @ 2019-07-06

100 downloads per month

MIT license

43KB
603 lines

Crates.io Documentation Build Status Cirrus CI Build Status Codecov Dependency status

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.

Dependencies

~1.5MB
~20K SLoC