feat(lib): Move from log to tracing in a backwards-compatible way
#2204
Conversation
| @@ -29,7 +29,7 @@ http-body = "0.3.1" | |||
| httparse = "1.0" | |||
| h2 = "0.2.2" | |||
| itoa = "0.4.1" | |||
| log = "0.4" | |||
| tracing = { version = "0.1", default-features = false, features = ["log", "std"] } | |||
There was a problem hiding this comment.
It would be good to expose the log feature optionally (though it should default to on so we don't break existing code that expects log records emitted by Hyper), so that tracing users who don't need log can disable it. Otherwise, depending on Hyper will always enable the log feature, even when users don't need it.
There was a problem hiding this comment.
hmm, solid point. will fix.
There was a problem hiding this comment.
Something to consider, though, is that if the logging enabled becomes an optional feature, then those who have default-features = false will have the logs disabled when they upgrade.
(I find cargo's default-features to be annoying in this regard, but what we gonna do.)
There was a problem hiding this comment.
Darn, that's an annoying thing. Are you okay with breaking those people in a minor release? Or more generally, how should this be handled?
Cargo.toml
Outdated
| @@ -70,6 +71,10 @@ tcp = [ | |||
| "tokio/tcp", | |||
| "tokio/time", | |||
| ] | |||
| log = [ | |||
| "tracing/log", | |||
| "tracing/std" | |||
There was a problem hiding this comment.
i suspect that tracing/std can always be on, but i don't actually think hyper needs any of the functionality behind that feature, so we really don't care if it's enabled or not
There was a problem hiding this comment.
I think it might be off is default-features is set to false; I suspect that pulling in syn + quote via instrument might be a bigger issue for hyper. In either case, I don't care too much.
|
As an update, I'm personally fine with proceeding here, as long as we don't break people who already have Is having the |
In my book, it's totally fine to always the As long as Hyper doesn't also enable the The only added cost of the |
|
Personally, it’s not a dealbreaker. Most users of |
|
I've rebased and explicitly opted-in into EDIT: I think that pulling in |
|
Let me just confirm here, this is the dependency line that should be merged? tracing = { version = "0.1", default-features = false, features = ["log", "std"] }The default-features should be disabled, and |
Yup! Conversation I had with Eliza: Sorry about the back and forth! |
|
Thanks David! |
|
Yay! 🙌 |
## 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. [`tracing` crate]: https://github.com/tokio-rs/tracing [`hyper`]: hyperium/hyper#2204 [`h2`]: hyperium/h2#475 [`tonic`]: https://github.com/hyperium/tonic/blob/570c606397e47406ec148fe1763586e87a8f5298/tonic/Cargo.toml#L48 [other]: rust-lang/chalk#525 [parts]: rust-lang/compiler-team#331 ## Solution This PR is an MVP for instrumenting Tokio with `tracing` spans. When the "tracing" optional dependency is enabled, every spawned future will be instrumented with a `tracing` span. 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 `spawn`ed 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 `spawn`ed 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, a 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` `Layer`s to collect and display Tokio-specific data from these traces - using `track_caller` (when it's stable) to record _where_ a task was `spawn`ed from However, this is intended as an MVP to get us started on that path. Signed-off-by: Eliza Weisman <eliza@buoyant.io>
…hyperium#2204) I've moved Hyper from `log` to `tracing`. Existing `log`-based users shouldn't notice a difference, but `tracing` users will see higher performance when filtering data. This isn't the _end_ of the `tracing` integration that can happen in `Hyper` (e.g., Hyper can start using spans, typed fields, etc.), but _something_ is better than nothing. I'd rather address those points, including examples, in followups. I've attached a screenshot of the `hello` example working, but the logged information is pulled from `tracing`, not `log`. <img width="514" alt="Screen Shot 2020-05-16 at 1 23 19 PM" src="https://user-images.githubusercontent.com/2067774/82126298-d8103800-9779-11ea-8f0b-57c632c684d6.png">
I've moved Hyper from
logtotracing. Existinglog-based users shouldn't notice a difference, buttracingusers will see higher performance when filtering data. This isn't the end of thetracingintegration that can happen inHyper(e.g., Hyper can start using spans, typed fields, etc.), but something is better than nothing. I'd rather address those points, including examples, in followups.I've attached a screenshot of the
helloexample working, but the logged information is pulled fromtracing, notlog.