#perf #tracing #profiling

tracing-timing

Inter-event timing metrics on top of tracing

24 releases

0.5.0 May 15, 2021
0.4.4 May 13, 2021
0.4.3 Feb 6, 2020
0.3.0 Feb 4, 2020
0.1.2 Jun 29, 2019

#60 in Profiling

Download history 773/week @ 2021-08-11 912/week @ 2021-08-18 1820/week @ 2021-08-25 2015/week @ 2021-09-01 331/week @ 2021-09-08 94/week @ 2021-09-15 56/week @ 2021-09-22 55/week @ 2021-09-29 90/week @ 2021-10-06 216/week @ 2021-10-13 87/week @ 2021-10-20 60/week @ 2021-10-27 111/week @ 2021-11-03 8/week @ 2021-11-10 55/week @ 2021-11-17 141/week @ 2021-11-24

320 downloads per month

MIT license

60KB
914 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::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.

Dependencies

~1.3–2MB
~35K SLoC