Use tracing instead of log
#331
Labels
major-change
A proposal to make a major change to rustc
major-change-accepted
A major change proposal that was accepted
T-compiler
Add this label so rfcbot knows to poll the compiler team
Comments
oli-obk
added
T-compiler
|
This issue is not meant to be used for technical discussion. There is a Zulip stream for that. Use this issue to leave procedural comments, such as volunteering to review, indicating that you second the proposal (or third, etc), or raising a concern that you would like to be addressed. |
|
@rustbot second |
rustbot
added
the
final-comment-period
|
👋 I'd be happy to help out with this, either in the form of answering questions and giving advice, or in the form of actually sending PRs. :) Note that because |
hawkw
added a commit
to tokio-rs/tokio
that referenced
this issue
Jul 13, 2020
## 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>
This was referenced Jul 16, 2020
spastorino
added
major-change-accepted
bors
added a commit
to rust-lang-ci/rust
that referenced
this issue
Aug 1, 2020
Move from `log` to `tracing` The only visible change is that we now get timestamps in our logs: ``` Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: skipping replace of Rvalue::Use(const () because it is already a const Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: propagated into _2 Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: visit_constant: const () ``` This PR was explicitly designed to be as low-impact as possible. We can now move to using the name `tracing` insteads of `log` on a crate-by-crate basis and use any of the other tracing features where desirable. As far as I can tell this will allow tools to seamlessly keep working (since they are using `rustc_driver::init_log...`). This is the first half of step 1 of the accepted `tracing` MCP (rust-lang/compiler-team#331)
Merged
11 tasks
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Proposal
logcrate withtracing(there are verbatim replacements for the logging macros, so no code changes){:?}in tracing macro invocations with?valueinfront of the format stringspan!invocations to give us hirerarchical logsMentors or Reviewers
Process
The main points of the Major Change Process is as follows:
@rustbot second.-C flag, then full team check-off is required.@rfcbot fcp mergeon either the MCP or the PR.You can read more about Major Change Proposals on forge.
Comments
This issue is not meant to be used for technical discussion. There is a Zulip stream for that. Use this issue to leave procedural comments, such as volunteering to review, indicating that you second the proposal (or third, etc), or raising a concern that you would like to be addressed.
The text was updated successfully, but these errors were encountered: