Skip to content
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.

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

tracing: replace future names with spawn locations in task spans #3074

Merged
merged 10 commits into from Nov 1, 2020

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Oct 29, 2020

Motivation

Currently, the per-task tracing spans generated by tokio's tracing
feature flag include the std::any::type_name of the future that was
spawned. When future combinators and/or libraries like Tower are in use,
these future names can get quite long. Furthermore, when formatting
the tracing spans with their parent spans as context, any other task
spans in the span context where the future was spawned from can also
include extremely long future names.

In some cases, this can result in extremely high memory use just to
store the future names. For example, in Linkerd, when we enable
tokio=trace to enable the task spans, there's a spawned task whose
future name is 232990 characters long. A proxy with only 14 spawned
tasks generates a task list that's over 690 KB. Enabling task spans
under load results in the process getting OOM killed very quickly.

Solution

This branch removes future type names from the spans generated by
spawn. As a replacement, to allow identifying which spawn call a
span corresponds to, the task span now contains the source code location
where spawn was called, when the compiler supports the
#[track_caller] attribute. Since track_caller was stabilized in Rust
1.46.0, and our minimum supported Rust version is 1.45.0, we can't
assume that #[track_caller] is always available. Instead, we have a
RUSTFLAGS cfg, tokio_track_caller, that guards whether or not we use
it. I've also added a build.rs that detects the compiler minor
version, and sets the cfg flag automatically if the current compiler
version is >= 1.46. This means users shouldn't have to enable
tokio_track_caller manually.

Here's the trace output from the chat example, before this change:
Screenshot_20201030_110157
...and after:
Screenshot_20201030_110303

Closes #3073

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
whoops, i didn't realize i had a vscode plugin installed that does that.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw requested review from carllerche and a team October 29, 2020 20:54
tokio/build.rs Outdated Show resolved Hide resolved
tokio/build.rs Outdated Show resolved Hide resolved
tokio/build.rs Outdated Show resolved Hide resolved
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@@ -122,6 +122,7 @@ cfg_rt! {
/// ```text
/// error[E0391]: cycle detected when processing `main`
/// ```
#[cfg_attr(tokio_track_caller, track_caller)]
Copy link
Member Author

Choose a reason for hiding this comment

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

Note that this enables track_caller on spawn even when it's not used by the "tracing" feature flag. I think this is actually a good thing, since it means the panic when spawn is called outside the runtime will have the callsite's location, which may make debugging a little easier for users?

However, if folks prefer, I can change this to only enable track_caller when the cfg is set and the "tracing" feature flag is enabled.

target: "tokio::task",
"task",
%kind,
spawn.location = %format_args!("{}:{}:{}", location.file(), location.line(), location.column()),
Copy link
Member Author

Choose a reason for hiding this comment

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

spawn.location feels a little wordy but I couldn't think of something more descriptive off the top of my head. If folks have better ideas, let me know!

Copy link
Member Author

Choose a reason for hiding this comment

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

also, we could alternatively record the filename, line number, and column as separate fields on the task span, like

Suggested change
spawn.location = %format_args!("{}:{}:{}", location.file(), location.line(), location.column()),
spawn.file = %location.file(),
spawn.line = location.line(),
spawn.column = location.column(),

and rely on the tracing subscriber to format them nicely...but, this results in more verbose, harder to read output when the tracing subscriber that's in use isn't doing anything fancy, so I thought this was nicer.

@hawkw hawkw requested a review from taiki-e October 30, 2020 18:03
@taiki-e
Copy link
Member

taiki-e commented Oct 31, 2020

Probably MSRV will be increased in 1.0, so dependency on autocfg should be temporary.

However, futures-core may depend on autocfg in the future. (see rust-lang/futures-rs#2207 (comment) and rust-lang/futures-rs#1875 (comment))

@taiki-e taiki-e added the A-tokio Area: The main tokio crate label Oct 31, 2020
@hawkw hawkw merged commit fede3db into master Nov 1, 2020
@hawkw hawkw deleted the eliza/nice-trace branch November 1, 2020 18:48
Keruspe added a commit to Keruspe/tokio that referenced this pull request Nov 2, 2020
* master:
  tracing: replace future names with spawn locations in task spans (tokio-rs#3074)
  util: add back public poll_read_buf() function (tokio-rs#3079)
  net: add pid to tokio::net::unix::UCred (tokio-rs#2633)
  chore: prepare tokio-util v0.5.0 release (tokio-rs#3078)
hds added a commit that referenced this pull request Mar 22, 2023
In a previous PR (#4128), the `spawn.location` field on task spans was
structured into 3 separate fields for the `file`, `line`, and `col`.
There is a separately created span for blocking tasks which was missed.

This caused tasks created with `spawn_blocking` to appear in
`tokio-console` without a location, but with an additional "free form"
field containing the formatted source code location.

This change modifies this span to use the same format. The span creation
needs to be separate from the other task spans because it records the
function name. This information is useful in the `spawn_blocking` case,
but can be "catastrophically long" in the `async fn` case and was
removed in #3074.
hds added a commit that referenced this pull request Mar 22, 2023
In a previous PR (#4128), the `spawn.location` field on task spans was
structured into 3 separate fields for the `file`, `line`, and `col`.
There is a separately created span for blocking tasks which was missed.

This caused tasks created with `spawn_blocking` to appear in
`tokio-console` without a location, but with an additional "free form"
field containing the formatted source code location.

This change modifies this span to use the same format. The span creation
needs to be separate from the other task spans because it records the
function name. This information is useful in the `spawn_blocking` case,
but can be "catastrophically long" in the `async fn` case and was
removed in #3074.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-tokio Area: The main tokio crate
Projects
None yet
Development

Successfully merging this pull request may close these issues.

tracing: remove future names from task spans
3 participants