"Async::Semaphore#async allows tasks to execute concurrently" on async-1.x fails with slow CPU/low-res timer

[matoro]

Hi, with async-1.x the test "Async::Semaphore#async allows tasks to execute concurrently" fails when run on a system with a slow CPU and/or low-resolution timers. The same test passes in async-2.x on the same system.

Tested async-1.30.3, async-1.31.0 with ruby 2.7, ruby 3.0, ruby 3.1, all exhibit the same failure. No 2.x version exhibits the issue.

I thought that https://github.com/socketry/async/commit/f0e520d3f2ab18d767affc0497c1236642aaeb85 might be related so I tried adjusting the sleep times to 0.01 rather than 0.1, but this did not solve the issue.

I can provide shell access on demand if this information is not sufficient. Thanks!

Failures:

  1) Async::Semaphore#async allows tasks to execute concurrently
     Got 2 failures:

     1.1) Failure/Error: expect(order).to be == [0, 1, 2, 0, 1, 2]

            expected: == [0, 1, 2, 0, 1, 2]
                 got:    [0, 1, 2, 2, 0, 1]
          # ./spec/async/semaphore_spec.rb:85:in `block (3 levels) in <top (required)>'
          # ./lib/async/task.rb:261:in `block in make_fiber'

     1.2) Failure/Error: expect(order).to be == [0, 1, 2, 0, 1, 2]

            expected: == [0, 1, 2, 0, 1, 2]
                 got:    [0, 1, 2, 2, 0, 1]
          # ./spec/async/semaphore_spec.rb:85:in `block (3 levels) in <top (required)>'
          # ./lib/async/task.rb:261:in `block in make_fiber'

Finished in 43.58 seconds (files took 22.81 seconds to load)
175 examples, 1 failure, 3 pending

Failed examples:

rspec ./spec/async/semaphore_spec.rb:73 # Async::Semaphore#async allows tasks to execute concurrently

[ioquatix]

I can probably fix this, it looks like the test is probably racy.

[ioquatix]

This should be fixed, do you mind checking it?

[matoro]

This should be fixed, do you mind checking it?

That does fix this specific problem, thank you!

I reran the test suite again and now interestingly everything passes with Ruby 2.7, but I get two failures under Ruby 3.0. The first one is reproducible, while the second one is intermittent. Should I create a new issue for this, or just keep it under this one?

Failures:

  1) Async::Scheduler IO.pipe can send message via pipe
     Failure/Error: DEFAULT_FAILURE_NOTIFIER = lambda { |failure, _opts| raise failure }
       expected `[#<IO:fd 8>].empty?` to be truthy, got false
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-support-3.12.0/lib/rspec/support.rb:102:in `block in <module:Support>'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-support-3.12.0/lib/rspec/support.rb:111:in `notify_failure'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/fail_with.rb:35:in `fail_with'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/handler.rb:40:in `handle_failure'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/handler.rb:56:in `block in handle_matcher'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/handler.rb:27:in `with_matcher'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/expectation_target.rb:65:in `to'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-expectations-3.12.2/lib/rspec/expectations/expectation_target.rb:101:in `to'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-files-1.1.3/lib/rspec/files/leaks.rb:42:in `block (3 levels) in <module:Files>'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-files-1.1.3/lib/rspec/files/leaks.rb:41:in `block (2 levels) in <module:Files>'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:390:in `execute_with'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:352:in `call'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:486:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:468:in `with_around_example_hooks'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:511:in `with_around_and_singleton_context_hooks'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:259:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:646:in `block in run_examples'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:642:in `map'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:642:in `run_examples'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:607:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `block in run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `map'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `map'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/configuration.rb:2070:in `with_suite_hooks'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:116:in `block in run_specs'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/reporter.rb:74:in `report'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:115:in `run_specs'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:89:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:71:in `run'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:45:in `invoke'
     # /usr/lib/ruby/gems/3.0.0/gems/rspec-core-3.12.1/bin/rspec:4:in `<top (required)>'
     # /usr/bin/rspec-3:9:in `load'
     # /usr/bin/rspec-3:9:in `<main>'
     #
     #   Showing full backtrace because every line was filtered out.
     #   See docs for RSpec::Configuration#backtrace_exclusion_patterns and
     #   RSpec::Configuration#backtrace_inclusion_patterns for more information.

  2) Async::Task#sleep can sleep for the requested duration
     Failure/Error: expect(time).to be >= duration

       expected: >= 0.01
            got:    0.007999976980499923
     # ./spec/async/task_spec.rb:314:in `block (3 levels) in <top (required)>'

Finished in 41.45 seconds (files took 6.92 seconds to load)
175 examples, 2 failures, 3 pending

Failed examples:

rspec ./spec/async/scheduler_spec.rb:58 # Async::Scheduler IO.pipe can send message via pipe
rspec ./spec/async/task_spec.rb:300 # Async::Task#sleep can sleep for the requested duration

[ioquatix]

It's okay to keep it under one issue. Let me check what's going on.

[thesamesam]

I can reproduce this too - the patch helps with the original failures, but I get the same sporadic failure with that patch. Most of the time it passes though.

[ioquatix]

Okay, I'm taking a look now.

[ioquatix]

I've improved the robustness of the two mentioned tests. Do you mind checking whether that's fixed the issues you were experiencing?

[thesamesam]

Sure, let me take a look, thanks! 🔬

[ioquatix]

@thesamesam how did you get on?

[ioquatix]

@matoro are you able to try the latest changes to stable-v1?

[matoro]

@matoro are you able to try the latest changes to stable-v1?

If I recall, this issue was on hppa, so I reran this test and strangely everything passed even without the newest commit - tested on ruby 3.0 and 3.1. I'm not sure exactly what could have changed to cause this to mysteriously disappear, but if it works it works and I won't complain :+1:

Just to be safe I also tested with this newest commit and everything still passed, so I'm good to consider this fixed.

[ioquatix]

If it shows up again, please feel free to let me know! (Timing issues and related tests can be super tricky).

[thesamesam]

@thesamesam how did you get on?

Sorry, the container needed upgrading and it took about a day. I also wish I'd said in my original comment which box it was, but I'm pretty certain it was HPPA.

It took me a while to reproduce. I can't reproduce it anymore in our packaging w/ 1.31.0, but I did manage to hit it just now by running rspec manually from a git checkout.

I've now tried stable-v1 repeatedly and I can't hit it anymore, so it looks like it's worked, thank you!

[ioquatix]

Awesome, thanks for all your effort!