timeout is buggy in JRuby

[HoneyryderChuck]

First I thought it was celluloid-io sockets, but then I realized that in Jruby, timeouts will not always be triggered. Here is a simple script:

require 'time'
require 'celluloid/io'


class Tester
  include Celluloid::IO
  def initialize
    @sock = TCPSocket.new("localhost", 80)
  end

  def test_timeout
    begin
      timeout(2) do
         # option 1
         # @sock.wait_readable
         # option 2
         # sleep 3
         # option 3 
         loop do
            sleep 1
         end
      end
    rescue Celluloid::Task::TimeoutError
      puts "successfull timeout fetch: #{Time.now}"
      retry
    ensure
      puts "#{$!.class} #{$!.message}" if $!
    end
  end

end


puts "starting the actor..."
t = Tester.new
t.async(:test_timeout)
sleep

# Option 1
# Both MRI 2.1 and jruby 9.0.5.0
....
successfull timeout fetch: 2016-01-27 18:50:47 +0100
successfull timeout fetch: 2016-01-27 18:50:49 +0100
successfull timeout fetch: 2016-01-27 18:50:51 +0100
successfull timeout fetch: 2016-01-27 18:50:53 +0100
successfull timeout fetch: 2016-01-27 18:50:55 +0100
successfull timeout fetch: 2016-01-27 18:50:57 +0100
successfull timeout fetch: 2016-01-27 18:50:59 +0100
successfull timeout fetch: 2016-01-27 18:51:01 +0100


(hangs at some point...)


# Option 2
# MRI 2.1 and JRUBY-9.0.5.0
starting the actor...
successfull timeout fetch: 2016-01-27 18:49:12 +0100
W, [2016-01-27T18:49:15.799990 #328595]  WARN -- : Attempted to resume a dead task: type=:call, meta={:dangerous_suspend=>false, :method_name=>:test_timeout}, status=:dead

Option 3 works in MRI (apparently), but also hangs at some point.

This can seriously hinder celluloid/celluloid-io#170.

[tarcieri]

Yeah, this has been reported several times...

Any ideas @ioquatix?

[ioquatix]

I will investigate the issue, is the above test case failing on MRI 2.3?

[HoneyryderChuck]

didn't test with all possible mri versions. will continue to test today, I'll come up with more results.

[HoneyryderChuck]

maybe this is old news, but I'll state them nonetheless: replacing the Celluloid::IO with a Celluloid actor seems to fix the issues. My bet is now on the evented mailbox.

[HoneyryderChuck]

I've been investigating option 3, which consistently happens in jruby. Something's wrong with the timeout...

I've added a few messages before the reactor selects, and also inside the jruby extension, before select is called on the NIO channel. Here's an example of a successful select:

# on celluloid/io/reactor.rb:59
selecting for 0.9849073000000006 seconds...   
# on ext/nio4r/org/nio4r/Nio4r.java:291
timing out for 984.9073000000006 milliseconds...

Here's where it gets blocked:

selecting for 0.0009740119999985808 seconds...
timing out for 0.9740119999985808 milliseconds

The doSelect() method has a condition stating that if timeout is 0, one calls selectNow() on the NIO channel.

I've patched it by calling selectNow() when the timeout is smaller than 1 millisecond, and it doesn't hang anymore:

/* inside doSelect(), line 290 */
                        long tim = (long)(t * 1000);
                        if (tim < 1) {
                          result = this.selector.selectNow();
                        } else {
                          result = this.selector.select(tim);
                        }
...

Would this be an acceptable patch?

I think the real "problem" still comes from timer, as an interval triggering a message handling is probably so small that the java Runtime can't handle it properly. Or are java NIO channels not able to handle that kind of precision?

[ioquatix]

This could be an okay patch, but I have a request, could you print out values of tim where the bug happens? Is this bug also solved if you change the condition to (tim <= 0)?

[HoneyryderChuck]

@ioquatix I just did:

timing out for 0.9740119999985808 milliseconds

I'm digging a bit more, problem comes from Celluloid::Actor#run, particularly the wait block (line 157).

Timers is passing the wait_interval to the block, and this will be used to check a message from the mailbox. This wait_interval can be apparently very small! I've just tracked the wait_interval:

# these are okay!
checking message: 0.9983331230000001 seconds
checking message: 0.9967141259999996 seconds
# this one is not! that's your block!
checking message: 7.559099999987495e-05 seconds 

that's some precise shit!

Were select system calls ever able to deal with such an interval? Is this just the java way?

[ioquatix]

I wrote the code which generate those intervals, but it was a while ago. Yes, it's possible to generate small intervals.

Did you try with the condition I suggested?

Are you referring to this code in Nio4r?

https://github.com/celluloid/nio4r/blob/8cc48508a7cf3bb8497ba65f15febd691cf5d2a6/ext/nio4r/org/nio4r/Nio4r.java#L284-L291

That code is a bit different from what you quoted above. It uses double rather than long so avoids rounding issues, handles negative values correctly.

[ioquatix]

Can you link me to the code you are looking at w.r.t wait_interval, thanks :)

[ioquatix]

Just FYI, in some cases timers will provide a -ve wait interval if a timer should have fired already (it was late) https://github.com/celluloid/timers/blob/41145ed260e4f061c6b93604c5e0ba86192f37af/lib/timers/group.rb#L81-L90 but I'm not sure if this is used in the code you are talking about or not.

[HoneyryderChuck]

it casts it to a long before calling select, check a few lines below. That's what tim was, the long already converted to milliseconds value that the channel must interpret on the selec call .

I don't think anymore that the interval is the issue, as timers are supposed to be that precise, right? It's as if the NIO channels can't handle that low of an interval.

The code I meant: https://github.com/celluloid/celluloid/blob/master/lib/celluloid/actor.rb#L152-L156

[ioquatix]

When it gets cast to a long, perhaps the result is 0. In that case, some API have sleep indefinitely behaviour when called with 0 (or sometimes -1).

[ioquatix]

So you can see here exactly what I said:

https://docs.oracle.com/javase/7/docs/api/java/nio/channels/Selector.html#select(long)

timeout - If positive, block for up to timeout milliseconds, more or less, while waiting for a channel to become ready; if zero, block indefinitely; must not be negative

So if you call it with 0, clearly it will block forever :D

[ioquatix]

IF you call that API with a negative number, it will return the meaning of life.

[HoneyryderChuck]

The result is not 0, is the one that was printed out in the example above. Are you saying the channel will interpret it as 0 and block forever?