tokio::time::sleep has ~19ms overhead on BSD

[WhyNotHugo]

Version

bsd_timer_reproducer v0.1.0 (/tmp/minimal_reproducer)
└── tokio v1.52.2
    ├── bytes v1.11.1
    ├── libc v0.2.186
    ├── mio v1.2.0
    │   └── libc v0.2.186
    ├── parking_lot v0.12.5
    │   ├── lock_api v0.4.14
    │   │   └── scopeguard v1.2.0
    │   └── parking_lot_core v0.9.12
    │       ├── cfg-if v1.0.4
    │       ├── libc v0.2.186
    │       └── smallvec v1.15.1
    ├── pin-project-lite v0.2.17
    ├── signal-hook-registry v1.4.8
    │   ├── errno v0.3.14
    │   │   └── libc v0.2.186
    │   └── libc v0.2.186
    ├── socket2 v0.6.3
    │   └── libc v0.2.186
    └── tokio-macros v2.7.0 (proc-macro)
        ├── proc-macro2 v1.0.106
        │   └── unicode-ident v1.0.24
        ├── quote v1.0.45
        │   └── proc-macro2 v1.0.106 (*)
        └── syn v2.0.117
            ├── proc-macro2 v1.0.106 (*)
            ├── quote v1.0.45 (*)
            └── unicode-ident v1.0.24

I originally reproduced this with an older version of tokio; it doesn't seem to be a recent bug.

Platform

BSD. uname -a yields OpenBSD prophecy.whynothugo.nl 7.8 GENERIC.MP#54 amd64

Description

tokio::time::sleep has an ~19ms overhead. When sleeping for short amounts of time (e.g.: in the order of 30ms), this completely breaks any logic relying on sleep.

I tried this code:

use std::time::Duration;
use tokio::time::{sleep, Instant};

#[tokio::main]
async fn main() {
    let timeout = Duration::from_millis(40);

    println!("Running {}ms timers.", timeout.as_millis());
    for _run in 1..=10 {
        let start = Instant::now();
        sleep(timeout).await;
        let end = Instant::now();

        println!("duration: {}ms", end.duration_since(start).as_millis());
    }

}

I expected to see this happen: durations of aprox 40ms.

Instead, this happened: sample output:

Running 40ms timers.
duration: 53ms
duration: 59ms
duration: 59ms
duration: 59ms
duration: 59ms
duration: 60ms
duration: 49ms
duration: 59ms
duration: 60ms
duration: 59ms

I'm reproducing this on a i7-13700K.

The overhead seems to be fixed, so a 15ms sleep will sleep 25–30ms:

Running 15ms timers.
duration: 25ms
duration: 29ms
duration: 20ms
duration: 29ms
duration: 29ms
duration: 29ms
duration: 30ms
duration: 30ms
duration: 29ms
duration: 20ms

For reference, attempting to render at 60fps would require submitting frames every 16ms. The overhead in sleep already blows 118% of that budget.

[Darksonn]

This kind of thing is generally due to the OS itself delivering notifications slowly to Tokio. I would suggest seeing if you can configure OpenBSD differently.

[WhyNotHugo]

An equivalent program in C has an ~9ms overhead:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/types.h>
#include <sys/event.h>
#include <unistd.h>

int main(void) {
	const int timeout_ms = 40;
	const int iterations = 10;
	struct timespec ts = {
		.tv_sec = 0,
		.tv_nsec = timeout_ms * 1000000
	};

	printf("Running %dms timers.\n", timeout_ms);

	int kq = kqueue();
	if (kq == -1) {
		perror("kqueue");
		return 1;
	}

	struct kevent ev;
	EV_SET(&ev, 1, EVFILT_TIMER, EV_ADD | EV_ENABLE, 0, timeout_ms, NULL);

	for (int i = 0; i < iterations; i++) {
		struct timespec start, end;
		clock_gettime(CLOCK_MONOTONIC, &start);

		struct kevent changed;
		if (kevent(kq, &ev, 1, &changed, 1, NULL) == -1) {
			perror("kevent");
			close(kq);
			return 1;
		}

		clock_gettime(CLOCK_MONOTONIC, &end);

		long duration_ms = (end.tv_sec - start.tv_sec) * 1000 + (end.tv_nsec - start.tv_nsec) / 1000000;
		printf("duration: %ldms\n", duration_ms);
	}

	close(kq);
	return 0;
}

It's way too much, but it's also half of the overhead of the Rust equivalent.

[Darksonn]

For a more direct comparison, please wrap the loop in tokio::spawn so that it executes on an ordinary task, rather than in the block_on task.

[WhyNotHugo]

I don't quite follow. The entire loop runs the same main. Shouldn't it all run within the same task?

Updated reproducer:

use std::time::Duration;
use tokio::time::{sleep, Instant};

#[tokio::main]
async fn main() {
    let timeout = Duration::from_millis(40);

    println!("Running {}ms timers.", timeout.as_millis());
    for _run in 1..=10 {
        tokio::spawn(async move {
            let start = Instant::now();
            sleep(timeout).await;
            let end = Instant::now();

            println!("duration: {}ms", end.duration_since(start).as_millis());
        })
        .await
        .unwrap();
    }
}

Same results:

Running 40ms timers.
duration: 52ms
duration: 59ms
duration: 59ms
duration: 59ms
duration: 59ms
duration: 59ms
duration: 49ms
duration: 59ms
duration: 59ms
duration: 59ms

[Darksonn]

The contents of the #[tokio::main] macro runs under block_on, which doesn't quite work the same way as tokio::spawn. So I meant to move the entire function body.

Also, Tokio passes the timeout as the last parameter to kevent, which you passed as NULL, so it's not entirely apples-to-apples for that reason either.

[WhyNotHugo]

	struct kevent ev;
	EV_SET(&ev, 0, EVFILT_TIMER, EV_ADD, 0, 100000000000, NULL);
	if (kevent(kq, &ev, 1, NULL, 0, NULL) == -1) {
		perror("kevent");
		return 1;
	}

	for (int i = 0; i < iterations; i++) {
		struct timeval start, end;
		gettimeofday(&start, NULL);

		struct timespec timeout;
		timeout.tv_sec = 0;
		timeout.tv_nsec = timeout_ms  * 1000000;

		struct kevent output_ev;
		kevent(kq, NULL, 0, &output_ev, 1, &timeout);

		gettimeofday(&end, NULL);

		long duration_ms = (end.tv_sec - start.tv_sec) * 1000 + (end.tv_usec - start.tv_usec) / 1000;
		printf("duration: %ldms\n", duration_ms);
	}

Also yields a ~9ms overhead. Obviously there's still a non-tokio issue here for the 9ms overhead in this case. Still not sure why tokio's overhead is even more.

[akshatmahla]

I tried this in mac m5:

Running 40ms timers.
duration: 42ms
duration: 42ms
duration: 42ms
duration: 42ms
duration: 42ms
duration: 42ms
duration: 41ms
duration: 42ms
duration: 42ms
duration: 41ms

[WhyNotHugo]

@akshatmahla On what OS was this?

So far, this seems to reproduce only in OpenBSD.