Measure function call latency

[user8555]

Is it possible to measure function call latency with spans or instrument ?

I don’t it in the console log output that is generated.

[davidbarsky]

If you're using tracing_subscriber, set fmt::Layer::with_span_events to FmtSpan::FULL. This will cause tracing_subscriber to print out the the span's busy time (the total time for which it was entered) and idle time (the total time that the span existed but was not entered). Here's a subset of the output I got when running the fmt.rs example with fmt::Layer::with_span_events set to FmtSpan::FULL:

❯ cargo run --example fmt
    Finished dev [unoptimized + debuginfo] target(s) in 0.12s
     Running `/Users/david/Developer/Rust/tracing/target/debug/examples/fmt`
Jul 25 13:33:24.707  INFO fmt: preparing to shave yaks number_of_yaks=3
Jul 25 13:33:24.708  INFO fmt::yak_shave: shaving yaks
Jul 25 13:33:24.708  INFO shave{yak=1}: fmt::yak_shave: new
Jul 25 13:33:24.708  INFO shave{yak=1}: fmt::yak_shave: enter
Jul 25 13:33:24.708 DEBUG shave{yak=1}: fmt::yak_shave: hello! I'm gonna shave a yak. excitement="yay!"
Jul 25 13:33:24.708 DEBUG shave{yak=1}: fmt::yak_shave: yak shaved successfully
Jul 25 13:33:24.708  INFO shave{yak=1}: fmt::yak_shave: exit
Jul 25 13:33:24.708  INFO shave{yak=1}: fmt::yak_shave: close time.busy=207µs time.idle=105µs

For that example, I configured the fmt::Layer like this:

fn main() {
    tracing_subscriber::fmt()
        // all spans/events with a level higher than DEBUG (e.g, info, warn, etc.)
        // will be written to stdout.
        .with_max_level(Level::DEBUG)
        // Events will be synthesized whenever a span is created, entered, exited, or closed.
        // The close event will contain the span's busy and idle time if timestamps are enabled.
        .with_span_events(FmtSpan::FULL)
        // sets this to be the default, global subscriber for this application.
        .init();
    // rest of the example redacted...
}

If you need more detailed per-span information, take a look at tracing-timing.

As one final note, tracing generally prefers to avoid imposing costs—performance or otherwise—on subscribers and layers that might not need them. Measuring the elapsed time of a span is one such example.

[user8555]

Measuring the elapsed time of a span is one such example.

What do you mean? Is measuring time not recommended because it is expensive?

[davidbarsky]

What do you mean? Is measuring time not recommended because it is expensive?

My bad! No, please measure the elapsed time. I should've said that tracing is very conservative with what data it records itself versus what data it defers to libraries that are built atop of tracing. I wanted to provide context as to some of tracing's design decisions.

In either case, I hope my explanation helped.

[user8555]

Thanks!

Is it possible to Instrument async functions? The fmt.rs shave function is not async function.

Is there a tracing subscriber that can write latency in more structured format to a file?

[davidbarsky]

Is it possible to Instrument async functions? The fmt.rs shave function is not async function.

Yup! Take a look at this section: https://github.com/tokio-rs/tracing#in-asynchronous-code. In short, you've got two options:

• the #[instrument] macro can be used on asynchronous functions, and it'll create a new span and attach it to the asynchronous function
• You can use the tracing-futures (and soon to be, tracing)-vended instrument combinator: tracing: Instrument std::future::Future in tracing #808 and attach the span manually to an unawaited future like this:

let my_future = async {
    // ...
};

my_future
    .instrument(tracing::info_span!("my_future"))
    .await

We have some smaller asynchronous examples in this repo (hyper-echo, tokio-spawny-thing), but I'd also suggest looking at tokio-rs/mini-redis, which shows how to use tracing (and other parts of Tokio!) in the context of a larger application.

Is there a tracing subscriber that can write latency in more structured format to a file?

Kinda. You can use tracing-appender to get a RollingFileAppender-style writer. It has all the standard/expected features of appending to a file in on a dedicated thread. However, we have a standard way to emit metrics/timing information via some Subscriber or Layer—just some adhoc stuff like tracing-subscriber's JSON logging feature. That configuration, for what it's worth, would be:

tracing_subscriber::fmt()
    // all spans/events with a level higher than DEBUG (e.g, info, warn, etc.)
    // will be written to stdout.
    .with_max_level(Level::DEBUG)
    .with_span_events(format::FmtSpan::FULL)
    .json()
    .init();

On an aside, it's funny that you asked about metrics! It's something we've been discussing for the past week and I have a meeting later today with some colleagues to figure out a path forward for emitting metrics from tracing. The artifact of this meeting should be an outline of an issue that I'll cc you on.

Additionally, feel free to ping me on Discord; I'm endsofthreads#8974 there or join us in the tracing channel in the Tokio Discord channel (link in the main README.md), as I can speak a bit more candidly about that I'm thinking about and get a better understanding of your needs.

Is there a way to capture values such as time.busy in code?