tracing: add tokio::task::Builder #3881

jbr · 2021-06-21T23:13:44Z

Motivation

Task name annotations are helpful in order to better understand what is happening in an async application

Solution

This PR adds a cfg_trace-gated unstable builder tokio::task::Builder, which allows authors to annotate a task at runtime with an appropriate name. It includes task.name instrumentation for Builder::spawn, Builder::spawn_local, and Builder::spawn_blocking

carllerche

Looks good to me. Some basic tests using the Builder would be nice. We don't have any testing infrastructure to validate tracing spaces yet, so that doesn't matter so much. However, we could duplicate some of the existing "spawn" tests to go via the builder.

carllerche · 2021-06-22T17:02:15Z

tokio/src/task/builder.rs

+    ///
+    /// See [`task::spawn_local`][crate::task::spawn_local]
+    /// for more details
+    #[cfg_attr(tokio_track_caller, track_caller)]


For the caller location to be tracked, do we need to call Location::caller() in the method proper or is the location passed to inner calls?

My read of this is that it just makes the annotated function "transparent" to the walked Location, so inner calls don't report this function, but its caller. I'm new to this interface though — did I misunderstand it?

Not sure what you mean exactly, but here: https://play.rust-lang.org/?version=stable&mode=debug&edition=2018&gist=9fe91c5452a8add4f3b9a45e688ec3c7

Without #[track_caller] on fn two(), Location::caller() isn't what we want. If fn two() does have #[track_caller] then it is passed through one() and reports the line within fn main().

So it looks like you are correct.

carllerche · 2021-06-22T17:09:42Z

Once this lands, it would be nice to see it piped through the console. I think it would be fine to switch the console git repo to point to the latest tokio git.

jbr · 2021-06-22T17:20:00Z

Currently the console doesn't do anything special with task.name, but I have some locally stashed changes that adds a column on the task view

In general, I wasn't quite sure how to test this. Does CI run tracing tests? Would I register a subscriber, spawn a task, and then check that the right task.name was registered?

Another note: I wasn't sure how to handle tracing spawn_blocking, since task::spawn_blocking hasn't been instrumented yet, but it didn't seem strictly necessary for this PR. So as of this PR: Builder::new().spawn_blocking(||) is instrumented but task::spawn_blocking(||) isn't

hawkw · 2021-06-22T17:53:32Z

Another note: I wasn't sure how to handle tracing spawn_blocking, since task::spawn_blocking hasn't been instrumented yet, but it didn't seem strictly necessary for this PR. So as of this PR: Builder::new().spawn_blocking(||) is instrumented but task::spawn_blocking(||) isn't

spawn_blocking is instrumented on the Handle::spawn_blocking function, which task::spawn_blocking calls internally:

tokio/tokio/src/runtime/handle.rs

Lines 179 to 200 in e7d74b3

    
           #[cfg(all(tokio_unstable, feature = "tracing"))] 
        
           let fut = { 
        
               use tracing::Instrument; 
        
               #[cfg(tokio_track_caller)] 
        
               let location = std::panic::Location::caller(); 
        
               #[cfg(tokio_track_caller)] 
        
               let span = tracing::trace_span!( 
        
                   target: "tokio::task", 
        
                   "task", 
        
                   kind = %"blocking", 
        
                   function = %std::any::type_name::<F>(), 
        
                   spawn.location = %format_args!("{}:{}:{}", location.file(), location.line(), location.column()), 
        
               ); 
        
               #[cfg(not(tokio_track_caller))] 
        
               let span = tracing::trace_span!( 
        
                   target: "tokio::task", 
        
                   "task", 
        
                   kind = %"blocking", 
        
                   function = %std::any::type_name::<F>(), 
        
               ); 
        
               fut.instrument(span) 
        
           };

So, AFAICT, I think using the builder will currently wrap spawn_blocking calls with a duplicate span, since it calls runtime::spawn_blocking, which calls Handle::spawn_blocking, which also adds a span. I think we need to fix that by adding a spawn_blocking_inner and threading the task name through to that, just like we do for the other spawn functions, rather than constructing the span in Builder::spawn_blocking.

hawkw · 2021-06-22T17:55:09Z

In general, I wasn't quite sure how to test this. Does CI run tracing tests? Would I register a subscriber, spawn a task, and then check that the right task.name was registered?

I wouldn't worry too much about writing tests for this; you're right that we don't currently have any way of writing tests for trace output, and I'm not sure if it's really worth spending a lot of time on. Instead, I would just run some of the examples with RUSTFLAGS="--cfg tokio_unstable" and tracing_subscriber::fmt added, and confirm manually that the logged traces look correct.

hawkw

overall, this definitely looks like the right direction to go in --- i think this is close to ready! the main things that i noticed are

i think using the builder's spawn_blocking will currently produce duplicate spans --- i left a comment explaining that in more detail
it would be nice to have a way to spawn named tasks using a Handle. i left a comment on that as well.

tokio/src/task/builder.rs

carllerche · 2021-06-25T20:17:43Z

tokio/src/runtime/handle.rs

                function = %std::any::type_name::<F>(),
            );
            fut.instrument(span)
        };
+
+        #[cfg(not(all(tokio_unstable, feature = "tracing")))]
+        let _ = name;


carllerche

Anyway, this looks good to me. Because it is an unstable API, I won't block on a test.

hawkw

looks good to me!

davidbarsky · 2021-06-26T19:31:59Z

Running CI since it needed permissions to do so.

Darksonn · 2021-06-28T08:07:28Z

tokio/src/task/builder.rs

+#[derive(Default, Debug)]
+pub struct Builder<'a> {
+    name: Option<&'a str>,
+}
+
+impl Builder<'_> {
+    /// Creates a new task builder.
+    pub fn new() -> Self {
+        Self::default()
+    }
+
+    /// Assigns a name to the task which will be spawned.
+    pub fn name<'b>(&self, name: &'b str) -> Builder<'b> {
+        Builder { name: Some(name) }
+    }


This seems dangerous. If we add another option that also has a lifetime in the future, then this signature will not work because that other option's lifetime will continue to be 'a, not 'b. To handle that, we would need two lifetime parameters, but afaik adding a new lifetime parameter is a breaking change.

Wouldn't adding a second lifetime to a public struct already be a breaking change?

Yes. My point is that you also can't reuse the same lifetime for both fields.

What other lifetime are we discussing here, and what is the proposed change? Only accepting &'static str (or Into<Cow<'static, str>> in order to not lose support for dynamic names, which we established we didn't want to enforce against)? I'm not sure what you're proposing

We couldn't add another lifetime once this is stable so I don't understand the concern. Are you proposing that we design for hypothetical future borrows to necessarily have the same lifetime as the str?

It's more that this introduces a convention for having borrowed options for the builder. If we add any other string arguments, then we would be in trouble if the convention is to store them as a reference.

If the signature is changed to this, then reusing the 'a for all parameters that are by reference would not be a problem.

impl<'a> Builder<'a> { /// Assigns a name to the task which will be spawned. pub fn name(&self, name: &'a str) -> Builder<'a> { Builder { name: Some(name) } } }

[deleted comment]

Thanks for the suggestion, addressed in 183d556

Now that Tokio supports optional user-provided task names (in tokio-rs/tokio#3881), the task spans it generates may contain empty fields (if the user does not provide a name for a spawned task). However, the console always displays the `task.name` field, even when they are empty. This wastes space, and looks kind of ugly. This branch updates the console to skip displaying fields whose value is the empty string. ### Before: ![image](https://user-images.githubusercontent.com/2796466/128227118-7ee3b4d7-634f-410f-a1d0-4e5afd423566.png) ### After: ![image](https://user-images.githubusercontent.com/2796466/128227203-248bd059-839a-4254-8470-2761f726c885.png) Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Depends on #81 (since it touches the same code and would cause merge conflicts). * feat(console): don't display fields with "" values Now that Tokio supports optional user-provided task names (in tokio-rs/tokio#3881), the task spans it generates may contain empty fields (if the user does not provide a name for a spawned task). However, the console always displays the `task.name` field, even when they are empty. This wastes space, and looks kind of ugly. This branch updates the console to skip displaying fields whose value is the empty string. ### Before: ![image](https://user-images.githubusercontent.com/2796466/128227118-7ee3b4d7-634f-410f-a1d0-4e5afd423566.png) ### After: ![image](https://user-images.githubusercontent.com/2796466/128227203-248bd059-839a-4254-8470-2761f726c885.png) Signed-off-by: Eliza Weisman <eliza@buoyant.io> * refac(console): factor out field from pb conversion This factors out the protobuf `Field` -> internal `Field` conversion into a method, and cleans it up a bit. No functional change, except that we now take the proto `Field` type by value, so we don't have to clone strings out of it like we did previously (due to taking it by reference). I also added the metadata ID to the `Metadata` type, so that we can continue asserting that the metadata's ID matches the expected one for the field, without having to pass that in separately. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

PR #3881 factored out the spawning of local tasks on a `LocalSet` into a function `spawn_local_inner`, so that the implementation could be shared with the `task::Builder` API. But, that PR neglected to add a `#[track_caller]` attribute to `spawn_local_inner`, so the `tracing` spans for local tasks are all generated with `spawn_local_inner` as their spawn location, rather than forwarding the actual spawn location from the calling function. This causes pretty useless results when using `tokio-console` with code that spawns a number of local tasks, such as Actix (https://old.reddit.com/r/rust/comments/snt5fq/can_tokioconsole_profile_actixrt/) This commit fixes the issue by adding the missing `#[track_caller]` attribute.

PR #3881 factored out the spawning of local tasks on a `LocalSet` into a function `spawn_local_inner`, so that the implementation could be shared with the `task::Builder` API. But, that PR neglected to add a `#[track_caller]` attribute to `spawn_local_inner`, so the `tracing` spans for local tasks are all generated with `spawn_local_inner` as their spawn location, rather than forwarding the actual spawn location from the calling function. This causes pretty useless results when using `tokio-console` with code that spawns a number of local tasks, such as Actix (https://reddit.com/r/rust/comments/snt5fq/can_tokioconsole_profile_actixrt/) This commit fixes the issue by adding the missing `#[track_caller]` attribute.

initial sketch of tokio::task::Builder

fa87406

jbr mentioned this pull request Jun 21, 2021

a sketch for how task naming might work for tracing #3871

Closed

carllerche reviewed Jun 22, 2021

View reviewed changes

hawkw reviewed Jun 22, 2021

View reviewed changes

jbr added 2 commits June 22, 2021 13:38

don't double-instrument spawn_blocking tasks

45b0f78

silence warning about unused name

ed30870

hawkw reviewed Jun 22, 2021

View reviewed changes

tokio/src/task/builder.rs Outdated Show resolved Hide resolved

remove dynamic content from example

ede01e3

jbr marked this pull request as ready for review June 24, 2021 23:42

clippy

d158451

jbr changed the title ~~initial sketch of tokio::task::Builder~~ tracing: add tokio::task::Builder Jun 24, 2021

carllerche reviewed Jun 25, 2021

View reviewed changes

hawkw approved these changes Jun 25, 2021

View reviewed changes

Darksonn added A-tokio Area: The main tokio crate M-task Module: tokio/task M-tracing Tracing support in Tokio labels Jun 28, 2021

Darksonn reviewed Jun 28, 2021

View reviewed changes

jbr added 2 commits June 28, 2021 12:21

address lifetime issue with name

183d556

add task builder tests

3ae3808

carllerche merged commit 8fa29cb into tokio-rs:master Jun 29, 2021

jbr deleted the spawn_builder branch June 29, 2021 18:07

Darksonn mentioned this pull request Jul 2, 2021

Prepare Tokio v1.8.0 #3912

Merged

migrax mentioned this pull request Jul 6, 2021

Bump tokio from 1.5.0 to 1.8.0 RedesdeOrdenadores/ShuffleRouter#38

Closed

softdevca mentioned this pull request Jul 7, 2021

Bump tokio from 1.7.1 to 1.8.1 softdevca/mootranscode#24

Merged

hawkw mentioned this pull request Aug 4, 2021

stop rendering empty fields, refactor field conversion tokio-rs/console#83

Merged

seanmonstar mentioned this pull request Sep 16, 2021

meta: Task Builder stabilization #4114

Open

2 tasks

hawkw mentioned this pull request Feb 9, 2022

task: fix missing #[track_caller] in spawn_local #4483

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tracing: add tokio::task::Builder #3881

tracing: add tokio::task::Builder #3881

jbr commented Jun 21, 2021

carllerche left a comment

carllerche Jun 22, 2021

jbr Jun 22, 2021 •

edited

carllerche Jun 22, 2021

carllerche Jun 22, 2021

carllerche commented Jun 22, 2021

jbr commented Jun 22, 2021

hawkw commented Jun 22, 2021

hawkw commented Jun 22, 2021

hawkw left a comment

carllerche Jun 25, 2021

carllerche left a comment

hawkw left a comment

davidbarsky commented Jun 26, 2021

Darksonn Jun 28, 2021

jbr Jun 28, 2021

Darksonn Jun 28, 2021

jbr Jun 28, 2021

jbr Jun 28, 2021 •

edited

Darksonn Jun 28, 2021

Darksonn Jun 28, 2021 •

edited

jbr Jun 28, 2021 •

edited

jbr Jun 28, 2021

tracing: add tokio::task::Builder #3881

tracing: add tokio::task::Builder #3881

Conversation

jbr commented Jun 21, 2021

Motivation

Solution

carllerche left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbr Jun 22, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllerche commented Jun 22, 2021

jbr commented Jun 22, 2021

hawkw commented Jun 22, 2021

hawkw commented Jun 22, 2021

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllerche left a comment

Choose a reason for hiding this comment

hawkw left a comment

Choose a reason for hiding this comment

davidbarsky commented Jun 26, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbr Jun 28, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Darksonn Jun 28, 2021 • edited

Choose a reason for hiding this comment

jbr Jun 28, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbr Jun 22, 2021 •

edited

jbr Jun 28, 2021 •

edited

Darksonn Jun 28, 2021 •

edited

jbr Jun 28, 2021 •

edited