Introduce Tracing into Chalk (Third Time's the Charm) #525
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Co-authored-by: nolanderc <christofer.nolander@gmail.com>
|
Awesome @nathanwhit! Can you also add a bit in the book of how to use this? (i.e. if I want to look at the debug output, what would I use instead of |
jackh726
requested changes
Jun 15, 2020
|
Applied your suggestions and added some documentation! As for debugging the rustc integration, all you should have to do is add some code to register a "subscriber" to collect the tracing data, like this. You would probably want to place it at an entry point to chalk (and from that point onward logs will be collected), but you could add it anywhere really, as long as it gets executed. |
|
Would that, theoretically, capture other crates' tracing calls? I'll have to test this out, but I overall feel pretty good about landing this. @nikomatsakis what do you think? I would rather land this sooner rather than later, if everything looks good, so it doesn't get stale (again). |
|
It could potentially capture other crates tracing calls, but only if you register the tracing subscriber as the global default (which is the case for the code I linked). If instead you set a subscriber as a local default using this method or this one, like in this snippet here, then the subscriber would only capture tracing calls that are made transitively within that scope (if that makes sense). |
nikomatsakis
approved these changes
Jun 16, 2020
|
I approve to land, yes. |
|
Let's try it out |
hawkw
added a commit
to tokio-rs/tokio
that referenced
this pull request
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
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
This PR is a continuation of #409. The changes made here are largely the same as that PR, but rewritten on top of the current
masterand with a few minor adjustments to the macros. I also opted to take the suggestion in this comment and makechalk-irnot depend on tracing to potentially easerustcintegration.