How can I log span duration with Rust tracing?

Question

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?

Answer 1

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.