Skip to content

feat(lib): switch from log to tracing #475

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
merged 3 commits into from
Jul 7, 2020
Merged

feat(lib): switch from log to tracing #475

merged 3 commits into from
Jul 7, 2020

Conversation

davidbarsky
Copy link
Contributor

Like hyperium/hyper#2204, this PR switches from log to tracing. It's a slightly noisy diff because I didn't want to make a big change to h2 in this PR.

seanmonstar
seanmonstar approved these changes Jul 7, 2020
View reviewed changes
Copy link
Member

@seanmonstar seanmonstar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me. I fixed the check failure on master already, if you want to rebase.

hawkw
hawkw reviewed Jul 7, 2020
View reviewed changes
David Barsky and others added 2 commits July 7, 2020 13:27
@davidbarsky davidbarsky requested a review from hawkw July 7, 2020 17:46
@davidbarsky
Copy link
Contributor Author

I've rebased against mainline and included @hawkw's commit.

@seanmonstar
Copy link
Member

Hm, looks like CI is failing with -Zminimal-versions. Do we need to pin to a later version of tracing?

@davidbarsky
Copy link
Contributor Author

Hm, looks like CI is failing with -Zminimal-versions. Do we need to pin to a later version of tracing?

Possibly. I'm thinking that we select at least the latest stable tracing release?

hawkw
hawkw approved these changes Jul 7, 2020
View reviewed changes
Copy link
Collaborator

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, modulo the -Zminimal-versions thing ... i don't actually know what that does!

@seanmonstar
Copy link
Member

It's forcing cargo to download the minimum versions allowed by the Cargo.toml's involved. It seems it's complaining that tracing-attributes doesn't compile on Rust 1.39, but I thought we disabled it. Perhaps the minimum version here still included it?

@hawkw
Copy link
Collaborator

hawkw commented Jul 7, 2020

@seanmonstar aah, I see --- tracing-attributes was made an optional dependency in tracing 0.1.13, before then it was always downloaded even with default-features = false (yes, this was an unintentional breaking change for default-features = false users, it's one of my bigger regrets). We probably want to depend on 0.1.13 and later.

Side note, we should probably add minimal versions checks for tracing CI (cc @davidbarsky).

@seanmonstar
Copy link
Member

Ah, then this CI failure is kind of dumb. We don't really want to require tracing >0.1.13 for anything inside h2, but we have to in order to make the Rust 1.39 + minimal-versions check pass... Oh well, probably not bad to require a newer version.

@seanmonstar seanmonstar merged commit d3b9f1e into hyperium:master Jul 7, 2020
@hawkw hawkw mentioned this pull request Jul 11, 2020
Merged
hawkw added a commit to tokio-rs/tokio that referenced this pull request Jul 13, 2020
@hawkw
task: add Tracing instrumentation to spawned tasks (#2655)
b9e3d2e 
## 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`:
![image](https://user-images.githubusercontent.com/2796466/87231927-e50f6900-c36f-11ea-8a90-6da9b93b9601.png)
And, with multiple connections actually sending messages:
![trace_example_1](https://user-images.githubusercontent.com/2796466/87231876-8d70fd80-c36f-11ea-91f1-0ad1a5b3112f.png)


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 <[email protected]>
This was referenced Jul 16, 2020
Merged
Merged
@davidbarsky davidbarsky mentioned this pull request Jul 20, 2020
Closed
BenxiangGe pushed a commit to BenxiangGe/h2 that referenced this pull request Jul 26, 2021
@davidbarsky
feat(lib): switch from log to tracing (hyperium#475)
92abdb7
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@seanmonstar seanmonstar seanmonstar approved these changes

@hawkw hawkw hawkw approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@davidbarsky @seanmonstar @hawkw