tracing: instrument time::Sleep

tokio/src/macros/mod.rs

@@ -15,6 +15,9 @@ mod ready;
 #[macro_use]
 mod thread_local;
 
+#[macro_use]
+mod trace;
+
 #[macro_use]
 #[cfg(feature = "rt")]
 pub(crate) mod scoped_tls;

tokio/src/macros/trace.rs

@@ -0,0 +1,26 @@
+cfg_trace! {
+    macro_rules! trace_op {
+        ($name:literal, $readiness:literal) => {
+            tracing::trace!(
+                target: "runtime::resource::poll_op",
+                op_name = $name,
+                is_ready = $readiness
+            );
+        }
+    }
+
+    macro_rules! trace_poll_op {
+        ($name:literal, $poll:expr) => {
+            match $poll {
+                std::task::Poll::Ready(t) => {
+                    trace_op!($name, true);
+                    std::task::Poll::Ready(t)
+                }
+                std::task::Poll::Pending => {
+                    trace_op!($name, false);
+                    return std::task::Poll::Pending;
+                }
+            }
+        };
+    }
+}

tokio/src/time/driver/sleep.rs

@@ -6,6 +6,10 @@ use std::future::Future;
 use std::pin::Pin;
 use std::task::{self, Poll};
 
+cfg_trace! {
+    use crate::time::driver::ClockTime;
+}
+
 /// Waits until `deadline` is reached.
 ///
 /// No work is performed while awaiting on the sleep future to complete. `Sleep`
@@ -182,20 +186,67 @@ pin_project! {
     #[derive(Debug)]
     #[must_use = "futures do nothing unless you `.await` or poll them"]
     pub struct Sleep {
-        deadline: Instant,
+        inner: Inner,
 
         // The link between the `Sleep` instance and the timer that drives it.
         #[pin]
         entry: TimerEntry,
     }
 }
 
+cfg_trace! {
+    #[derive(Debug)]
+    struct Inner {
+        deadline: Instant,
+        resource_span: tracing::Span,
+        async_op_span: tracing::Span,
+        time_source: ClockTime,
+    }
+}
+
+cfg_not_trace! {
+    #[derive(Debug)]
+    struct Inner {
+        deadline: Instant,
+    }
+}
+
 impl Sleep {
     pub(crate) fn new_timeout(deadline: Instant) -> Sleep {
         let handle = Handle::current();
         let entry = TimerEntry::new(&handle, deadline);
 
-        Sleep { deadline, entry }
+        #[cfg(all(tokio_unstable, feature = "tracing"))]
+        let inner = {
+            let time_source = handle.time_source().clone();
+            let duration = time_source.deadline_to_tick(deadline) - time_source.now();
+            let resource_span =
+                tracing::trace_span!("runtime.resource", concrete_type = "Sleep", kind = "timer",);
+
+            let async_op_span =
+                tracing::trace_span!("runtime.resource.async_op", source = "Sleep::new_timeout",);
+
+            let span_guard = resource_span.enter();
+            tracing::trace!(
+                target: "runtime::resource::state_update",
+                duration = duration,
+                duration.unit = "ms",
+                duration.op = "override",
+            );
+            drop(span_guard);
+
+            Inner {
+                deadline,
+                resource_span,
+                async_op_span,
+                time_source,
+            }
+        };
+
+        #[cfg(not(all(tokio_unstable, feature = "tracing")))]
+        let inner = Inner { deadline };
+
+        Sleep { inner, entry }
     }
 
     pub(crate) fn far_future() -> Sleep {
@@ -204,7 +255,7 @@ impl Sleep {
 
     /// Returns the instant at which the future will complete.
     pub fn deadline(&self) -> Instant {
-        self.deadline
+        self.inner.deadline
     }
 
     /// Returns `true` if `Sleep` has elapsed.
@@ -244,37 +295,79 @@ impl Sleep {
     ///
     /// [`Pin::as_mut`]: fn@std::pin::Pin::as_mut
     pub fn reset(self: Pin<&mut Self>, deadline: Instant) {
+        self.reset_inner(deadline)
+    }
+
+    fn reset_inner(self: Pin<&mut Self>, deadline: Instant) {
         let me = self.project();
         me.entry.reset(deadline);
-        *me.deadline = deadline;
+        (*me.inner).deadline = deadline;
+
+        #[cfg(all(tokio_unstable, feature = "tracing"))]
+        {
+            let now = me.inner.time_source.now();
+            let duration = me.inner.time_source.deadline_to_tick(deadline) - now;
+            let _span_guard = me.inner.resource_span.enter();
+            tracing::trace!(
+                target: "runtime::resource::state_update",
+                duration = duration,
+                duration.unit = "ms",
+                duration.op = "override",
+            );
+        }
     }
 
-    fn poll_elapsed(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Result<(), Error>> {
-        let me = self.project();
+    cfg_not_trace! {
+        fn poll_elapsed(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Result<(), Error>> {
+            let me = self.project();
 
-        // Keep track of task budget
-        let coop = ready!(crate::coop::poll_proceed(cx));
+            // Keep track of task budget
+            let coop = ready!(crate::coop::poll_proceed(cx));
 
-        me.entry.poll_elapsed(cx).map(move |r| {
-            coop.made_progress();
-            r
-        })
+            me.entry.poll_elapsed(cx).map(move |r| {
+                coop.made_progress();
+                r
+            })
+        }
+    }
+
+    cfg_trace! {
+        fn poll_elapsed(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Result<(), Error>> {
+            let me = self.project();
+            let _span_guard = me.inner.resource_span.enter();
+
+            // Keep track of task budget
+            let coop = ready!(trace_poll_op!(
+                "poll_elapsed",
+                crate::coop::poll_proceed(cx)
+            ));
+
+            let result =  me.entry.poll_elapsed(cx).map(move |r| {
+                coop.made_progress();
+                r
+            });
+
+            trace_poll_op!("poll_elapsed", result)
+        }
     }
 }
 
 impl Future for Sleep {
     type Output = ();
 
+    // `poll_elapsed` can return an error in two cases:
+    //
+    // - AtCapacity: this is a pathological case where far too many
+    //   sleep instances have been scheduled.
+    // - Shutdown: No timer has been setup, which is a mis-use error.
+    //
+    // Both cases are extremely rare, and pretty accurately fit into
+    // "logic errors", so we just panic in this case. A user couldn't
+    // really do much better if we passed the error onwards.
     fn poll(mut self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
-        // `poll_elapsed` can return an error in two cases:
-        //
-        // - AtCapacity: this is a pathological case where far too many
-        //   sleep instances have been scheduled.
-        // - Shutdown: No timer has been setup, which is a mis-use error.
-        //
-        // Both cases are extremely rare, and pretty accurately fit into
-        // "logic errors", so we just panic in this case. A user couldn't
-        // really do much better if we passed the error onwards.
+        #[cfg(all(tokio_unstable, feature = "tracing"))]
+        let _span = self.inner.async_op_span.clone().entered();
+
         match ready!(self.as_mut().poll_elapsed(cx)) {
             Ok(()) => Poll::Ready(()),
             Err(e) => panic!("timer error: {}", e),