io_uring timeout may overrun significantly.

[toziegler]

On Ubuntu kernel 7.0.0-22-generic, a submitted 10 ms io_uring timeout very
rarely blocks for hundreds of milliseconds:

expected timeout: 10 ms observed waits: 224 939 ms

In my testing I could see this with both:

• IORING_ENTER_GETEVENTS | IORING_ENTER_EXT_ARG
• classic IORING_OP_TIMEOUT

A minimal reproducer with one permanently pending POLL_ADD and repeated timeout waits reproduces the issue (an outstanding RECV also did reproduce it).
Example of the reproducer: SLOW iteration=327214 wait=939.594ms

With strace I could see observe the following:
io_uring_enter(... IORING_ENTER_GETEVENTS ...) <0.897755>

System-wide rtla timerlat showed low normal timer latency, with maxima around 24 us.

[toziegler]

Here is the reproducer. Unfortunately it took multiple hours to see this behavior, that's why there is not more information on the PR:

/*
 * liburing equivalent of io_uring_timeout_repro.zig.
 *
 * Build (requires the liburing development package):
 *   cc -O2 -Wall -Wextra io_uring_timeout_repro.c \
 *      -luring -o io_uring_timeout_repro_c
 *
 * Run forever, or pass an iteration count:
 *   ./io_uring_timeout_repro_c 0
 */

#define _GNU_SOURCE
#include <errno.h>
#include <inttypes.h>
#include <poll.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/eventfd.h>
#include <time.h>
#include <unistd.h>

#include <liburing.h>

enum {
  RUN_DURATION_NS = 10 * 1000 * 1000,
  SLOW_DURATION_NS = 50 * 1000 * 1000,
  REPORT_EVERY = 1000,
};

static uint64_t now_ns(clockid_t clock_id) {
  struct timespec ts;
  if (clock_gettime(clock_id, &ts) != 0) {
    perror("clock_gettime");
    exit(EXIT_FAILURE);
  }
  return (uint64_t)ts.tv_sec * 1000000000ull + (uint64_t)ts.tv_nsec;
}

static double milliseconds(uint64_t ns) { return (double)ns / 1000000.0; }

static void die_uring(const char *what, int ret) {
  fprintf(stderr, "%s: %s (%d)\n", what, strerror(-ret), ret);
  exit(EXIT_FAILURE);
}

int main(int argc, char **argv) {
  if (argc > 2) {
    fprintf(stderr, "usage: %s [iterations, 0=forever]\n", argv[0]);
    return EXIT_FAILURE;
  }

  uint64_t iteration_limit = 0;
  if (argc > 1) {
    char *end = NULL;
    errno = 0;
    iteration_limit = strtoull(argv[1], &end, 10);
    if (errno != 0 || end == argv[1] || *end != '\0' || argv[1][0] < '0' ||
        argv[1][0] > '9') {
      fprintf(stderr, "invalid iteration count: %s\n", argv[1]);
      return EXIT_FAILURE;
    }
  }

  struct io_uring ring;
  int ret = io_uring_queue_init(8, &ring, 0);
  if (ret < 0)
    die_uring("io_uring_queue_init", ret);
  if (!(ring.features & IORING_FEAT_EXT_ARG)) {
    fprintf(stderr, "IORING_FEAT_EXT_ARG is unavailable\n");
    io_uring_queue_exit(&ring);
    return EXIT_FAILURE;
  }

  printf("kernel=");
  fflush(stdout);
  FILE *version = fopen("/proc/sys/kernel/osrelease", "r");
  if (version) {
    char release[128] = {0};
    if (fgets(release, sizeof(release), version)) {
      release[strcspn(release, "\n")] = '\0';
      printf("%s", release);
    }
    fclose(version);
  } else {
    printf("unknown");
  }
#if defined(IO_URING_VERSION_MAJOR) && defined(IO_URING_VERSION_MINOR)
  printf(" liburing=%u.%u", (unsigned)IO_URING_VERSION_MAJOR,
         (unsigned)IO_URING_VERSION_MINOR);
#else
  printf(" liburing=unknown");
#endif
  printf(" timeout=10ms slow_threshold=50ms pending_poll=true\n");
  fflush(stdout);

  int event_fd = eventfd(0, EFD_CLOEXEC);
  if (event_fd < 0) {
    perror("eventfd");
    io_uring_queue_exit(&ring);
    return EXIT_FAILURE;
  }

  struct io_uring_sqe *sqe = io_uring_get_sqe(&ring);
  if (!sqe)
    die_uring("io_uring_get_sqe", -EAGAIN);
  io_uring_prep_poll_add(sqe, event_fd, POLLIN);
  io_uring_sqe_set_data64(sqe, 1);
  ret = io_uring_submit(&ring);
  if (ret != 1)
    die_uring("io_uring_submit", ret < 0 ? ret : -EIO);

  uint64_t iterations = 0, slow = 0, interrupted = 0;
  uint64_t maximum_run_ns = 0, maximum_enter_ns = 0;

  while (iteration_limit == 0 || iterations < iteration_limit) {
    const uint64_t run_started = now_ns(CLOCK_BOOTTIME);
    const uint64_t run_started_monotonic = now_ns(CLOCK_MONOTONIC);
    const uint64_t deadline = run_started + RUN_DURATION_NS;
    uint64_t iteration_interrupted = 0;
    uint64_t enter_total_ns = 0, enter_total_monotonic_ns = 0;
    uint64_t enter_max_ns = 0, enter_max_monotonic_ns = 0, enters = 0;
    uint64_t current = run_started;

    while (current < deadline) {
      const uint64_t wait_ns = deadline - current;
      struct __kernel_timespec timeout = {
          .tv_sec = (time_t)(wait_ns / 1000000000ull),
          .tv_nsec = (long)(wait_ns % 1000000000ull),
      };
      struct io_uring_cqe *cqe = NULL;
      int wait_ret;
      do {
        const uint64_t enter_started = now_ns(CLOCK_BOOTTIME);
        const uint64_t enter_started_monotonic = now_ns(CLOCK_MONOTONIC);
        wait_ret = io_uring_wait_cqes(&ring, &cqe, 1, &timeout, NULL);
        const uint64_t enter_elapsed = now_ns(CLOCK_BOOTTIME) - enter_started;
        const uint64_t enter_elapsed_monotonic =
            now_ns(CLOCK_MONOTONIC) - enter_started_monotonic;
        enters++;
        enter_total_ns += enter_elapsed;
        enter_total_monotonic_ns += enter_elapsed_monotonic;
        if (enter_elapsed > enter_max_ns)
          enter_max_ns = enter_elapsed;
        if (enter_elapsed_monotonic > enter_max_monotonic_ns)
          enter_max_monotonic_ns = enter_elapsed_monotonic;
        if (wait_ret == -EINTR) {
          interrupted++;
          iteration_interrupted++;
        }
      } while (wait_ret == -EINTR);

      if (wait_ret != -ETIME && wait_ret < 0)
        die_uring("io_uring_wait_cqes", wait_ret);
      if (cqe) {
        io_uring_cqe_seen(&ring, cqe);
        fprintf(stderr, "unexpected completion\n");
        return EXIT_FAILURE;
      }
      current = now_ns(CLOCK_BOOTTIME);
    }

    const uint64_t run_elapsed = now_ns(CLOCK_BOOTTIME) - run_started;
    const uint64_t run_elapsed_monotonic =
        now_ns(CLOCK_MONOTONIC) - run_started_monotonic;
    iterations++;
    if (run_elapsed > maximum_run_ns)
      maximum_run_ns = run_elapsed;
    if (enter_max_ns > maximum_enter_ns)
      maximum_enter_ns = enter_max_ns;

    if (run_elapsed >= SLOW_DURATION_NS) {
      slow++;
      printf("SLOW iteration=%" PRIu64 " run_boot=%.3fms run_mono=%.3fms "
             "enter_boot_total=%.3fms enter_mono_total=%.3fms "
             "enter_boot_max=%.3fms enter_mono_max=%.3fms enters=%" PRIu64
             " interrupted_iteration=%" PRIu64
             " interrupted_total=%" PRIu64 "\n",
             iterations, milliseconds(run_elapsed),
             milliseconds(run_elapsed_monotonic), milliseconds(enter_total_ns),
             milliseconds(enter_total_monotonic_ns), milliseconds(enter_max_ns),
             milliseconds(enter_max_monotonic_ns), enters,
             iteration_interrupted, interrupted);
      fflush(stdout);
    }
    if (iterations % REPORT_EVERY == 0 || iterations == iteration_limit) {
      printf("iterations=%" PRIu64 " slow=%" PRIu64
             " interrupted_total=%" PRIu64
             " max_run=%.3fms max_enter=%.3fms\n",
             iterations, slow, interrupted, milliseconds(maximum_run_ns),
             milliseconds(maximum_enter_ns));
      fflush(stdout);
    }
  }

  close(event_fd);
  io_uring_queue_exit(&ring);
  return EXIT_SUCCESS;
}

[krisman]

Interesting. I assume this is not a VM with limited resources and the host is otherwise idle?

Anything in dmesg from lockup detector? io_uring_enter with GET_EVENTS will block waiting for events. The question is, did the poll not arrive in time or did we block somewhere else in io_uring? I'd say the first is much more likely.

The second can be easily tested. The following bpftrace will show everywhere the io_uring syscall path blocked. just save it as find-scheds.bt and run your code like:

sudo bpftrace ~/find-scheds.bt -c ./reproducer

I'd also patch your example to terminate as soon as the first slowdown triggers.

I'll try it on a vm, but since it takes very long to reproduce, it might be useful if you collect the data too.

find-scheds.bt :
`tracepoint:syscalls:sys_enter_io_uring_enter /pid == cpid/ {
@io_uring_enter[tid] = 1;
}
tracepoint:syscalls:sys_exit_io_uring_enter /@io_uring_enter[tid]/{
delete(@io_uring_enter[tid]);

}

tracepoint:sched:sched_switch /@io_uring_enter[tid]/ {
if (@io_uring_enter[tid]) {
@[kstack] = count();
@sleep_start[tid] = nsecs;
}
}

tracepoint:sched:sched_wakeup /@io_uring_enter[args.pid]/ {
if (@io_uring_enter[args.pid]) {
$delay_ms = ((nsecs - @sleep_start[args.pid]) / 1000000);
@pool_delay_ms = lhist($delay_ms, 1000, 2000, 1);
delete(@sleep_start[tid]);
if ($delay_ms > 50) {
printf("wakeup took too long");
}
}
}

`

[toziegler]

Thanks for the help! Apologies it took me so long to follow up, I lost access to my machine, and it took me some time to get it back and to reproduce the issue again.

The dmesg output looked good to me. However, I was able to reproduce the issue successfully.

Here are the results:

SLOW iteration=33289 run_boot=876.249ms run_mono=876.249ms enter_boot_total=876.249ms enter_mono_total=876.248ms enter_boot_max=876.249ms enter_mono_max=876.248ms enters=1 interrupted=0
SLOW wakeup tid=8938 sleep_ms=876


@sleep_delay_ms:
[0, 10)              214 |                                                    |
[10, 20)           33073 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[20, 30)               1 |                                                    |
[30, 40)               0 |                                                    |
[40, 50)               0 |                                                    |
[50, 60)               0 |                                                    |
[60, 70)               0 |                                                    |
[70, 80)               0 |                                                    |
[80, 90)               0 |                                                    |
[90, 100)              0 |                                                    |
[100, 110)             0 |                                                    |
[110, 120)             0 |                                                    |
[120, 130)             0 |                                                    |
[130, 140)             0 |                                                    |
[140, 150)             0 |                                                    |
[150, 160)             0 |                                                    |
[160, 170)             0 |                                                    |
[170, 180)             0 |                                                    |
[180, 190)             0 |                                                    |
[190, 200)             0 |                                                    |
[200, 210)             0 |                                                    |
[210, 220)             0 |                                                    |
[220, 230)             0 |                                                    |
[230, 240)             0 |                                                    |
[240, 250)             0 |                                                    |
[250, 260)             0 |                                                    |
[260, 270)             0 |                                                    |
[270, 280)             0 |                                                    |
[280, 290)             0 |                                                    |
[290, 300)             0 |                                                    |
[300, 310)             0 |                                                    |
[310, 320)             0 |                                                    |
[320, 330)             0 |                                                    |
[330, 340)             0 |                                                    |
[340, 350)             0 |                                                    |
[350, 360)             0 |                                                    |
[360, 370)             0 |                                                    |
[370, 380)             0 |                                                    |
[380, 390)             0 |                                                    |
[390, 400)             0 |                                                    |
[400, 410)             0 |                                                    |
[410, 420)             0 |                                                    |
[420, 430)             0 |                                                    |
[430, 440)             0 |                                                    |
[440, 450)             0 |                                                    |
[450, 460)             0 |                                                    |
[460, 470)             0 |                                                    |
[470, 480)             0 |                                                    |
[480, 490)             0 |                                                    |
[490, 500)             0 |                                                    |
[500, 510)             0 |                                                    |
[510, 520)             0 |                                                    |
[520, 530)             0 |                                                    |
[530, 540)             0 |                                                    |
[540, 550)             0 |                                                    |
[550, 560)             0 |                                                    |
[560, 570)             0 |                                                    |
[570, 580)             0 |                                                    |
[580, 590)             0 |                                                    |
[590, 600)             0 |                                                    |
[600, 610)             0 |                                                    |
[610, 620)             0 |                                                    |
[620, 630)             0 |                                                    |
[630, 640)             0 |                                                    |
[640, 650)             0 |                                                    |
[650, 660)             0 |                                                    |
[660, 670)             0 |                                                    |
[670, 680)             0 |                                                    |
[680, 690)             0 |                                                    |
[690, 700)             0 |                                                    |
[700, 710)             0 |                                                    |
[710, 720)             0 |                                                    |
[720, 730)             0 |                                                    |
[730, 740)             0 |                                                    |
[740, 750)             0 |                                                    |
[750, 760)             0 |                                                    |
[760, 770)             0 |                                                    |
[770, 780)             0 |                                                    |
[780, 790)             0 |                                                    |
[790, 800)             0 |                                                    |
[800, 810)             0 |                                                    |
[810, 820)             0 |                                                    |
[820, 830)             0 |                                                    |
[830, 840)             0 |                                                    |
[840, 850)             0 |                                                    |
[850, 860)             0 |                                                    |
[860, 870)             0 |                                                    |
[870, 880)             1 |                                                    |

@switch_stacks[
        perf_trace_sched_switch+20
        __schedule+1144
        preempt_schedule_irq+56
        raw_irqentry_exit_cond_resched+49
        irqentry_exit+46
        sysvec_reschedule_ipi+108
        asm_sysvec_reschedule_ipi+27
        io_cqring_wait+533
        __do_sys_io_uring_enter+721
        __x64_sys_io_uring_enter+34
        x64_sys_call+6992
        do_syscall_64+277
        entry_SYSCALL_64_after_hwframe+118
]: 1
@switch_stacks[
        perf_trace_sched_switch+20
        __schedule+1144
        preempt_schedule_irq+56
        raw_irqentry_exit_cond_resched+49
        irqentry_exit+46
        sysvec_reschedule_ipi+108
        asm_sysvec_reschedule_ipi+27
        trace_syscall_exit+84
        do_syscall_64+1191
        entry_SYSCALL_64_after_hwframe+118
]: 1
@switch_stacks[
        perf_trace_sched_switch+20
        __schedule+1144
        schedule+39
        io_cqring_wait+1824
        __do_sys_io_uring_enter+721
        __x64_sys_io_uring_enter+34
        x64_sys_call+6992
        do_syscall_64+277
        entry_SYSCALL_64_after_hwframe+118
]: 33289

[toziegler]

Another interesting observation is that this does not occur when /dev/cpu_dma_latency is set to 0. Ofc, only based on empirical observation, so better treat it as another hint rather than fact.