Tokio time, sleep and interval, two seconds too fast

help
1

I'm running into a weird issue with Tokio and tokio::time::sleep and tokio::time::interval. For some reason the following code runs two seconds fast each iteration.

tokio::spawn(async move {
  tokio::select! {
     _ = async {
      let mut interval = tokio::time::interval(Duration::from_secs(60));
      loop {
        let now = Instant::now();
        info!("Then: {now:?}");
  
        interval.tick().await;
  
        let now = Instant::now();
        info!("Now: {now:?}");
      }
    } => {}
    _ = rx => {
      info!("Timer task has exited.");
    }
  }
});

Here is an example of the log output:

2024-08-28T16:34:40.760926Z  INFO report_timer: Then: Instant { tv_sec: 93042, tv_nsec: 879689666 }
2024-08-28T16:35:38.473309Z  INFO report_timer: Now: Instant { tv_sec: 93102, tv_nsec: 881257662 }

2024-08-28T16:35:38.473452Z  INFO report_timer: Then: Instant { tv_sec: 93102, tv_nsec: 881405822 }
2024-08-28T16:36:36.214138Z  INFO report_timer: Now: Instant { tv_sec: 93162, tv_nsec: 879549291 }

2024-08-28T16:36:36.214301Z  INFO report_timer: Then: Instant { tv_sec: 93162, tv_nsec: 879717380 }
2024-08-28T16:37:35.083884Z  INFO report_timer: Now: Instant { tv_sec: 93222, tv_nsec: 880528512 }

As you can see, even though the output of the Timespec struct shows an increment of 60 seconds between each Then and Now logging statement the time passed is almost 2 seconds faster each loop iteration.

Any advice on how I can get this interval to be closer to accurate. I know it's almost impossible to be exact, but a 2 second drift each iteration is too much.

2

This seems to be an issue with the timestamp used during the creation of the tracing span. If you replace them with calls to println!, you would see correct timestamps.

1 Like
3

Thanks. I tested with println! and there is something to what you're saying. However it's still a bit off. Here's the output with println!:

before: 2024-08-28T18:49:42.175385759Z
after : 2024-08-28T18:50:40.977902843Z

It's still fast by ~1 second, but if I set the interval to 60_001 milliseconds then it works as expected.

4

Hu, that's weird. I tested it in the playground.

5

That's weird, it's working perfectly in the playground. Wonder if mine isn't playing nicely because I'm in WSL.

6

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.