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

make tracing a task public so self-tracing is possible #6972

Open
wants to merge 5 commits into
base: master
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
66 changes: 65 additions & 1 deletion tokio/src/runtime/dump.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,9 @@
//! See [`Handle::dump`][crate::runtime::Handle::dump].

use crate::task::Id;
use std::{fmt, path::Path};
use std::{fmt, future::Future, path::Path};

pub use crate::runtime::task::trace::Root;

/// A snapshot of a runtime's state.
///
Expand Down Expand Up @@ -214,6 +216,68 @@ impl Trace {
})
.collect()
}

/// Runs the function `f` in tracing mode, and returns its result along with the resulting [`Trace`].
arielb1 marked this conversation as resolved.
Show resolved Hide resolved
///
/// The passed-in function is normally a poll function. Due to the way tracing is implemented,
/// Tokio leaf futures might, instead of doing their actual work, do the equivalent of a
arielb1 marked this conversation as resolved.
Show resolved Hide resolved
/// `yield_now` (returning a `Poll::Pending` and scheduling the current context for execution),
/// which means forward progress is only guaranteed if you eventually call your future outside of
/// `capture`.
///
/// Example usage:
/// ```
/// use std::future::Future;
/// use std::task::Poll;
/// use tokio::runtime::dump::Trace;
///
/// # async fn test_fn() {
/// // some future
/// let mut test_future = std::pin::pin!(async move { tokio::task::yield_now().await; 0 });
///
/// // trace it once
/// let (trace, res) = Trace::root(std::future::poll_fn(|cx| {
/// let (res, trace) = Trace::capture(|| test_future.as_mut().poll(cx));
/// Poll::Ready((trace, res))
/// })).await;
///
/// let output = match res {
/// Poll::Ready(output) => output,
/// Poll::Pending => test_future.await,
/// };
///
/// println!("{trace}");
/// # }
/// ```
///
/// ### Nested calls
///
/// Nested calls to `capture` might return partial traces, but will not do any other undesirable behavior (for
/// example, they will not panic).
///
/// ### Unstable Implementation Details
///
/// When run in tracing mode, Tokio leaf futures will return `Poll::Pending` and emit a stack trace
/// that will be captured in the returning [`Trace`].
arielb1 marked this conversation as resolved.
Show resolved Hide resolved
pub fn capture<F, R>(f: F) -> (R, Trace)
where
F: FnOnce() -> R,
{
let (res, trace) = super::task::trace::Trace::capture(f);
(res, Trace { inner: trace })
}

/// Create a root for stack traces captured using [`Trace::capture`]. Stack frames above
/// the root will not be captured.
///
/// Nesting multiple [`Root`] futures is fine. Captures will stop at the first root. Not having
/// a [`Root`] is fine as well, but there is no guarantee on where the capture will stop.
pub fn root<F>(f: F) -> Root<F>
arielb1 marked this conversation as resolved.
Show resolved Hide resolved
where
F: Future,
{
crate::runtime::task::trace::Trace::root(f)
}
}

impl Dump {
Expand Down
3 changes: 2 additions & 1 deletion tokio/src/runtime/task/trace/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,8 @@ pub(crate) struct Trace {
pin_project_lite::pin_project! {
#[derive(Debug, Clone)]
#[must_use = "futures do nothing unless you `.await` or poll them"]
pub(crate) struct Root<T> {
/// A future wrapper that roots traces (captured with [`Trace::capture`]).
pub struct Root<T> {
#[pin]
future: T,
}
Expand Down
107 changes: 107 additions & 0 deletions tokio/tests/task_trace_self.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,107 @@
#![allow(unknown_lints, unexpected_cfgs)]
#![cfg(all(
tokio_unstable,
tokio_taskdump,
target_os = "linux",
any(target_arch = "aarch64", target_arch = "x86", target_arch = "x86_64")
))]

use std::future::Future;
use std::pin::Pin;
use std::sync::{Arc, Mutex};
use std::task::{Context, Poll};
use std::time::{Duration, Instant};

use tokio::runtime::dump::{Root, Trace};

pin_project_lite::pin_project! {
pub struct PrettyFuture<F: Future> {
#[pin]
f: Root<F>,
t_last: State,
logs: Arc<Mutex<Vec<Trace>>>,
}
}

enum State {
NotStarted,
Running { since: Instant },
Alerted,
}

impl<F: Future> PrettyFuture<F> {
pub fn pretty(f: F, logs: Arc<Mutex<Vec<Trace>>>) -> Self {
PrettyFuture {
f: Trace::root(f),
t_last: State::NotStarted,
logs,
}
}
}

impl<F: Future> Future for PrettyFuture<F> {
type Output = F::Output;

fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<F::Output> {
let mut this = self.project();
let now = Instant::now();
let t_last = match this.t_last {
State::Running { since } => Some(*since),
State::NotStarted => {
*this.t_last = State::Running { since: now };
None
}
State::Alerted => {
// don't double-alert for the same future
None
}
};
if t_last.is_some_and(|t_last| now.duration_since(t_last) > Duration::from_millis(500)) {
let (res, trace) = tokio::runtime::dump::Trace::capture(|| this.f.as_mut().poll(cx));
this.logs.lock().unwrap().push(trace);
*this.t_last = State::Alerted;
return res;
}
this.f.poll(cx)
}
}

#[tokio::test]
async fn task_trace_self() {
let log = Arc::new(Mutex::new(vec![]));
let log2 = Arc::new(Mutex::new(vec![]));
let mut good_line = vec![];
let mut bad_line = vec![];
PrettyFuture::pretty(
PrettyFuture::pretty(
async {
bad_line.push(line!() + 1);
tokio::task::yield_now().await;
bad_line.push(line!() + 1);
tokio::time::sleep(Duration::from_millis(1)).await;
for _ in 0..100 {
good_line.push(line!() + 1);
tokio::time::sleep(Duration::from_millis(10)).await;
}
},
log.clone(),
),
log2.clone(),
)
.await;
for line in good_line {
let s = format!("{}:{}:", file!(), line);
assert!(log.lock().unwrap().iter().any(|x| {
eprintln!("{}", x);
format!("{}", x).contains(&s)
}));
}
for line in bad_line {
let s = format!("{}:{}:", file!(), line);
assert!(!log
.lock()
.unwrap()
.iter()
.any(|x| format!("{}", x).contains(&s)));
}
}
Loading