Don't auto-advance time when a spawn_blocking task is running.

[jorendorff]

Time shouldn't auto-advance unless there's really nothing else going on. In general that is hard to fix, but this special case is relatively easy.

Fixes: #4614

Motivation

I'm writing tests for a complex distributed system. In a single test process, a "server" task runs CPU-bound units of work using spawn_blocking, while a "client" task sends requests and waits for responses using .await, with a generous timeout. Issue #4614 causes the timeout to elapse instantly; no responses ever succeed.

There seems to be consensus in #4614 that this behavior is a bug, and I agree.

Solution

I added a field in the clock that tells how many spawn_blocking tasks are running/scheduled.

The code increments this counter when spawning such a task and decrements it when the task is done. This means the increment and the decrement are not conveniently side by side in the code, but I think it might be important to bump the counter synchronously, to avoid a race condition if the new task doesn't actually start running right away.

I named the counter auto_advance_inhibit_count, instead of something obvious like num_blocking_tasks, because it might make sense in the future to provide an API whereby users can manually inhibit auto-advance (... if I'm right in thinking that blocking tasks are not the only kind of work Tokio "can't see").

[jorendorff]

This could conceivably break someone's existing code.

If a spawn_blocking task behaves like a server, and runs forever (but using sync code) handling requests from async clients, this change would inhibit auto-advance as long as that task is running. That could make a test stall.

If that's too big a breaking change, my problem could alternatively be addressed with

• a new API that's like spawn_blocking but inhibits auto-advance; or
• a new API that allows spawn_blocking tasks to turn auto-advance on or off manually as needed.

Of course, there's the question of whether such APIs would actually work well. Intuitively, I think the second option is pretty good. I think async code generally "knows" locally there's a future that represents work that's happening outside of tokio's managed tasks, that will complete and unblock a tokio task. When such a future is polled, I think that's when auto-advance should be inhibited.

[Darksonn]

Hmm, yes, the server example is annoying.

[jorendorff]

Hmm, yes, the server example is annoying.

OK, how about a function that wraps a future, say

// (in tokio::time)

/// Annotate a future as doing work, from when it is first polled to when it becomes `Ready`, even if no
/// tokio thread is currently polling it.
///
/// This suppresses the auto-advance feature when time is paused. When time is not paused, or
/// the **test-util** feature is not enabled, this is a no-op.
async fn inhibit_auto_advance<F: Future>(fut: F) -> F::Output;

?

[carllerche]

I haven't reviewed enough, but I am OK considering this a "bug fix" and not a "breaking change". The arguments are valid. Also, risk is lower due to it being a test-time feature.

[jorendorff]

I haven't reviewed enough, but I am OK considering this a "bug fix" and not a "breaking change". The arguments are valid. Also, risk is lower due to it being a test-time feature.

In that case, this is ready for review.

[Darksonn]

I had a quick look and it looks reasonable enough. There are some CI failures though.

[jorendorff]

OK, I fixed it—CI is green now.

[jorendorff]

There's still a race condition, apparently. Loom runs the test about 600 times before detecting it.

[jorendorff]

I wonder if this is the second problem I mentioned a couple days ago: if the main thread parks itself, allow_auto_advance in the blocking-task-runner thread won't wake it up.

The interleaving that fails is:

About to spawn task a
spawn_blocking_inner(task a)
BlockingSchedule::new()
inhibit_auto_advance: about to ask for clock lock
inhibit_auto_advance: acquired clock lock
inhibit_auto_advance: count is: 1
About to spawn task b
spawn_blocking_inner(task b)
BlockingSchedule::new()
inhibit_auto_advance: about to ask for clock lock
inhibit_auto_advance: acquired clock lock
inhibit_auto_advance: count is: 2
spawned both tasks
About to await task a
Running task a
allow_auto_advance: about to ask for clock lock
allow_auto_advance: acquired clock lock
allow_auto_advance: count is: 1
allow_auto_advance: about to ask for clock lock
allow_auto_advance: acquired clock lock
allow_auto_advance: count is: 0
thread 'main' panicked at 'deadlock; threads = [(Id(0), Blocked(Location(None))), (Id(1), Blocked(Location(None))), (Id(2), Blocked(Location(None)))]', /Users/jorendorff/.cargo/registry/src/github.com-1ecc6299db9ec823/loom-0.5.6/src/rt/execution.rs:215:13

I don't know why we don't see Running task b.

[Darksonn]

Considering that loom reports a deadlock, it seems reasonable to conclude that this is due to the issue you mention.

As for why you don't see task B, I assume its because it was scheduled to run later?

[jorendorff]

The loom issue is fixed and has a test now. This is ready for review.

(I don't know why there are still jobs that are "Expected" after all this time; I think I've seen that before with gh actions when new jobs are added...?)

[Darksonn]

You can fix CI by merging in master.

[jorendorff]

OK, this is ready for a CI run.

[jorendorff]

Thanks! Tests are green. I think this is ready for review.

[jorendorff]

👋 hi, friendly review ping (or, what should I do next here)

[Darksonn]

Sorry about the silence. We discussed this on the discord back when you said CI was green, and I think we came to the conclusion that this looks fine. I took another look just now, and I have one comment regarding your tests.

[Darksonn]

Please reduce the sleeps. Our test suite already takes long enough.