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.

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

Mutex sleeps indefinitely with timeout <= 0.0001 seconds #4862

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

Comments

Projects
None yet
3 participants
@camlow325
Contributor

camlow325 commented Nov 21, 2017

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 from Mutex sleeps indefinitely with timeout > 0.0001 seconds to Mutex sleeps indefinitely with timeout < 0.0001 seconds Nov 21, 2017

@camlow325 camlow325 changed the title from Mutex sleeps indefinitely with timeout < 0.0001 seconds to Mutex sleeps indefinitely with timeout <= 0.0001 seconds Nov 21, 2017

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

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?

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

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

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.

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

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

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

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

This comment has been minimized.

Show comment
Hide comment
@camlow325

camlow325 Nov 21, 2017

Contributor

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

Contributor

camlow325 commented Nov 21, 2017

@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 added a commit that referenced this issue Nov 21, 2017

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

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

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 Nov 21, 2017

eregon added a commit to ruby/spec that referenced this issue Dec 1, 2017

@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