Skip to content

Commit

Permalink
make self-tracing public
Browse files Browse the repository at this point in the history
  • Loading branch information
Ariel Ben-Yehuda committed Jan 9, 2025
1 parent 5c8cd33 commit 6e64f61
Show file tree
Hide file tree
Showing 3 changed files with 173 additions and 2 deletions.
64 changes: 63 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,66 @@ impl Trace {
})
.collect()
}

/// Runs the function `f` in tracing mode, and returns its result along with the resulting [`Trace`].
///
/// 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
/// `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:
/// ```
/// let mut trace = None;
///
/// // some future
/// let mut test_future = Box::pin(async move { tokio::task::yield_now().await; 0 });
///
/// // trace it once
/// Trace::root(std::future::poll_fn(|cx| {
/// if trace.is_none() {
/// // make sure we only trace once
/// let (res, captured) = Trace::capture(|| test_future.as_mut().poll(cx));
/// trace = Some(captured);
/// res
/// } else {
/// test_future.as_mut().poll(cx)
/// }
/// })).await;@@
///
/// // check that there are backtraces
/// assert!(!trace.unwrap().resolve_backtraces().is_empty());
/// ```
///
/// ### 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`].
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>
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
108 changes: 108 additions & 0 deletions tokio/tests/task_trace_self.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,108 @@
#![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,
pin::Pin,
sync::{Arc, Mutex},
task::{Context, Poll},
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)));
}
}

0 comments on commit 6e64f61

Please sign in to comment.