tracing: instrument time::Sleep

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`
@@ -89,6 +93,23 @@ pub fn sleep(duration: Duration) -> Sleep {
     }
 }
 
+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,
+    }
+}
+
 pin_project! {
     /// Future returned by [`sleep`](sleep) and [`sleep_until`](sleep_until).
     ///
@@ -182,7 +203,7 @@ 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]
@@ -191,11 +212,43 @@ pin_project! {
 }
 
 impl Sleep {
-    pub(crate) fn new_timeout(deadline: Instant) -> Sleep {
-        let handle = Handle::current();
-        let entry = TimerEntry::new(&handle, deadline);
+    cfg_not_trace! {
+        pub(crate) fn new_timeout(deadline: Instant) -> Sleep {
+            let handle = Handle::current();
+            let entry = TimerEntry::new(&handle, deadline);
+            Sleep { inner: Inner {deadline}, entry }
+        }
+    }
+
+    cfg_trace! {
+        pub(crate) fn new_timeout(deadline: Instant) -> Sleep {
+            let handle = Handle::current();
+            let entry = TimerEntry::new(&handle, deadline);
+
+            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: "tokio::resource::state_update",
+                duration = duration,
+                duration.unit = "ms",
+                duration.op = "override",
+            );
+            drop(span_guard);
 
-        Sleep { deadline, entry }
+            Sleep { inner: Inner {deadline, resource_span, async_op_span, time_source }, entry }
+        }
     }
 
     pub(crate) fn far_future() -> Sleep {
@@ -204,7 +257,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.
@@ -220,7 +273,7 @@ impl Sleep {
     /// future completes without having to create new associated state.
     ///
     /// This function can be called both before and after the future has
-    /// completed.
+    /// completed.Event
     ///
     /// To call this method, you will usually combine the call with
     /// [`Pin::as_mut`], which lets you call the method without consuming the
@@ -244,40 +297,120 @@ impl Sleep {
     ///
     /// [`Pin::as_mut`]: fn@std::pin::Pin::as_mut
     pub fn reset(self: Pin<&mut Self>, deadline: Instant) {
-        let me = self.project();
-        me.entry.reset(deadline);
-        *me.deadline = deadline;
+        self.reset_inner(deadline)
+    }
+
+    cfg_trace! {
+        fn reset_inner(self: Pin<&mut Self>, deadline: Instant) {
+            let me = self.project();
+
+            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: "tokio::resource::state_update",
+                duration = duration,
+                duration.unit = "ms",
+                duration.op = "override",
+            );
+            me.entry.reset(deadline);
+            (*me.inner).deadline = deadline;
+        }
     }
 
-    fn poll_elapsed(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Result<(), Error>> {
-        let me = self.project();
+    cfg_not_trace! {
+        fn reset_inner(self: Pin<&mut Self>, deadline: Instant) {
+            let me = self.project();
+            me.entry.reset(deadline);
+            (*me.inner).deadline = deadline;
+        }
+    }
+
+    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>> {
+            macro_rules! trace_op {
+                ($readiness:literal) => {
+                    tracing::trace!(
+                        target: "tokio::resource::poll_op",
+                        op_name = "poll_elapsed",
+                        readiness = $readiness
+                    );
+                }
+            }
+
+            let me = self.project();
+            let _span_guard = me.inner.resource_span.enter();
+
+            // Keep track of task budget
+            let coop = match crate::coop::poll_proceed(cx) {
+                Poll::Pending => {
+                    trace_op!("pending");
+                    return Poll::Pending;
+                },
+                Poll::Ready(coop) => coop
+            };
+
+
+            let result =  me.entry.poll_elapsed(cx).map(move |r| {
+                coop.made_progress();
+                r
+            });
+            match result {
+                Poll::Ready(result) => {
+                    trace_op!("ready");
+                    Poll::Ready(result)
+                },
+                Poll::Pending => {
+                    trace_op!("pending");
+                    Poll::Pending
+                }
+            }
+        }
     }
 }
 
 impl Future for Sleep {
     type Output = ();
 
-    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.
-        match ready!(self.as_mut().poll_elapsed(cx)) {
-            Ok(()) => Poll::Ready(()),
-            Err(e) => panic!("timer error: {}", e),
+    // `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_not_trace! {
+        fn poll(mut self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
+            match ready!(self.as_mut().poll_elapsed(cx)) {
+                Ok(()) => Poll::Ready(()),
+                Err(e) => panic!("timer error: {}", e),
+            }
+        }
+    }
+
+    cfg_trace! {
+        fn poll(mut self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
+            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),
+            }
         }
     }
 }