tracing: add resource instrumentation using declarative macros

[zaharidichev]

This PR adds macros that help instrument a resource
and its respective ops. It is an alternative version of #3893

[zaharidichev]

I am not entirely sure how I can get around

error[E0432]: unresolved import `file::File`
  --> tokio/tests/fs_file_mocked.rs:29:5
   |
29 | use file::File;
   |     ^^^^^^^^^^ no `File` in `file`

error: cannot find macro `new_instrumented_resource` in this scope
   --> tokio/tests/../src/fs/file.rs:212:9
    |
212 |         new_instrumented_resource! {
    |         ^^^^^^^^^^^^^^^^^^^^^^^^^

error: cannot find macro `instrument_resource` in this scope
  --> tokio/tests/../src/fs/file.rs:22:1
   |
22 | instrument_resource! {
   | ^^^^^^^^^^^^^^^^^^^

Seems this is triggered by the fact that test load the file module and the macro cannot be resolved...

// Load source
#[allow(warnings)]
#[path = "../src/fs/file.rs"]
mod file;
use file::File;

[seanmonstar]

LGTM!

[hawkw]

nit, take it or leave it: why match the resource kind as an identifier and then stringify it? it might be simpler to just have the macro take a string literal...unless we care about ensuring that the kind is a valid Rust identifier?

[carllerche]

I'm OK merging this as is to keep moving, but I don't think that this is the right way to instrument poll_read and poll_write functions. We need a tracking issue in the Tokio repo tracking the stabilization of instrumentation and we should have an open question around how to instrument poll_read and poll_write.

I'm leaning towards @seanmonstar's idea of just creating a span per poll_read / poll_write call. We can track it as that. Then, at a higher level, we should track the actual async operation. Eg. AsyncReadExt::read should have a span that instruments the entire read op.

Additionally, do we instrument if an operation (e.g. sleep) completes successfully or is cancelled?

[zaharidichev]

@carllerche I see, not sure if it is worth merging if that does not seem the correct approach. So what do we precisely need/want? I also feel it makes much more sense to track the async operation from first poll to returning result or erroring. I am not sure what having a new span per poll_* invocation gives us much. So a few questions.

1. Can the resource itself have a span per operation that lives for the duration of the async op and gets dropped once we get Poll::Ready/error?
2. Can that cause problems if there are concurrent callers to poll methods?
3. If we do that, can we get away with not instrumenting the extension traits?
4. How would we want to instrument additional information about resources (how many bytes have been read, an operation was cancelled, etc, a timer was reset)?
5. Does it make sense to try and pack all of that in macros or is it better to avoid that to begin with

[carllerche]

@carllerche I see, not sure if it is worth merging if that does not seem the correct approach. So what do we precisely need/want?

Well, I don't think we know exactly what we want yet and IMO there is value in getting some data to show up in the console sooner than later. This is all flagged as experimental so we can figure it out as we go. That is my thinking, I'll defer to @seanmonstar / @hawkw on the call.

I also feel it makes much more sense to track the async operation from first poll to returning result or erroring. I am not sure what having a new span per poll_* invocation gives us much.

Well, the reason I moved away from this is that it isn't a perfect heuristic. You could imagine doing a poll_read in a select! then the branch loses, the task does other work, then comes back around and calls poll_read again. In this case, span shouldn't be from the first poll_read to it returning Ready. The fact is, at the poll_read level, we don't really know when the async op starts / stops, so I don't think we should guess. We have higher level async fns like AsyncReadExt::read that do give us a clear start / stop point, so that is where we should embed the span IMO.

So a few questions.

1. Can the resource itself have a span per operation that lives for the duration of the async op and gets dropped once we get Poll::Ready/error?

I am not sure, but I can't think of an error-proof way to do this.

2. Can that cause problems if there are concurrent callers to poll methods?

In theory, there should be no concurrent calls to poll_* fns.

3. If we do that, can we get away with not instrumenting the extension traits?

We should instrument the extension traits. One option would be to track poll_* instrumentation separately in a way that we could filter out in the console.

4. How would we want to instrument additional information about resources (how many bytes have been read, an operation was cancelled, etc, a timer was reset)?

Maybe @hawkw has a thought here. We may need to emit special events within the span.

5. Does it make sense to try and pack all of that in macros or is it better to avoid that to begin with

Personally, I would avoid macros initially until we have figured out the pattern.

All that said, again, I think it is fine to just move forward and tweak as we go. We want to start seeing resource instrumentation in console.

[seanmonstar]

Looks like all the feedback has been addressed, anything keeping us from merging?

[zaharidichev]

@seanmonstar I do not think so. Unless there are objections, this PR is in line with the RFC. Actually, I will try and get this view put together before we merge this. I think that this will inform any changes we need to make here

[zaharidichev]

Closing in favour of #4072