6

Rust has a tracing library that seems quite popular. It uses a building block called "span":

Spans represent periods of time in the execution of a program.

Now that I've set spans all throughout my app, how can I actually log their duration?

I've so far found:

  • tracing-timing. Great, but a bit elaborate, printing whole histogram, when I'd like simple durations.
  • tracing-tree. This one is really close to what I'm looking for, currently set up is failing for me, I'll figure it out, but this one still prints them in a tree, I'm looking more for the plain duration. No tree.

Any way to do that with tracing?

kmdreko
  • 42,554
  • 6
  • 57
  • 106
alextes
  • 1,817
  • 2
  • 15
  • 22

1 Answers1

6

The basic formatting layer from tracing-subscriber is very flexible with what is logged. By default it will only show log events, but there are other events available for spans (new, enter, exit, close). You'd be interested in the logging the "close" events, which indicate when the span has ended and would know the time elapsed from when it started.

You can do this simply using .with_span_events() and FmtSpan::CLOSE. Here's a sample:

[dependencies]
tracing = "0.1.36"
tracing-subscriber = "0.3.15"

use std::time::Duration;
use tracing_subscriber::fmt;
use tracing_subscriber::fmt::format::FmtSpan;

#[tracing::instrument]
fn do_some_work(n: i32) {
    std::thread::sleep(Duration::from_millis(100));
    if n == 1 {
        do_some_more_work();
    }
}

#[tracing::instrument]
fn do_some_more_work() {
    std::thread::sleep(Duration::from_millis(100));
}

fn main() {
    fmt::fmt()
        .with_span_events(FmtSpan::CLOSE)
        .with_target(false)
        .with_level(false)
        .init();

    for n in 0..3 {
        do_some_work(n);
    }
}


2022-09-14T15:47:01.684149Z do_some_work{n=0}: close time.busy=110ms time.idle=5.10µs
2022-09-14T15:47:01.904656Z do_some_work{n=1}:do_some_more_work: close time.busy=109ms time.idle=3.00µs
2022-09-14T15:47:01.904986Z do_some_work{n=1}: close time.busy=220ms time.idle=1.60µs
2022-09-14T15:47:02.014846Z do_some_work{n=2}: close time.busy=110ms time.idle=2.20µs

You can customize it to your liking further with other methods or by creating a custom FormatEvent implementation.

I do want to mention that tracing is "a framework for instrumenting Rust programs to collect structured, event-based diagnostic information." While function timing is part of that diagnostic information, it is designed in a way to collect that information in the field. If you're trying to assess the performance of your code in a synthetic environment, I'd encourage you to use a more robust benchmarking library like criterion.

kmdreko
  • 42,554
  • 6
  • 57
  • 106
  • How do you do this limited to application (not library) spans only? – Sridhar Ratnakumar Aug 10 '23 at 14:44
  • @SridharRatnakumar If you want to limit your log output to only the application, you can use something like [`EnvFilter`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html) or some other hard-coded filter to do that. If you want all logs but only see the *close* events in your application, then you'd probably need a custom layer for that. Post a separate question if you need more details or other options. – kmdreko Aug 10 '23 at 15:14