tracing: #[instrument] adds unnecessary frames to async backtraces

[TethysSvensson]

Feature Request

When using #[tracing::instrument] the generated backtraces are larger than necessary.

Here is an example of what I mean:

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt().init();
    this_will_panic().await;
}

#[tracing::instrument]
async fn this_will_panic() {
    todo!()
}

This outputs the following backtrace frames related to this_will_panic:

   3: example::this_will_panic::{{closure}}::{{closure}}
             at ./src/main.rs:9:5
   4: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at .../tracing-0.1.44/src/instrument.rs:321:15
   5: example::this_will_panic::{{closure}}
             at ./src/main.rs:7:1

Here frame 5 does not bring any meaningful value to the reader. Similarly the repeated {{closure}}::{{closure}} in frame 3 brings no value either and should ideally only be {{closure}}.

Crates

• tracing

Motivation

I am trying to improve the OpenTelemetry logging at my company. Specifically I am trying to improve the signal-to-noise ratio and limit the amount of logs we store. One of the ways we are considering is to only capture a limited number of backtrace frames.

With this current implementation of #[instrument], that approach is made harder by the fact that the macro outputs more frames than strictly necessary.

More generally I think a lot of users would benefit from having more readable backtraces. Backtraces in async code can already be fairly long and outputting extra frames certainly isn't helping.

Proposal

I suggest that we get rid of one of the backtrace frames by slightly changing the generated code.

Instead of generating an async function, I propose that we generate a function that returns an impl Future.

I am thinking that the generated code will look something like this:

fn this_will_panic() -> impl Future<Output = ()> {
        let __tracing_attr_span = #span;
        let __tracing_instrument_future = #mk_fut;
        if !__tracing_attr_span.is_disabled() {
            #follows_from
        }
        ::tracing::Instrument::instrument(
            __tracing_instrument_future,
            __tracing_attr_span
        )
}

As a minor bonus, this version should use marginally less memory. The current code double-wraps the inner future: First in the Instrumented<T> then in a compiler-generated state machine for the outer async function. The new version only wraps the inner future once.

(Theoretically it should also execute faster, though I highly doubt that anybody is going to notice that in practice)

Open questions

Type inference: To my understanding this should be equivalent to the current code; however, I am not 100% sure that both versions are equivalent with regard to lifetimes or auto-traits such as Send.

Conditional wrapping: The current code uses an if statement to avoid wrapping the inner future in an Instrumented<T> when the span is disabled. For a disabled span the Instrumented<T> does not act completely the same as a plain T, as Span::do_enter may still execute side effects even when the span is disabled. If this is a problem, a different wrapper type could potentially be used instead.