Rack test spec_rack_runtime fails on JRuby due to timing

Rack test spec_rack_runtime fails on JRuby due to timing

[Charles Oliver Nutter]

Hey, the following test currently fails on JRuby, but not for a very
good reason:

  specify "should allow multiple timers to be set" do
    app = lambda { |env| sleep 0.1; [200, {'Content-Type' => 'text/
plain'}, "Hello, World!"] }
    runtime1 = Rack::Runtime.new(app, "App")
    runtime2 = Rack::Runtime.new(runtime1, "All")
    response = runtime2.call({})

    response[1]['X-Runtime-App'].should =~ /[\d\.]+/
    response[1]['X-Runtime-All'].should =~ /[\d\.]+/

    Float(response[1]['X-Runtime-All']).should > Float(response[1]['X-
Runtime-App'])
  end

The test here is trying to time that the "All" timer is longer than
the "App" timer. Unfortunately, when running on JRuby, the All time is
often below 1ms, which is shorter than the granularity for our Time
class (JVM only provides current time to 1ms granularity). As a
result, the test usually fails.

This came up because a friend of JRuby is working to prepare a Gentoo
ebuild, and wants to get all related packages running green.

I'm not sure the best way to fix this; the difference in execution
time between the "App" and the "All" wrapper are very small, and a
timing test like this is probably going to be unpredictable. I have
made a JRuby-specific patch here to use the JVM's nanosecond timer
(which can be used for deltas but not absolute times), but it's
obviously JRuby-specific:

http://gist.github.com/279475

Running the tests with this modification shows the "All" time to range
around 0.00015s and the "App" time around 0.00003s.

Thoughts?

- Charlie

Re: Rack test spec_rack_runtime fails on JRuby due to timing

[Ryan Tomayko]

On Sun, Jan 17, 2010 at 10:20 AM, Charles Oliver Nutter
<headius@headius.com> wrote:
> Hey, the following test currently fails on JRuby, but not for a very
> good reason:
>
>  specify "should allow multiple timers to be set" do
>    app = lambda { |env| sleep 0.1; [200, {'Content-Type' => 'text/
> plain'}, "Hello, World!"] }
>    runtime1 = Rack::Runtime.new(app, "App")
>    runtime2 = Rack::Runtime.new(runtime1, "All")
>    response = runtime2.call({})
>
>    response[1]['X-Runtime-App'].should =~ /[\d\.]+/
>    response[1]['X-Runtime-All'].should =~ /[\d\.]+/
>
>    Float(response[1]['X-Runtime-All']).should > Float(response[1]['X-
> Runtime-App'])
>  end
>
> The test here is trying to time that the "All" timer is longer than
> the "App" timer. Unfortunately, when running on JRuby, the All time is
> often below 1ms, which is shorter than the granularity for our Time
> class (JVM only provides current time to 1ms granularity). As a
> result, the test usually fails.
>
> This came up because a friend of JRuby is working to prepare a Gentoo
> ebuild, and wants to get all related packages running green.
>
> I'm not sure the best way to fix this; the difference in execution
> time between the "App" and the "All" wrapper are very small, and a
> timing test like this is probably going to be unpredictable. I have
> made a JRuby-specific patch here to use the JVM's nanosecond timer
> (which can be used for deltas but not absolute times), but it's
> obviously JRuby-specific:
>
> http://gist.github.com/279475
>
> Running the tests with this modification shows the "All" time to range
> around 0.00015s and the "App" time around 0.00003s.
>
> Thoughts?

Perhaps changing the assertion to be:

    Float(response[1]['X-Runtime-All']).should >=
Float(response[1]['X-Runtime-App'])

... or removing the assertion entirely.

Thanks,
Ryan

Re: Rack test spec_rack_runtime fails on JRuby due to timing

[Christian Neukirchen]

On Mon, Jan 18, 2010 at 7:38 AM, Ryan Tomayko <r@tomayko.com> wrote:
> On Sun, Jan 17, 2010 at 10:20 AM, Charles Oliver Nutter
> <headius@headius.com> wrote:
>> Hey, the following test currently fails on JRuby, but not for a very
>> good reason:
>>
>>  specify "should allow multiple timers to be set" do
>>    app = lambda { |env| sleep 0.1; [200, {'Content-Type' => 'text/
>> plain'}, "Hello, World!"] }
>>    runtime1 = Rack::Runtime.new(app, "App")
>>    runtime2 = Rack::Runtime.new(runtime1, "All")
>>    response = runtime2.call({})
>>
>>    response[1]['X-Runtime-App'].should =~ /[\d\.]+/
>>    response[1]['X-Runtime-All'].should =~ /[\d\.]+/
>>
>>    Float(response[1]['X-Runtime-All']).should > Float(response[1]['X-
>> Runtime-App'])
>>  end
>>
>> The test here is trying to time that the "All" timer is longer than
>> the "App" timer. Unfortunately, when running on JRuby, the All time is
>> often below 1ms, which is shorter than the granularity for our Time
>> class (JVM only provides current time to 1ms granularity). As a
>> result, the test usually fails.
>>
>> This came up because a friend of JRuby is working to prepare a Gentoo
>> ebuild, and wants to get all related packages running green.
>>
>> I'm not sure the best way to fix this; the difference in execution
>> time between the "App" and the "All" wrapper are very small, and a
>> timing test like this is probably going to be unpredictable. I have
>> made a JRuby-specific patch here to use the JVM's nanosecond timer
>> (which can be used for deltas but not absolute times), but it's
>> obviously JRuby-specific:
>>
>> http://gist.github.com/279475
>>
>> Running the tests with this modification shows the "All" time to range
>> around 0.00015s and the "App" time around 0.00003s.
>>
>> Thoughts?
>
> Perhaps changing the assertion to be:
>
>    Float(response[1]['X-Runtime-All']).should >=
> Float(response[1]['X-Runtime-App'])
>
> ... or removing the assertion entirely.

... or introducing/moving a second sleep.

> Thanks,
> Ryan
>
-- 
Christian Neukirchen  <chneukirchen@gmail.com>  http://chneukirchen.org

Re: Rack test spec_rack_runtime fails on JRuby due to timing

[Charles Oliver Nutter]

On Mon, Jan 18, 2010 at 12:59 AM, Christian Neukirchen
<chneukirchen@gmail.com> wrote:
> On Mon, Jan 18, 2010 at 7:38 AM, Ryan Tomayko <r@tomayko.com> wrote:
>> Perhaps changing the assertion to be:
>>
>>    Float(response[1]['X-Runtime-All']).should >=
>> Float(response[1]['X-Runtime-App'])
>>
>> ... or removing the assertion entirely.
>
> ... or introducing/moving a second sleep.

I made the following change on my (temporary) rack fork, which helps
ensure the times are long enough to be measurable:

http://github.com/headius/rack/commit/fb0a7378852b678315b403eb2061da73b4478a37

It's a little hacky, but it works well enough. Timing tests are
obviously hard to get right in any case.

- Charlie

Re: Rack test spec_rack_runtime fails on JRuby due to timing

[Ryan Tomayko]

On Mon, Jan 18, 2010 at 9:17 AM, Charles Oliver Nutter
<headius@headius.com> wrote:
> On Mon, Jan 18, 2010 at 12:59 AM, Christian Neukirchen
> <chneukirchen@gmail.com> wrote:
>> On Mon, Jan 18, 2010 at 7:38 AM, Ryan Tomayko <r@tomayko.com> wrote:
>>> Perhaps changing the assertion to be:
>>>
>>>    Float(response[1]['X-Runtime-All']).should >=
>>> Float(response[1]['X-Runtime-App'])
>>>
>>> ... or removing the assertion entirely.
>>
>> ... or introducing/moving a second sleep.
>
> I made the following change on my (temporary) rack fork, which helps
> ensure the times are long enough to be measurable:
>
> http://github.com/headius/rack/commit/fb0a7378852b678315b403eb2061da73b4478a37
>
> It's a little hacky, but it works well enough. Timing tests are
> obviously hard to get right in any case.

Applied this to rack/master along with a fix for the content-length
issue. Sorry for the delay.

Thanks,
Ryan