summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorEliza Weisman <eliza@buoyant.io>2020-11-01 10:48:44 -0800
committerGitHub <noreply@github.com>2020-11-01 10:48:44 -0800
commitfede3db76aef95c010c3e0c3da3b732380285097 (patch)
tree0aa934da682d7f31cf093e69e420ba88601acb6e
parent2b23aa7389686f341e564c8da565a3b4c8b1188f (diff)
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 <eliza@buoyant.io>
-rw-r--r--tokio/Cargo.toml7
-rw-r--r--tokio/build.rs22
-rw-r--r--tokio/src/runtime/handle.rs15
-rw-r--r--tokio/src/runtime/mod.rs4
-rw-r--r--tokio/src/task/blocking.rs1
-rw-r--r--tokio/src/task/local.rs2
-rw-r--r--tokio/src/task/spawn.rs1
-rw-r--r--tokio/src/util/trace.rs48
8 files changed, 63 insertions, 37 deletions
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<F, R>(&self, func: F) -> JoinHandle<R>
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::<F>(),
+ 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<F>(&self, future: F) -> JoinHandle<F::Output>
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<F, R>(&self, func: F) -> JoinHandle<R>
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, R>(f: F) -> JoinHandle<R>
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<F>(future: F) -> JoinHandle<F::Output>
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<F>(&self, future: F) -> JoinHandle<F::Output>
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<T>(task: T) -> JoinHandle<T::Output>
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<T> {
- #[pin]
- inner: T,
- span: Span,
- }
- }
-
- impl<T: Future> Future for Instrumented<T> {
- type Output = T::Output;
-
- fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
- let this = self.project();
- let _enter = this.span.enter();
- this.inner.poll(cx)
- }
- }
-
- impl<T> Instrumented<T> {
- 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<F>(task: F, kind: &'static str) -> Instrumented<F> {
+ 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::<F>(),
);
- Instrumented::new(task, span)
+ task.instrument(span)
}
}
}