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

Mutex sleeps indefinitely with timeout <= 0.0001 seconds #4862

Closed
camlow325 opened this issue Nov 21, 2017 · 5 comments
Closed

Mutex sleeps indefinitely with timeout <= 0.0001 seconds #4862

camlow325 opened this issue Nov 21, 2017 · 5 comments
Milestone
JRuby 9.1.15.0

Comments

@camlow325
Copy link
Contributor

Environment

Provide at least:

  • JRuby version (jruby -v) and command line (flags, JRUBY_OPTS, etc)

JRuby 9.1.14.0

  • Operating system and platform (e.g. uname -a)

Windows

Expected Behavior

  • Describe your expectation of how JRuby should behave, perhaps by showing how CRuby/MRI behaves.

When sleep() is called with a timeout which is 0.0001 or less (including 0) seconds on a locked mutex, the sleep() appears to be indefinite. For MRI 2.4.2, however, the sleep times out quickly with these smaller values.

  • Provide an executable Ruby script or a link to an example repository.

I ran the following script to reproduce this issue:

m = Mutex.new
m.synchronize do
  [0.001, 0.0001, 0].each do |timeout|
    puts "About to sleep for #{timeout} seconds..."
    m.sleep(timeout)
    puts "Done sleeping for #{timeout} seconds"
  end
end

With MRI 2.4.2, the following output appears and the script ends normally:

About to sleep for 0.001 seconds...
Done sleeping for 0.001 seconds
About to sleep for 0.0001 seconds...
Done sleeping for 0.0001 seconds
About to sleep for 0 seconds...
Done sleeping for 0 seconds

Actual Behavior

  • Describe or show the actual behavior.

With JRuby 9.1.14.0, only part of the output appears:

About to sleep for 0.001 seconds...
Done sleeping for 0.001 seconds
About to sleep for 0.0001 seconds...

Even after leaving the script running for several minutes, the next expected message never appears: "Done sleeping for 0.0001 seconds". The same apparent hang appears if a sleep for 0 seconds - without the preceding sleep for 0.0001 seconds - occurs.

Here is a backtrace for the main thread while in the hang state:

"main" #1 prio=5 os_prio=0 tid=0x000000000355e000 nid=0x7ff0 waiting on condition [0x000000000375d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000e0efc748> (a java.util.concurrent.Semaphore$NonfairSync)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
        at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
        at org.jruby.RubyThread$SleepTask2.run(RubyThread.java:1445)
        at org.jruby.RubyThread$SleepTask2.run(RubyThread.java:1434)
        at org.jruby.RubyThread.executeTask(RubyThread.java:1486)
        at org.jruby.RubyThread.sleep(RubyThread.java:1354)
        at org.jruby.ext.thread.Mutex.sleep(Mutex.java:135)
        at org.jruby.ext.thread.Mutex$INVOKER$i$sleep.call(Mutex$INVOKER$i$sleep.gen)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:153)
        at C_3a_.mutex_sleep.invokeOther4:sleep(mutex_sleep.rb:5)
        at C_3a_.mutex_sleep.RUBY$block$\=mutex_sleep\,rb$1(mutex_sleep.rb:5)
        at java.lang.invoke.LambdaForm$DMH/468121027.invokeStatic_L8_L(LambdaForm$DMH)
        at java.lang.invoke.LambdaForm$MH/422392391.invokeExact_MT(LambdaForm$MH)
        at org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
        at org.jruby.runtime.BlockBody.yield(BlockBody.java:114)
        at org.jruby.runtime.Block.yield(Block.java:165)
        at org.jruby.RubyArray.each(RubyArray.java:1734)
        at org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:308)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:137)
        at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:142)
        at C_3a_.mutex_sleep.invokeOther12:each(mutex_sleep.rb:3)
        at C_3a_.mutex_sleep.RUBY$block$\=mutex_sleep\,rb$0(mutex_sleep.rb:3)
        at java.lang.invoke.LambdaForm$DMH/468121027.invokeStatic_L8_L(LambdaForm$DMH)
        at java.lang.invoke.LambdaForm$MH/422392391.invokeExact_MT(LambdaForm$MH)
        at org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
        at org.jruby.runtime.IRBlockBody.yieldSpecific(IRBlockBody.java:80)
        at org.jruby.runtime.Block.yieldSpecific(Block.java:134)
        at org.jruby.ext.thread.Mutex.synchronize(Mutex.java:148)
        at org.jruby.ext.thread.Mutex$INVOKER$i$0$0$synchronize.call(Mutex$INVOKER$i$0$0$synchronize.gen)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:308)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:137)
        at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:142)
        at C_3a_.mutex_sleep.invokeOther15:synchronize(mutex_sleep.rb:2)
        at C_3a_.mutex_sleep.RUBY$script(mutex_sleep.rb:2)
        at java.lang.invoke.LambdaForm$DMH/1450495309.invokeStatic_L7_L(LambdaForm$DMH)
        at java.lang.invoke.LambdaForm$BMH/84739718.reinvoke(LambdaForm$BMH)
        at java.lang.invoke.LambdaForm$MH/632249781.invoker(LambdaForm$MH)
        at java.lang.invoke.LambdaForm$MH/434176574.invokeExact_MT(LambdaForm$MH)
        at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)
        at org.jruby.ir.Compiler$1.load(Compiler.java:95)
        at org.jruby.Ruby.runScript(Ruby.java:828)
        at org.jruby.Ruby.runNormally(Ruby.java:747)
        at org.jruby.Ruby.runNormally(Ruby.java:765)
        at org.jruby.Ruby.runFromMain(Ruby.java:578)
        at org.jruby.Main.doRunFromMain(Main.java:417)
        at org.jruby.Main.internalRun(Main.java:305)
        at org.jruby.Main.run(Main.java:232)
        at org.jruby.Main.main(Main.java:204

I had some code which would sleep for 0 seconds periodically to allow a waiter to take the mutex and change some state to interrupt a long running process. Bumping the timeout up to a slightly higher value - like 0.001 seconds - is a reasonable workaround. Just thought it might be good to point out the discrepancy as compared to MRI Ruby behavior.
@camlow325 camlow325 changed the title Mutex sleeps indefinitely with timeout > 0.0001 seconds Mutex sleeps indefinitely with timeout < 0.0001 seconds Nov 21, 2017
@camlow325 camlow325 changed the title Mutex sleeps indefinitely with timeout < 0.0001 seconds Mutex sleeps indefinitely with timeout <= 0.0001 seconds Nov 21, 2017
@headius
Copy link
Member

headius commented Nov 21, 2017

This sleep is likely using the available sleeping options from the JDK, most of which have a minimum time of 1ms. Ignoring that, what do you need such small sleep times for? Or are you just trying to get a sleep time that's small enough to not be noticeable but not instantaneous?

@headius
Copy link
Member

headius commented Nov 21, 2017

A simple fix for this would be to detect whether the incoming value is below some ms threshold but nonzero and not sleep at all.

@headius
Copy link
Member

headius commented Nov 21, 2017

I have a fix. Perhaps there's no tests for Mutex that test zero and low-timeout sleeps? o_O

@camlow325
Copy link
Contributor Author

@headius Yeah, I was just using a sleep that was nearly instantaneous to avoid any noticeable overhead but allow a pending lock request from another thread to be serviced, if one is available. A small value like 0.001 would be perfectly fine for my case. I'd just happened to pick 0 initially because it worked fine on MRI. That's great that you've found a fix already. Thanks much for looking into this!

headius added a commit that referenced this issue Nov 21, 2017
@headius
Sleep times in the range (0.001..0.0] should wake up.

Verified

This commit was signed with the committer’s verified signature. The key has expired.
nomadium Miguel Landaeta
GPG key ID: AFB8E0FC9231CC6D
Expired
Verified
Learn about vigilant mode
0c38d21 
Fixes #4862
headius added a commit that referenced this issue Nov 21, 2017
@headius
Add spec for tiny Mutex#sleep times.

Verified

This commit was signed with the committer’s verified signature. The key has expired.
nomadium Miguel Landaeta
GPG key ID: AFB8E0FC9231CC6D
Expired
Verified
Learn about vigilant mode
ff9a618 
See #4862
@headius
Copy link
Member

headius commented Nov 21, 2017

@camlow325 I have committed a patch that I believe does what you want it to: it always release and re-acquire the lock, but for sleep values smaller than the JDK's lock sleep granularity it will not bother to attempt to sleep.

Spec added for tiny Mutex#sleep times as well.

Thanks for the report! I find it incredible that nobody has reported it before.

@headius headius closed this as completed Nov 21, 2017
eregon pushed a commit to ruby/spec that referenced this issue Dec 1, 2017
@headius @eregon
Add spec for tiny Mutex#sleep times.

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature. The key has expired.
GPG key ID: 4AEE18F83AFDEB23
Expired
Verified
Learn about vigilant mode
12ab462 
See jruby/jruby#4862
@enebo enebo added this to the JRuby 9.1.15.0 milestone Dec 7, 2017
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
JRuby 9.1.15.0
Development

No branches or pull requests
3 participants
@headius @enebo @camlow325