Combination of TcpListener::from_std and manual runtime creation makes tokio::spawn one step behind

[vorner]

Version

└── tokio v1.0.1
    └── tokio-macros v1.0.0 (proc-macro)

Full tree:

nospawn v0.1.0 (/home/vorner/nospawn)
├── socket2 v0.3.19
│   ├── cfg-if v1.0.0
│   └── libc v0.2.81
└── tokio v1.0.1
    ├── bytes v1.0.0
    ├── libc v0.2.81
    ├── memchr v2.3.4
    ├── mio v0.7.7
    │   ├── libc v0.2.81
    │   └── log v0.4.11
    │       └── cfg-if v0.1.10
    ├── num_cpus v1.13.0
    │   └── libc v0.2.81
    ├── pin-project-lite v0.2.1
    └── tokio-macros v1.0.0 (proc-macro)
        ├── proc-macro2 v1.0.24
        │   └── unicode-xid v0.2.1
        ├── quote v1.0.8
        │   └── proc-macro2 v1.0.24 (*)
        └── syn v1.0.58
            ├── proc-macro2 v1.0.24 (*)
            ├── quote v1.0.8 (*)
            └── unicode-xid v0.2.1
    [build-dependencies]
    └── autocfg v1.0.1
vorner@charybdis ~/nospawn

Platform

Linux charybdis 5.10.3-charybdis #1 SMP PREEMPT Sat Jan 2 19:52:15 CET 2021 x86_64 Intel(R) Core(TM) i5-8265U CPU @ 1.60GHz GenuineIntel GNU/Linux

Description

I've discovered that under certain conditions, task spawned by tokio::spawn doesn't run right away, but is put to sleep until another task is spawned (and then the next one is put to sleep). I don't seem to be able to get any logging out of tokio itself, but I've managed to somehow minimize what I have (the real problem happened when trying to port spirit-tokio to 1.0).

use std::net::SocketAddr;
use std::time::Instant;

use socket2::{Socket, Type, Domain};
use tokio::net::TcpListener;
use tokio::runtime::Builder;
use tokio::sync::oneshot;
use tokio::io::AsyncWriteExt;

type Error = Box<dyn std::error::Error + Send + Sync>;

fn create_listener() -> Result<TcpListener, Error> {
    let sock = Socket::new(Domain::ipv4(), Type::stream(), None)?;
    sock.set_reuse_address(true)?;
    let addr: SocketAddr = "127.0.0.1:1234".parse().unwrap();
    sock.bind(&addr.into())?;
    sock.listen(128)?;
    TcpListener::from_std(sock.into_tcp_listener()).map_err(From::from)
}

async fn starter(listener: TcpListener) -> Result<(), Error> {
    eprintln!("Starter started");
    let mut i = 0;
    let start = Instant::now();
    let t = move || Instant::now().duration_since(start);
    loop {
        let mut c = listener.accept().await?.0;
        i += 1;
        eprintln!("{:?}, Starting {}", t(), i);
        tokio::spawn(async move {
            eprintln!("{:?}, Started {}", t(), i);
            c.write_all(b"Hello world").await.unwrap();
            eprintln!("{:?}, Done {}", t(), i);
        });
        eprintln!("{:?}, Spawn of {} done", t(), i);
        // Adding this makes it work again
        //tokio::spawn(async {});
    }
}

fn do_init() -> Result<(), Error> {
    let listener = create_listener()?;
    tokio::spawn(starter(listener));
    Ok(())
}

fn main() -> Result<(), Error> {
    let runtime = Builder::new_multi_thread()
        .enable_all()
        .worker_threads(2)
        .max_blocking_threads(2)
        .build()?;
    let _guard = runtime.enter();
    do_init()?;
    let (_s, r) = oneshot::channel::<()>();
    runtime.block_on(r).unwrap();

    Ok(())
}

I'd expect that whenever I start connecting to it on the port 1234, each connection receives a „Hello world“ string and is terminated. The output of the program should look something like this:

Starter started
1.664336238s, Starting 1
1.664370236s, Spawn of 1 done
1.664419469s, Started 1
1.664499009s, Done 1
2.853677555s, Starting 2
2.853793738s, Spawn of 2 done
2.853973184s, Started 2
2.854107723s, Done 2
3.910397251s, Starting 3
3.910516759s, Spawn of 3 done
3.910609779s, Started 3
3.910766635s, Done 3
4.957451408s, Starting 4
4.957568756s, Spawn of 4 done
4.957735347s, Started 4
4.95788227s, Done 4

Instead, each new connection gets initially stuck (nothing happening on it) and the output looks like this:

Starter started
3.158499847s, Starting 1
3.158576249s, Spawn of 1 done
5.312971103s, Starting 2
5.31308098s, Spawn of 2 done
5.313171877s, Started 1
5.31334025s, Done 1
7.860883879s, Starting 3
7.860938604s, Spawn of 3 done
7.861003094s, Started 2
7.861063677s, Done 2
9.443288849s, Starting 4
9.443423441s, Spawn of 4 done
9.443469749s, Started 3
9.443629278s, Done 3
10.769886785s, Starting 5
10.770030951s, Spawn of 5 done
10.770090273s, Started 4
10.77025339s, Done 4

The first connection (and the first spawned task) is executed only after the second connection comes and the second task is spawned.

I've tried playing with the example a little bit and:

• If I use #[tokio::main] instead of this manual runtime creation, the problem disappears.
• If I create the listener directly, instead of going socket2 -> std -> tokio, the problem disappears.
• If I add that commented-out spawn of empty task, the problem disappears (here I guess it's simply flushed by the empty task and the empty task is the one being put to sleep).

[malaire]

Try adding tokio::task::yield_now().await(); after eprintln!("{:?}, Spawn of {} done", t(), i);

The problem here seems to be that tokio tasks are co-operative and each task must await regularly to let other tasks run.

Your starter, after spawning a task, doesn't awaitto let the spawned task run. Instead it goes to accept another connection, and only if there is no connection available will the await there allow other task to run.

[Darksonn]

When creating a TcpListener with from_std, you must make sure to set it in non-blocking mode before converting it. From the documentation:

This function is intended to be used to wrap a TCP listener from the standard library in the Tokio equivalent. The conversion assumes nothing about the underlying listener; it is left up to the user to set it in non-blocking mode.

So to explain your weird behavior, it is because by not setting the socket in non-blocking mode, you are blocking the thread.

[vorner]

Instead it goes to accept another connection, and only if there is no connection available will the await there allow other task to run.

That would be fine, though, as there were no other connections. And it was waiting for them for several seconds.

When creating a TcpListener with from_std, you must make sure to set it in non-blocking mode before converting it.

Ok, thanks, after setting it to non-blocking, it works. Is that something that changed between versions? Because I certainly wasn't doing it in tokio 0.2 and it was working fine (I was porting old code and it started to compile fine, so I assumed everything should just work now). The fact that it works with #[tokio::main] is just because of luck?

Edit: yes, I've found that in 0.2 the from_std did place it into non-blocking mode. Such „silent“ change in behaviour is unfortunate, but I guess it was necessary :-|.

[Darksonn]

Yes, it was one of the breaking changes in the 0.3.0 release. You can find the changelog here.

net: the from_std function on all sockets no longer sets socket into non-blocking mode (#2893)