Async task is never executed when a CPU demanding task yields back regularly

[zhulik]

Hello,

I recently tried to write a ruby script which was supposed to mix async tasks and some CPU intensive calculations. I found out that an async task was not executed even though the CPU intensive part of the script yielded control regularly

I narrowed it down to a simple script that reliably reproduces the issue.

Async do |task|
  Async do |task|
    loop do
      Console.logger.warn("Log") { "Message" }

      task.sleep(1)
    end
  end

  loop do
    50000.downto(1).inject(:*) # Whatever CPU intensive calculations for 0.5s
    task.yield
  end
end

OS: Arch Linux latest Async version: 2.3.1 Ruby version: 3.2.0 installed with asdf

Expected behavior: "Message" is printed more or less regularly Observed behavior: "Message" is never printed

Adding a tiny sleep after task.yield makes it work, but blocks from reaching the desired performance

[ioquatix]

I will investigate the issue, but the first advice is to use a thread for CPU intensive work. Thread#join is event driven in the scheduler.

[ioquatix]

It looks like a bug with the io_uring backend. With the following test code:

require_relative 'lib/async'

Async do |task|
  Async do |task|
    clock = Async::Clock.start
    total = 0.0
    loop do
      task.sleep(1.0)
      total += 1.0

      Console.logger.warn(self, "sleep drift: #{clock.total - total}")
    end
  end

  loop do
    50000.downto(1).inject(:*) # Whatever CPU intensive calculations for 0.5s
    task.yield
  end
end

$ IO_EVENT_SELECTOR=EPoll ruby test.rb
  0.0s     warn: Object [oid=0x50] [ec=0x64] [pid=334809] [2023-01-06 13:08:31 +1300]
               | sleep drift: 0.23215503804385662
 1.21s     warn: Object [oid=0x50] [ec=0x64] [pid=334809] [2023-01-06 13:08:32 +1300]
               | sleep drift: 0.43828919099178165
 2.41s     warn: Object [oid=0x50] [ec=0x64] [pid=334809] [2023-01-06 13:08:33 +1300]
               | sleep drift: 0.6448842060053721
 3.63s     warn: Object [oid=0x50] [ec=0x64] [pid=334809] [2023-01-06 13:08:35 +1300]
               | sleep drift: 0.8637306360178627
 4.84s     warn: Object [oid=0x50] [ec=0x64] [pid=334809] [2023-01-06 13:08:36 +1300]
               | sleep drift: 1.0737416759948246

so generally it's working, it's just something odd with the io_uring backend. Further investigation is needed.

[ioquatix]

I have narrowed it down to the implementation in io-event.

block(, #<Fiber:0x00007f1873576b28 /home/samuel/Projects/socketry/async/lib/async/task.rb:244 (resumed)>, 1.0)
.
IO_Event_Selector_URing_yield enter
select_process_completions(completed=0)
IO_Event_Selector_URing_select
IO_Event_Selector_URing_yield exit
.
IO_Event_Selector_URing_yield enter
select_process_completions(completed=0)
IO_Event_Selector_URing_select
IO_Event_Selector_URing_yield exit
.
IO_Event_Selector_URing_yield enter
select_process_completions(completed=0)
IO_Event_Selector_URing_select
after(1.0) -> resume
IO_Event_Selector_URing_io_write(2)
io_write:io_uring_prep_write(fiber=0x7f1873576b28)
IO_Event_Selector_URing_yield exit
.

[ioquatix]

Okay, I've narrowed down then issue to the pending event queue / flushing behaviour. I've got a fix for it.

[ioquatix]

Okay the fix was released in io-event v1.1.5.

[zhulik]

Thanks! I'll test in a few hours and close the issue

[zhulik]

Everything is great, thanks again!