console icon indicating copy to clipboard operation
console copied to clipboard

subscriber/tasks proto: capture spans *inside* spawned tasks

Open hawkw opened this issue 4 years ago • 3 comments

Right now, the TasksLayer in console-subscriber only captures the span attached to every spawned task by Tokio's own tracing integration. these spans are useful, but they lack a lot of the user-generated data that's provided by the user's spans. If the user instruments the future passed to tokio::spawn, for example, we should be able to recognize that this span is also part of the task, and record its data as well.

The primary motivation for implementing a feature like this is that most of the mocks and designs that people have come up with so far show user-provided names and fields for tasks in the console. However, we can't capture that if we are only looking at the per-task spans generated by the runtime (e.g. tokio's task span).

hawkw avatar May 04 '21 22:05 hawkw

I assume you mean that at tokio::spawn, if the user uses essentially tokio::spawn(future.instrument(span)), that span's user-set values would be worth including, which I agree. How would we detect that? I at first thought since F: 'static, we could check the TypeId or downcast, but it would be tracing::Instrumented<T>, which would make it a type we couldn't really check for in that way.

There's also the question of how "deep" should we try to sniff. Like, if someone spawns a Box<dyn Future> that was instrumented before boxed, that'd be helpful. They might also wrap an instrumented future in a tiny combinator. But how far do we go?

seanmonstar avatar May 04 '21 23:05 seanmonstar

I assume you mean that at tokio::spawn, if the user uses essentially tokio::spawn(future.instrument(span)), that span's user-set values would be worth including, which I agree. How would we detect that? I at first thought since F: 'static, we could check the TypeId or downcast, but it would be tracing::Instrumented<T>, which would make it a type we couldn't really check for in that way.

I was imagining something a bit simpler, which is that we would just record whatever the first span that's entered inside a spawned task's span is.

hawkw avatar May 15 '21 17:05 hawkw

As a new console user, I found this behavior to be very surprising. When running this code, I expected that I'd see a task named "fancy_sleep" in tokio-console, with the associated Duration as a field.

#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error>> {
    console_subscriber::init();

    tokio::task::spawn(fancy_sleep(Duration::from_secs(30))).await?;
    Ok(())
}

#[instrument]
async fn fancy_sleep(duration: Duration) {
    tokio::time::sleep(duration).await;
}

I've looked for workarounds, but nothing feels especially satisfying to me. I could use task::Builder, but it seems needlessly verbose, duplicates the function name, and doesn't capture the instrumented duration field.

    task::Builder::new()
        .name("fancy_sleep")
        .spawn(fancy_sleep(Duration::from_secs(30)))?
        .await?;

vultix avatar Jan 14 '24 21:01 vultix