Timing async functions in rust

I would like to time async function calls in Rust. The crate tracing_timing does not appear adequate since it does not support async function calls. What I would like is that after the end of the running of the program I obtain statistics over the runtime use
One solution which empirically works is to have some features with some code like

    if cfg!(feature = "timings") {
        let before = SystemTime::now();
        let result = self.get_data(key).await;
        let after = SystemTime::now();
        println!("|get_data|={:?}", after.duration_since(before));
        result
    } else {
        self.get_data(key).await
    }

It works well and fine for the purpose. The feature is very similar to a #ifdef TIMINGS in C++ and the timing information is written to a log file that can be looked at after the run by Python scripts of similar. But that solution is kind of direct adaptation of C++ and surely Rust must have some more idiomatic solutions.

What would be such a idiomatic rust solution? What would be the source of information on how to trace rust code and identify slow points. There are many different crates and their interaction can be complicated.

There's tons of ways to do this, depending on which frameworks you're using. It also depends on what you want to time.

From scratch

If you want to know the duration between calling await and returning, like your example, you can easily create a wrapper function that does that.

pub async fn time_async<F, O>(f: F) -> (O, Duration)
where
    F: Future<Output = O>,
{
    let start = Instant::now();
    let out = f.await;
    let duration = start.elapsed();
    (out, duration)
}

You should use Instant for finding durations. SystemTime is useful for knowing when something happens, but since it can change forwards or backwards at any moment (from your program's perspective), it's not suitable for finding how long something takes.

Then you can log it however you like.

pub async fn log_time_async<F, D, O>(f: F, name: D) -> O
where
    F: Future<Output = O>,
    D: Display,
{
    if cfg!(feature = "timings") {
        let (out, duration) = time_async(f).await;
        println!("|{name}|={duration:?}");
        out
    } else {
        f.await
    }
}

The ecosystem

tracing

I believe tracing's enter method would give you the above behavior when used naively. However, I don't think subscribers are usually set up to handle the overlapping spans this produces (you can have numerous instances of the function awaiting at the same time), so you would have to test that it works for your case.

pub async fn trace_async<F, O>(f: F, span: Span) -> O
where
    F: Future<Output = O>,
{
    let guard = span.enter();
    let out = f.await;
    drop(guard);
    out
}

If you want to know how much executor time a future takes—in other words, how much time is spent polling the future—then you need a more complex solution. Fortunately, tracing has a method just for that: instrument, as well as a macro.

// With the method
pub async fn trace_exec<F, O>(f: F, span: Span) -> O
where
    F: Future<Output = O>,
{
    f.instrument(span).await
}

// Or directly on the function
#[tracing::instrument]
pub async fn something_to_time() {
    something_slow().await;
}

These events can then be interpreted by a subscriber, of which there are many.

log

For logging, tracing can communicate with log. Details on that are in the documentation.

tokio

Tokio has a framework for logging called console that uses instrument spans to track active and idle time, but it's executor-specific (tokio) and fairly new.

All the code in playground