Display durations nicely

restatedev · Dec 13, 2024 · d292f6b · d292f6b
1 parent 19f158e
commit d292f6b
Show file tree

Hide file tree

Showing 3 changed files with 27 additions and 9 deletions.
diff --git a/src/lib.rs b/src/lib.rs
@@ -313,8 +313,12 @@ pub trait VM: Sized {
 
     fn sys_state_clear_all(&mut self) -> VMResult<()>;
 
-    fn sys_sleep(&mut self, wake_up_time_since_unix_epoch: Duration)
-        -> VMResult<AsyncResultHandle>;
+    /// Note: `now_since_unix_epoch` is only used for debugging purposes
+    fn sys_sleep(
+        &mut self,
+        wake_up_time_since_unix_epoch: Duration,
+        now_since_unix_epoch: Option<Duration>,
+    ) -> VMResult<AsyncResultHandle>;
 
     fn sys_call(&mut self, target: Target, input: Bytes) -> VMResult<AsyncResultHandle>;
 

diff --git a/src/tests/sleep.rs b/src/tests/sleep.rs
@@ -22,7 +22,7 @@ fn sleep_suspends() {
         .run(|vm| {
             vm.sys_input().unwrap();
 
-            let h1 = vm.sys_sleep(Duration::from_secs(1)).unwrap();
+            let h1 = vm.sys_sleep(Duration::from_secs(1), None).unwrap();
             vm.notify_await_point(h1);
             let h1_result = vm.take_async_result(h1);
             if let Err(SuspendedOrVMError::Suspended(_)) = &h1_result {
@@ -67,7 +67,7 @@ fn sleep_completed() {
         .run(|vm| {
             vm.sys_input().unwrap();
 
-            let h1 = vm.sys_sleep(Duration::from_secs(1)).unwrap();
+            let h1 = vm.sys_sleep(Duration::from_secs(1), None).unwrap();
             vm.notify_await_point(h1);
             let h1_result = vm.take_async_result(h1);
             if let Err(SuspendedOrVMError::Suspended(_)) = &h1_result {
@@ -115,7 +115,7 @@ fn sleep_still_sleeping() {
         .run(|vm| {
             vm.sys_input().unwrap();
 
-            let h1 = vm.sys_sleep(Duration::from_secs(1)).unwrap();
+            let h1 = vm.sys_sleep(Duration::from_secs(1), None).unwrap();
             vm.notify_await_point(h1);
             let h1_result = vm.take_async_result(h1);
             if let Err(SuspendedOrVMError::Suspended(_)) = &h1_result {

diff --git a/src/vm/mod.rs b/src/vm/mod.rs
@@ -34,7 +34,7 @@ use std::fmt;
 use std::mem::size_of;
 use std::time::Duration;
 use strum::IntoStaticStr;
-use tracing::{enabled, instrument, Level};
+use tracing::{debug, enabled, instrument, Level};
 
 mod context;
 pub(crate) mod errors;
@@ -442,12 +442,26 @@ impl super::VM for CoreVM {
         fields(restate.invocation.id = self.debug_invocation_id(), restate.journal.index = self.context.journal.index(), restate.protocol.version = %self.version),
         ret
     )]
-    fn sys_sleep(&mut self, wake_up_time: Duration) -> VMResult<AsyncResultHandle> {
-        invocation_debug_logs!(self, "Executing 'Sleep for {wake_up_time:?}'");
+    fn sys_sleep(
+        &mut self,
+        wake_up_time_since_unix_epoch: Duration,
+        now_since_unix_epoch: Option<Duration>,
+    ) -> VMResult<AsyncResultHandle> {
+        if self.is_processing() {
+            if let Some(now_since_unix_epoch) = now_since_unix_epoch {
+                debug!(
+                    "Executing 'Sleeping for {:?}'",
+                    wake_up_time_since_unix_epoch - now_since_unix_epoch
+                );
+            } else {
+                debug!("Executing 'Sleeping");
+            }
+        }
+
         self.do_transition(SysCompletableEntry(
             "SysSleep",
             SleepEntryMessage {
-                wake_up_time: u64::try_from(wake_up_time.as_millis())
+                wake_up_time: u64::try_from(wake_up_time_since_unix_epoch.as_millis())
                     .expect("millis since Unix epoch should fit in u64"),
                 ..Default::default()
             },