deadlock in tokio-1.0

[tancehao]

Version

│ │ ├── tokio v1.0.2
│ │ │ └── tokio-macros v1.0.0
│ │ ├── tokio-util v0.6.1
│ │ │ ├── tokio v1.0.2 ()
│ │ │ └── tokio-stream v0.1.2
│ │ │ └── tokio v1.0.2 ()
│ ├── tokio v1.0.2 ()
├── tokio v1.0.2 ()
├── tokio-compat-03 v0.0.0
├── tokio-stream v0.1.2 ()
├── tokio-util v0.6.1 ()

Platform

linux 4.9.0-8-amd64 #1 SMP Debian 4.9.144-3 (2019-02-02) x86_64 GNU/Linux

Description
My program pulls data from a redis server and send them to another one.
There are many futures —— some of them pull data from the source, some push to the target, and some print stats into stdout periodically(5 seconds). And when pulling and pushing data, the program modifies some metrics managed by prometheus-0.1.0.
The program works well for months under tokio-0.3.0, but when I upgraded to tokio-1.0, deadlock happens. When it is blocked, the program no longer print stats, meaning that some of the futures are not polled by the tokio runtime(multi-threaded mode).

I executed perf top, and here is the output:

and here is what it showed when I selected the first line and then it's annotation:

These statistics seldom change for a long time.

So what happend in my process. What's wrong with the atomic operations?

[Darksonn]

Are you able to get some sort of backtrace or line number for the snippet of assembly?

[tancehao]

Are you able to get some sort of backtrace or line number for the snippet of assembly?

I don't know how...

[Darksonn]

Can you try out doing this? If the program is running in release mode, you might need to add this to your Cargo.toml to include debugging information such as line numbers in the executable.

[pronvis]

My problem is not related to dead lock (as I think), but still worth to mention: #3500

[Flakebi]

I think I hit the same bug. Upgrading from tokio 0.2 to 1.0 went relatively smooth, just in one part in the application, when performing a certain slightly more complex request, it started to hang with 100 % CPU on one core and never returned.
I was able to pinpoint it to one part in my code, a print; tokio::sleep.await; print reached the first print but often not the second (sometimes it worked). It was constantly polling the future, spending most time in atomic operations as mentioned in the issue, but it never got beyond the await.

Today, I finally found the reason in the cooperative scheduling in tokio::coop for reducing tail latencies. Replacing Budget::initial() with Budget::unconstrained() (disabling early returns) fixed this bug for me.

tokio/tokio/src/coop.rs

Lines 97 to 99 in cc97fb8

	pub(crate) fn budget<R>(f: impl FnOnce() -> R) -> R {
	with_budget(Budget::initial(), f)
	}

This bug can only be found in sufficiently large projects that have deeply nested futures and exhaust the initial budget (a backtrace I captured had 218 stackframes).

The module descriptions mentions that “voluntary yield points should be placed after at least some work has been done”. However, that is not always obeyed, leading to tasks being polled and doing nothing for eternity.

One of the places I found is tokio::sleep:

tokio/tokio/src/time/driver/sleep.rs

Lines 216 to 221 in cc97fb8

	let coop = ready!(crate::coop::poll_proceed(cx));
	me.entry.poll_elapsed(cx).map(move |r| {
	coop.made_progress();
	r
	})

My original code did not contain a sleep, so there must to be other places too.

[Darksonn]

Thank you @Flakebi. The coop system consuming permits without doing any work certainly sounds like a problem that can cause a deadlock. Thanks for pointing it out!

I have opened a new issue for tracking this specifically, a link to which you can find right above this reply.

@tancehao Can you check whether your deadlock is caused by the same issue by replacing Budget::initial with Budget::unconstrainted in Tokio? You can replace your Tokio dependency with a custom modified one using a patch section in your Cargo.toml.

[jonhoo]

I replied over in #3502, but the indicated code in sleep doesn't look wrong to me. If coop is dropped without the call to made_progress (that is, if poll_elapsed returns Pending), then the budget is restored to what it was prior to the call to poll_proceed.

I suspect the root cause here is instead that there is some code in the application in question that will not return Pending as long as some child future returns Ready, which is the same problem as an old version of FuturesUnordered had. I'm not sure why that would have changed in the move from 0.2 to 1.0 though..

Could it be that some dependency in your stack still uses tokio 0.2 — that might explain this too. If you run cargo tree -d -p tokio, do you see any other versions than 1.0 show up?

[Flakebi]

Thanks for the fast answers!
There is a tokio 0.2 in my dependency graph, but it’s in a crate that doesn’t actually use it (meilisearch-error), everything else uses 1.1.1 :)
Interesting bug, there are a lot of FuturesOrdered in my call stack. The application/juniper code in that case does not contain any manual implementation of Future or Stream (also this part changed little when updating tokio) apart from message passing with actix and tokio sleeps inserted for debugging. Also, a bug there shouldn’t change behavior if I switch off coop I guess?

The behavior I see is:

1. coop disabled (as described in my comment above): Request finishes instantly (few milliseconds)
2. coop enabled (unchanged tokio): Request does not finish within 30 s. The future that should make progress is constantly polled but it does not make any progress.
3. coop enabled and print; tokio::sleep.await; print in code: The first print is reached, so it started polling the future. The second print is never reached.

 

I guess I don’t understand how coop is working. In the case of sleep, it seems to return early when the budget is used up? (coop::poll_proceed returns Pending, thus ready! returns)
In the case that budget is left and the sleep finished, it calls made_progress, which resets the budget, so sleep does not use any budget.
That means, if I poll enough sleeps with a short enough sleep time that they are always ready, I never use up the budget?

[jonhoo]

So, FuturesOrdered should work just fine as long as you're on a recent version of the futures- crates. I don't think that's buggy any more.

I guess I don’t understand how coop is working. In the case of sleep, it seems to return early when the budget is used up? (coop::poll_proceed returns Pending, thus ready! returns)

Yes, that's right, though that should result in Pending being propagated all the way up to the executor, which then resets the budget and immediately polls again (if there are no other futures to poll). So the question is really why the coop budget is always exhausted by the time you get to polling the sleep. The budget is only decremented when you poll a "leaf future" (like sleep or Receiver::recv) and it returns Ready, so this suggests that somewhere in your code a large number of leaf futures are polled any time the top-level task is polled. Are you calling sleep in a loop or something like that?

In the case that budget is left and the sleep finished, it calls made_progress, which resets the budget, so sleep does not use any budget.

Ah, no, quite the opposite. The default behavior is that dropping coop resets the budget — only if made_progress is called is the budget actually decremented. The intuition here is that we don't want to "pay" out of the budget if the future did not make progress. So, if poll_elapsed returns Pending, then made_progress is not call, and therefore the budget is reset, which means that the call to poll_elapsed did not spend out of the budget.

You can see the relevant code here:

tokio/tokio/src/coop.rs

Lines 156 to 173 in 3e5a0a7

	impl RestoreOnPending {
	pub(crate) fn made_progress(&self) {
	self.0.set(Budget::unconstrained());
	}
	}
	impl Drop for RestoreOnPending {
	fn drop(&mut self) {
	// Don't reset if budget was unconstrained or if we made progress.
	// They are both represented as the remembered budget being unconstrained.
	let budget = self.0.get();
	if !budget.is_unconstrained() {
	CURRENT.with(|cell| {
	cell.set(budget);
	});
	}
	}
	}

That means, if I poll enough sleeps with a short enough sleep time that they are always ready, I never use up the budget?

It's the other way around. If you poll sleeps that are always ready, every time they're ready your budget gets decremented. If, on the other hand, you create a very long sleep that is basically never ready, then polling it does not consume any of your budget.

[Flakebi]

It's the other way around.

Ah, right, I knew I missed something. Thanks for the explanation!

It seems like the Pending never gets to the executor, it’s stuck at 0. I’ll keep debugging.

[Flakebi]

I got a little further, in my case it is not actually a deadlock, it just takes a minute to finish and I never waited that long.
What I can observe:

1. Disabled coop: 132 ms
2. Enabled coop: 54286 ms (411x)

Reading the futures issue @jonhoo linked above, I think I can infer the reason. If the budget is exhausted, tokio’s leaf futures return Pending but instantly wake themselves again. FuturesUnordered keeps polling futures if they are woken, even if they just returned Pending. Having a leaf future inside FuturesUnordered would create a deadlock if the budget is exhausted, weren’t it for the fact that FuturesUnordered bails out after unsuccessfully polling for 32 times.

According to the stacktrace I captured, there are 6 nested layers of FuturesUnordered. Every layer will poll 32 times until returning, which makes 32⁶ = 1,073,741,824 polls that do nothing.

[Darksonn]

I see. Well, FuturesUnordered probably should not be doing that.

That said, I have considered if the coop system should turn itself off automatically if the task keeps polling the future. Thoughts?