Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

time::advance advances too far when given a Duration of sub-millisecond granularity #3837

Closed
hallmaxw opened this issue Jun 3, 2021 · 6 comments · Fixed by #3852
Closed
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-time Module: tokio/time

Comments

@hallmaxw
Copy link

hallmaxw commented Jun 3, 2021

Version

tokio-repro v0.1.0 (/Users/hallmaxw/tokio-repro)
└── tokio v1.6.1
    └── tokio-macros v1.2.0 (proc-macro)

Platform
Darwin Kernel Version 19.6.0

Description

time::advance advances time too far when it's given a Duration of sub-millisecond granularity. This worked prior to this commit, which was included in tokio 1.6 2b9b558

I assume this is happening because the above commit updates time::advance to use sleep_until, which operates at millisecond granularity.

Here's some code to reproduce the issue:

#[cfg(test)]
mod tests {
    use std::time::Duration;

    use tokio::time::{self, Instant};

    #[tokio::test]
    async fn test_time_advance() {
        time::pause();
        let start_time = Instant::now();
        time::advance(Duration::from_micros(3_141_592)).await;

        // The duration elapsed is the duration passed to time::advance plus
        // an extra 1 ms. You'd expect the duration elapsed to just be the duration
        // passed to time::advance
        assert_eq!(
            start_time.elapsed(),
            Duration::from_micros(3_141_592 + 1_000)
        )
    }
}

I expected the duration elapsed to be the exact duration passed to time::advance.

Instead, the duration elapsed was the duration passed to time::advance plus an additional millisecond.

cc: @LucioFranco

@hallmaxw hallmaxw added A-tokio Area: The main tokio crate C-bug Category: This is a bug. labels Jun 3, 2021
@Darksonn Darksonn added the M-time Module: tokio/time label Jun 4, 2021
@Darksonn
Copy link
Contributor

Darksonn commented Jun 4, 2021

We should probably have had a test for this. Thanks for spotting it.

@LucioFranco
Copy link
Member

I believe this behavior was designed because the driver does this https://github.com/tokio-rs/tokio/blob/master/tokio/src/time/driver/mod.rs#L111? So technically during normal operation (not in test mode) tokio would round up and I think it makes sene for the mock clock to do the same?

@carllerche
Copy link
Member

time::advance isn't technically the timer though, it just enables mocking Instant::now() which is precise. I believe the answer is to avoid the sleep if the time range is below 1ms and just do a yield in that case.

@carllerche
Copy link
Member

Actually, more robust is probably checking when the next timer expiration is and comparing to that.

@loyd
Copy link
Contributor

loyd commented Jun 10, 2021

Is someone fixing this problem?

@jazvit
Copy link

jazvit commented Jun 10, 2021

This broke my tests :( rolled back 1.5

carllerche added a commit that referenced this issue Jun 10, 2021
Update the advance logic to factor in the timer's ms rounding.

Fixes #3837
carllerche added a commit that referenced this issue Jun 11, 2021
Update the advance logic to factor in the timer's ms rounding.

Fixes #3837
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-time Module: tokio/time
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants