task: add Tracing instrumentation to spawned tasks

[hawkw]

Motivation

When debugging asynchronous systems, it can be very valuable to inspect
what tasks are currently active (see #2510). The tracing crate and
related libraries provide an interface for Rust libraries and
applications to emit and consume structured, contextual, and async-aware
diagnostic information. Because this diagnostic information is
structured and machine-readable, it is a better fit for the
task-tracking use case than textual logging — tracing spans can be
consumed to generate metrics ranging from a simple counter of active
tasks to histograms of poll durations, idle durations, and total task
lifetimes. This information is potentially valuable to both Tokio users
and to maintainers.

Additionally, tracing is maintained by the Tokio project and is
becoming widely adopted by other libraries in the "Tokio stack", such as
hyper, h2, and tonic and in other parts of the broader Rust
ecosystem. Therefore, it is suitable for use in Tokio itself.

Solution

This PR is an MVP for instrumenting Tokio with tracing spans. When the
"tracing" feature flag and the "tokio_unstable" cfg are both enabled,
every spawned future will be instrumented with a tracing span. If both
the cfg flag and the "tracing" feature flag are not set, tokio will
not depend on tracing, and no spans will be generated.

The generated spans are at the TRACE verbosity level, and have the
target "tokio::task", which may be used by consumers to filter whether
they should be recorded. They include fields for the type name of the
spawned future and for what kind of task the span corresponds to (a
standard spawned task, a local task spawned by spawn_local, or a
blocking task spawned by spawn_blocking). Because tracing has
separate concepts of "opening/closing" and "entering/exiting" a span, we
enter these spans every time the spawned task is polled. This allows
collecting data such as:

• the total lifetime of the task from spawn to drop
• the number of times the task was polled before it completed
• the duration of each individual time that the span was polled (and
  therefore, aggregated metrics like histograms or averages of poll
  durations)
• the total time a span was actively being polled, and the total time
  it was alive but not being polled
• the time between when the task was spawned and the first poll

As an example, here is the output of a version of the chat example
instrumented with tracing:

And, with multiple connections actually sending messages:

I haven't added any tracing spans in the example, only converted the
existing println!s to tracing::info and tracing::error for
consistency. The span durations in the above output are generated by
tracing-subscriber. Of course, Tokio-specific subscriber could
generate even more detailed statistics, but that's follow-up work once
basic tracing support has been added.

Note that the Instrumented type from tracing-futures, which attaches
a tracing span to a future, was reimplemented inside of Tokio to avoid
a dependency on that crate. tracing-futures has a feature flag that
enables an optional dependency on Tokio, and I believe that if another
crate in a dependency graph enables that feature while Tokio's tracing
support is also enabled, it would create a circular dependency that
Cargo wouldn't be able to handle. Also, it avoids a dependency for a
very small amount of code that is unlikely to ever change.

There is, of course, room for plenty of future work here. This might
include:

• instrumenting other parts of tokio, such as I/O resources and
  channels (possibly via waker instrumentation)
• instrumenting the threadpool so that the state of worker threads
  can be inspected
• writing tracing-subscriber Layers to collect and display
  Tokio-specific data from these traces
• using track_caller (when it's stable) to record where a task
  was spawned from
• moving the feature out of "tokio_unstable"

However, this is intended as an MVP to get us started on that path.

Signed-off-by: Eliza Weisman eliza@buoyant.io

[davidbarsky]

We talked about this, but I don't think tracing merits being placed behind the tokio_unstable unstable flag. @carllerche will need to weigh in on this, but unlike the CancelationToken, changes to the tracing output aren't what the Tokio project has historically considered to be a "breaking change". An off-by-default (e.g., excluded from full) feature flag seems like a reasonable default.

[hawkw]

I think at one point, @carllerche suggested that any dependency on a pre-1.0 crate should require the tokio_unstable flag...but, in this case, we aren't exposing anything from tracing in Tokio's public APIs. AFAICT, it shouldn't be possible for the tracing dependency to cause any compile time breakage --- the worst failure mode, if there is eventually a breaking change to the tracing-core crate that we can't work around, is that the tracing diagnostics might silently fail to be collected.

IMO, you're right, and an off-by-default optional dep should be fine. That would be pretty similar to what we do for parking_lot, which is also pre-1.0 (and churns versions somewhat frequently!), since it's also not exposed publicly. Of course, if we were to expose tracing types (such as Span or Dispatch) in a public API later on, those APIs should require the unstable flag.

With all of that said: I made the more conservative choice of opening this PR with the tokio_unstable flag required, because I want to bias towards getting this merged sooner rather than later, and continuing to iterate once it merges. We can always remove the flag in a follow-up, but it's harder to add if these changes ship in a published release...

[jonhoo]

This is really cool, I'm excited!

I'll add to the future that from experience it'd also be really handy to have events for when a resource is notified.

[hawkw]

I'll add to the future that from experience it'd also be really handy to have events for when a resource is notified.

@jonhoo Yup, the next major thing to do in Tokio itself is probably going to be adding instrumentation to Wakers, IMO. That should let us track when a task expresses interest in a resource, and when a resource notifies a task.

[carllerche]

Looks great. We can remove the unstable flag.