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
4 changes: 2 additions & 2 deletions tokio/Cargo.toml
Expand Up @@ -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 }
Expand Down Expand Up @@ -131,4 +131,4 @@ all-features = true
rustdoc-args = ["--cfg", "docsrs"]

[package.metadata.playground]
features = ["full"]
features = ["full"]
41 changes: 41 additions & 0 deletions tokio/build.rs
@@ -0,0 +1,41 @@
use std::{env, ffi::OsString, process::Command};

fn main() {
match rustc_minor_version() {
// If rustc >= 1.47.0, we can enable `track_caller`.
hawkw marked this conversation as resolved.
Show resolved Hide resolved
Ok(minor) if minor >= 47 => println!("cargo:rustc-cfg=tokio_track_caller"),
Err(e) => println!("cargo:warning=could not parse rustc version: {}", e),
hawkw marked this conversation as resolved.
Show resolved Hide resolved
_ => {}
}
}

fn rustc_minor_version() -> Result<usize, Box<dyn std::error::Error>> {
let rustc = env::var_os("RUSTC").unwrap_or_else(|| OsString::from("rustc"));
let out = Command::new(rustc).arg("-V").output()?;
let version_str = std::str::from_utf8(&out.stdout)?;
let mut parts = version_str.split(' ');
if parts.next() != Some("rustc") {
return Err(format!("weird rustc version: {:?} (missing 'rustc') ", version_str).into());
}
if let Some(part) = parts.next() {
let mut parts = part.split('.');
if parts.next() != Some("1") {
return Err(format!(
"weird rustc version: {:?} (does not start with 1)",
version_str
)
.into());
}
if let Some(middle) = parts.next() {
Ok(middle.parse()?)
} else {
Err(format!("weird rustc version: {:?} (no minor version)", version_str).into())
}
} else {
Err(format!(
"weird rustc version: {:?} (missing version entirely?) ",
version_str,
)
.into())
}
}
15 changes: 14 additions & 1 deletion tokio/src/runtime/handle.rs
Expand Up @@ -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",
Expand Down
4 changes: 4 additions & 0 deletions tokio/src/runtime/mod.rs
Expand Up @@ -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),
Expand All @@ -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,
Expand Down
1 change: 1 addition & 0 deletions tokio/src/task/blocking.rs
Expand Up @@ -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,
Expand Down
2 changes: 2 additions & 0 deletions tokio/src/task/local.rs
Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand Down
1 change: 1 addition & 0 deletions tokio/src/task/spawn.rs
Expand Up @@ -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.

pub fn spawn<T>(task: T) -> JoinHandle<T::Output>
where
T: Future + Send + 'static,
Expand Down
48 changes: 14 additions & 34 deletions 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()),
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.

);
#[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)
}
}
}
Expand Down