Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
matoro opened this issue Mar 9, 2023 · 14 comments
Closed

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

matoro opened this issue Mar 9, 2023 · 14 comments

Comments

@matoro
Copy link

matoro commented Mar 9, 2023

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 f0e520d 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
Copy link
Member

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

ioquatix added a commit that referenced this issue Mar 12, 2023
@ioquatix
Improve robustness of test, fixes #218.
8f59041
@ioquatix
Copy link
Member

This should be fixed, do you mind checking it?

@matoro
Copy link
Author

matoro commented Mar 20, 2023

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
Copy link
Member

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

@thesamesam
Copy link

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
Copy link
Member

Okay, I'm taking a look now.

ioquatix added a commit that referenced this issue Jun 13, 2023
@ioquatix
More improvements to test, fixes #218.
fe8aa06
@ioquatix
Copy link
Member

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

@thesamesam
Copy link

Sure, let me take a look, thanks! 🔬

@ioquatix
Copy link
Member

@thesamesam how did you get on?

@ioquatix
Copy link
Member

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

@matoro
Copy link
Author

matoro commented Jun 14, 2023

@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 👍

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

@ioquatix
Copy link
Member

ioquatix commented Jun 14, 2023 •
edited

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

@thesamesam
Copy link

thesamesam commented Jun 14, 2023 •
edited

@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
Copy link
Member

Awesome, thanks for all your effort!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ioquatix @thesamesam @matoro