tokio::time::pause should not automatically advance time when there are other things to do

[KamilaBorowska]

Is your feature request related to a problem? Please describe.
Currently tokio::time::pause is not very useful due to automatically advancing the time even when there are other things to do. This makes it mostly useless for unit testing, something it was designed for, unless a test doesn't spawn new tasks that wait. For example, the following program:

use tokio::task::JoinError;
use tokio::time::{self, Duration, Instant};

#[tokio::main]
async fn main() -> Result<(), JoinError> {
    time::pause();
    println!("{:?}", Instant::now());
    tokio::spawn(time::sleep(Duration::from_secs(10)));
    tokio::spawn(async { }).await?;
    println!("{:?}", Instant::now());
    Ok(())
}

Will show a time difference of 10 seconds due to spawned tasks advancing a timer by 10 seconds even when it's not necessary.

Curiously, this behaviour wasn't always here, before #2059 was merged the behaviour was much saner in that the timer did not advance until manually advanced.

Describe the solution you'd like
Change the behaviour of tokio::time::pause to advance timer only when necessary.

[carllerche]

I do not believe this is correct. Without advancing time implicitly, there are many cases that just aren't possible. You made the claim "not very useful" without providing any support. Empirically, this statement is not true.

An argument could be made that it should not be called pause, but I don't see an argument for why it should deadlock.

Without this behavior, there is no real way to process all queued tasks before advancing the time manually.

[KamilaBorowska]

My issue is that I want to spawn a task that sleeps before doing something. For example this is a problem that pretty much prevents me from testing https://gitlab.com/KonradBorowski/psdevbot-rust/-/blob/232e13bbf0fb17abb1a2af35e27723a112395060/src/unbounded.rs.

Specifically, the issue is as follows, I'm trying to write a test that makes sure throttled channel doesn't delay on the first message. Simple enough.

First, let's make a minimal struct that doesn't depend on specific structures from the code I'm writing, something that could be put into lib.rs by itself.

use futures::channel::mpsc;
use futures::channel::mpsc::SendError;
use futures::{Sink, SinkExt, StreamExt};
use tokio::time;

pub struct UnboundedSender {
    sender: mpsc::UnboundedSender<i32>,
}

impl UnboundedSender {
    pub fn new(mut showdown_sender: impl Sink<i32> + Send + Unpin + 'static) -> Self {
        let (tx, mut rx) = mpsc::unbounded();
        tokio::spawn(async move {
            while let Some(message) = rx.next().await {
                if showdown_sender.send(message).await.is_err() {
                    return;
                }
                time::delay_for(time::Duration::from_millis(700)).await;
            }
        });
        Self { sender: tx }
    }

    pub async fn send(&self, message: i32) -> Result<(), SendError> {
        (&self.sender).send(message).await
    }
}

Then we can write a test.

#[tokio::test]
async fn sender_does_not_delay_on_first_message() -> Result<(), Box<dyn std::error::Error>> {
    use tokio::time::{self, Instant};
    time::pause();
    let (tx, mut rx) = mpsc::unbounded();
    let sender = UnboundedSender::new(tx);
    let now = Instant::now();
    sender.send(42).await?;
    assert_eq!(rx.next().await, Some(42));
    assert_eq!(now, Instant::now());
    Ok(())
}

This causes an error:

thread 'sender_does_not_delay_on_first_message' panicked at 'assertion failed: `(left == right)`
  left: `Instant { tv_sec: 1391, tv_nsec: 897378452 }`,
 right: `Instant { tv_sec: 1392, tv_nsec: 537331879 }`', src/lib.rs:38:5

If we go back to tokio 0.2.0 with cargo update -p tokio --precise 0.2.0 then everything works. The timer doesn't advance when we don't want it.

(by the way, yes, the change of behaviour in tokio 0.2.y was a breaking change, but at this point I don't think it should reverted)

Okay, but what if I want to check whether an event did not occur. Well, that could be done too.

#[tokio::test]
async fn sender_does_not_delay_on_first_message() -> Result<(), Box<dyn std::error::Error>> {
    use tokio::task;
    use tokio::time::{self, Duration, Instant};
    time::pause();
    let (tx, mut rx) = mpsc::unbounded();
    let sender = UnboundedSender::new(tx);
    let now = Instant::now();
    // First element gets send instantly
    sender.send(42).await?;
    task::yield_now().await;
    assert_eq!(rx.try_next()?, Some(42));
    assert_eq!(now, Instant::now());
    // Second element will require waiting
    sender.send(24).await?;
    task::yield_now().await;
    assert!(rx.try_next().is_err());
    // Actually waiting
    time::advance(Duration::from_millis(701)).await;
    task::yield_now().await;
    assert_eq!(rx.try_next()?, Some(24));
    Ok(())
}

How do I do this test with current time::pause. It's impossible, as far as I can tell.

Arguably the current implementation may have its uses (I don't know what they may be, didn't find anything on GitHub), but it's not pausing the timer, and should be called something else if it should be still available.

As for deadlocking, I would say that deadlocking in tests is somewhat more acceptable (time::pause is designed for tests). It would be cool if Tokio could detect a deadlock caused by time::pause usage however, but that's more of a separate feature request.

[carllerche]

As far as I can tell, both cases are bugs. Time should not advance unless the system is idle. It is caused because the root future is not spawned onto the runtime. It can be fixed by not advancing time if the waker was notified.

Feel free to submit a PR to fix.

[carllerche]

Reclassifying this as a bug and removing the 1.0 label as it is not a blocker.

[KamilaBorowska]

Thanks, for me spawning a task in a test is a valid workaround.

[b-naber]

This seems to no longer be a bug:

https://play.rust-lang.org/?version=stable&mode=debug&edition=2018&gist=4e1a7fd7b8a2dd82daf8ba3fc2831500

[KamilaBorowska]

This seems to no longer be a bug:

https://play.rust-lang.org/?version=stable&mode=debug&edition=2018&gist=4e1a7fd7b8a2dd82daf8ba3fc2831500

It's still here, it's just that spawning a task work-arounds the bug. It's a valid workaround for me as I said before.

[b-naber]

@xfix If I run your original test as a test on the current fork, the test passes as well. Also I looked at the timer implementation and I don't see how spawning a task should somehow change the behaviour of time::pause.

[KamilaBorowska]

@xfix If I run your original test as a test on the current fork, the test passes as well. Also I looked at the timer implementation and I don't see how spawning a task should somehow change the behaviour of time::pause.

Try running it as a test.

#[tokio::test]
async fn test() {
    sender_does_not_delay_on_first_message().await
}

[gwik]

I'll take a look at this one.

[gwik]

Provided tests cases pass with 1.x.
We can close this one.

[Darksonn]

Thanks for trying the test cases again @gwik