From fede3db76aef95c010c3e0c3da3b732380285097 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sun, 1 Nov 2020 10:48:44 -0800 Subject: tracing: replace future names with spawn locations in task spans (#3074) ## 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](https://user-images.githubusercontent.com/2796466/97741071-6d408800-1a9f-11eb-9ed6-b25e72f58c7b.png) ...and after: ![Screenshot_20201030_110303](https://user-images.githubusercontent.com/2796466/97741112-7e899480-1a9f-11eb-9197-c5a3f9ea1c05.png) Closes #3073 Signed-off-by: Eliza Weisman --- tokio/Cargo.toml | 7 +++++-- tokio/build.rs | 22 +++++++++++++++++++++ tokio/src/runtime/handle.rs | 15 +++++++++++++- tokio/src/runtime/mod.rs | 4 ++++ tokio/src/task/blocking.rs | 1 + tokio/src/task/local.rs | 2 ++ tokio/src/task/spawn.rs | 1 + tokio/src/util/trace.rs | 48 +++++++++++++-------------------------------- 8 files changed, 63 insertions(+), 37 deletions(-) create mode 100644 tokio/build.rs diff --git a/tokio/Cargo.toml b/tokio/Cargo.toml index 6c5de90d..c4825c20 100644 --- a/tokio/Cargo.toml +++ b/tokio/Cargo.toml @@ -102,7 +102,7 @@ mio = { version = "0.7.3", optional = true } num_cpus = { version = "1.8.0", optional = true } parking_lot = { version = "0.11.0", optional = true } # Not in full slab = { version = "0.4.1", optional = true } -tracing = { version = "0.1.16", default-features = false, features = ["std"], optional = true } # Not in full +tracing = { version = "0.1.21", default-features = false, features = ["std"], optional = true } # Not in full [target.'cfg(unix)'.dependencies] libc = { version = "0.2.42", optional = true } @@ -126,9 +126,12 @@ tempfile = "3.1.0" [target.'cfg(loom)'.dev-dependencies] loom = { version = "0.3.5", features = ["futures", "checkpoint"] } +[build-dependencies] +autocfg = "1" # Needed for conditionally enabling `track-caller` + [package.metadata.docs.rs] all-features = true rustdoc-args = ["--cfg", "docsrs"] [package.metadata.playground] -features = ["full"] +features = ["full"] \ No newline at end of file diff --git a/tokio/build.rs b/tokio/build.rs new file mode 100644 index 00000000..fe5c8300 --- /dev/null +++ b/tokio/build.rs @@ -0,0 +1,22 @@ +use autocfg::AutoCfg; + +fn main() { + match AutoCfg::new() { + Ok(ac) => { + // The #[track_caller] attribute was stabilized in rustc 1.46.0. + if ac.probe_rustc_version(1, 46) { + autocfg::emit("tokio_track_caller") + } + } + + Err(e) => { + // If we couldn't detect the compiler version and features, just + // print a warning. This isn't a fatal error: we can still build + // Tokio, we just can't enable cfgs automatically. + println!( + "cargo:warning=tokio: failed to detect compiler features: {}", + e + ); + } + } +} diff --git a/tokio/src/runtime/handle.rs b/tokio/src/runtime/handle.rs index b1e8d8f1..c9ffd5cd 100644 --- a/tokio/src/runtime/handle.rs +++ b/tokio/src/runtime/handle.rs @@ -39,13 +39,26 @@ impl Handle { // context::enter(self.clone(), f) // } - /// Run the provided function on an executor dedicated to blocking operations. + /// Run the provided function on an executor dedicated to blocking + /// operations. + #[cfg_attr(tokio_track_caller, track_caller)] pub(crate) fn spawn_blocking(&self, func: F) -> JoinHandle where F: FnOnce() -> R + Send + 'static, { #[cfg(feature = "tracing")] let func = { + #[cfg(tokio_track_caller)] + let location = std::panic::Location::caller(); + #[cfg(tokio_track_caller)] + let span = tracing::trace_span!( + target: "tokio::task", + "task", + kind = %"blocking", + function = %std::any::type_name::(), + spawn.location = %format_args!("{}:{}:{}", location.file(), location.line(), location.column()), + ); + #[cfg(not(tokio_track_caller))] let span = tracing::trace_span!( target: "tokio::task", "task", diff --git a/tokio/src/runtime/mod.rs b/tokio/src/runtime/mod.rs index 01788b9c..c76f5cf6 100644 --- a/tokio/src/runtime/mod.rs +++ b/tokio/src/runtime/mod.rs @@ -357,11 +357,14 @@ cfg_rt! { /// }); /// # } /// ``` + #[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn(&self, future: F) -> JoinHandle where F: Future + Send + 'static, F::Output: Send + 'static, { + #[cfg(feature = "tracing")] + let future = crate::util::trace::task(future, "task"); match &self.kind { #[cfg(feature = "rt-multi-thread")] Kind::ThreadPool(exec) => exec.spawn(future), @@ -385,6 +388,7 @@ cfg_rt! { /// println!("now running on a worker thread"); /// }); /// # } + #[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn_blocking(&self, func: F) -> JoinHandle where F: FnOnce() -> R + Send + 'static, diff --git a/tokio/src/task/blocking.rs b/tokio/src/task/blocking.rs index fc6632be..36bc4579 100644 --- a/tokio/src/task/blocking.rs +++ b/tokio/src/task/blocking.rs @@ -104,6 +104,7 @@ cfg_rt_multi_thread! { /// # Ok(()) /// # } /// ``` +#[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn_blocking(f: F) -> JoinHandle where F: FnOnce() -> R + Send + 'static, diff --git a/tokio/src/task/local.rs b/tokio/src/task/local.rs index 5896126c..566b2f2d 100644 --- a/tokio/src/task/local.rs +++ b/tokio/src/task/local.rs @@ -190,6 +190,7 @@ cfg_rt! { /// }).await; /// } /// ``` + #[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn_local(future: F) -> JoinHandle where F: Future + 'static, @@ -273,6 +274,7 @@ impl LocalSet { /// } /// ``` /// [`spawn_local`]: fn@spawn_local + #[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn_local(&self, future: F) -> JoinHandle where F: Future + 'static, diff --git a/tokio/src/task/spawn.rs b/tokio/src/task/spawn.rs index 77acb579..a060852d 100644 --- a/tokio/src/task/spawn.rs +++ b/tokio/src/task/spawn.rs @@ -122,6 +122,7 @@ cfg_rt! { /// ```text /// error[E0391]: cycle detected when processing `main` /// ``` + #[cfg_attr(tokio_track_caller, track_caller)] pub fn spawn(task: T) -> JoinHandle where T: Future + Send + 'static, diff --git a/tokio/src/util/trace.rs b/tokio/src/util/trace.rs index 18956a36..96a9db91 100644 --- a/tokio/src/util/trace.rs +++ b/tokio/src/util/trace.rs @@ -1,47 +1,27 @@ cfg_trace! { cfg_rt! { - use std::future::Future; - use std::pin::Pin; - use std::task::{Context, Poll}; - use pin_project_lite::pin_project; - - use tracing::Span; - - pin_project! { - /// A future that has been instrumented with a `tracing` span. - #[derive(Debug, Clone)] - pub(crate) struct Instrumented { - #[pin] - inner: T, - span: Span, - } - } - - impl Future for Instrumented { - type Output = T::Output; - - fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { - let this = self.project(); - let _enter = this.span.enter(); - this.inner.poll(cx) - } - } - - impl Instrumented { - pub(crate) fn new(inner: T, span: Span) -> Self { - Self { inner, span } - } - } + pub(crate) use tracing::instrument::Instrumented; #[inline] + #[cfg_attr(tokio_track_caller, track_caller)] pub(crate) fn task(task: F, kind: &'static str) -> Instrumented { + use tracing::instrument::Instrument; + #[cfg(tokio_track_caller)] + let location = std::panic::Location::caller(); + #[cfg(tokio_track_caller)] + let span = tracing::trace_span!( + target: "tokio::task", + "task", + %kind, + spawn.location = %format_args!("{}:{}:{}", location.file(), location.line(), location.column()), + ); + #[cfg(not(tokio_track_caller))] let span = tracing::trace_span!( target: "tokio::task", "task", %kind, - future = %std::any::type_name::(), ); - Instrumented::new(task, span) + task.instrument(span) } } } -- cgit v1.2.3