Project

General

Profile

Bug #10202

TestBenchmark#test_realtime_output breaks on ARM

Added by vo.x (Vit Ondruch) almost 6 years ago. Updated almost 6 years ago.

Status:
Closed
Priority:
Normal
Target version:
-
ruby -v:
ruby 2.2.0dev (2014-09-03 trunk 47372) [armv7hl-linux]
[ruby-core:64744]

Description

I observe following error on ARM:

  3) Failure:
TestBenchmark#test_realtime_output [/builddir/build/BUILD/ruby-2.2.0-r47372/test/benchmark/test_benchmark.rb:159]:
Expected 1.0 to be < 0.999977873172611.

It seems to be introduced by r47360. Reverting the commit makes test suite to pass once again.

Updated by normalperson (Eric Wong) almost 6 years ago

v.ondruch@tiscali.cz wrote:

I observe following error on ARM:

  3) Failure:
TestBenchmark#test_realtime_output [/builddir/build/BUILD/ruby-2.2.0-r47372/test/benchmark/test_benchmark.rb:159]:
Expected 1.0 to be < 0.999977873172611.

The real bug might be a timer firing too soon.

Can you show us the output of: strace -Tvf ruby -e 'sleep 1'

I mainly care about the timing of FUTEX_WAIT_BITSET(_PRIVATE) and poll
syscalls. Thank you.

It seems to be introduced by r47360. Reverting the commit makes test
suite to pass once again.

Reverting just the change to lib/benchmark.rb? Or reverting the test
case, too?

Updated by vo.x (Vit Ondruch) almost 6 years ago

The real bug might be a timer firing too soon.

Can you show us the output of: strace -Tvf ruby -e 'sleep 1'

I mainly care about the timing of FUTEX_WAIT_BITSET(_PRIVATE) and poll
syscalls. Thank you.

http://paste.fedoraproject.org/130884/81461414/

Updated by normalperson (Eric Wong) almost 6 years ago

v.ondruch@tiscali.cz wrote:

http://paste.fedoraproject.org/130884/81461414/

So I think everything looks right with FUTEX_WAIT_BITSET_PRIVATE
taking > 1.0s according to strace.

And your CLOCK_MONOTONIC output seems about right, but _RAW may not
be...

Reading more about it[1], CLOCK_MONOTONIC_RAW is probably not be the
right clock to use for us since NTP corrects for frequency adjustments
which we're likely to want for Benchmark.realtime measurements.

Furthermore, futex syscalls (for sleep duration) takes into account the
NTP adjustments which CLOCK_MONOTONIC_RAW ignores. Same goes for other
sleep mechanisms exposed to userspace (select/poll).

I'm leaning towards ignoring the existence of CLOCK_MONOTONIC_RAW
entirely.

Just curious, can you show strace with Benchmark.realtime {} wrapped
around sleep? Now I'm willing to bet CLOCK_MONOTONIC_RAW is off in
your case.

[1] this thread, where John Stultz explains how CLOCK_MONOTONIC
is frequency (but not offset) corrected:
https://lkml.org/lkml/2014/7/17/718

Updated by vo.x (Vit Ondruch) almost 6 years ago

Just curious, can you show strace with Benchmark.realtime {} wrapped
around sleep? Now I'm willing to bet CLOCK_MONOTONIC_RAW is off in
your case.

http://paste.fedoraproject.org/130924/14098270/

Updated by normalperson (Eric Wong) almost 6 years ago

v.ondruch@tiscali.cz wrote:

http://paste.fedoraproject.org/130924/14098270/

1144. 22470 clock_gettime(CLOCK_MONOTONIC_RAW, {18856, 134154424}) = 0 <0.000039>
<snip>
1152. 22470 clock_gettime(CLOCK_MONOTONIC_RAW, {18857, 135174677}) = 0 <0.000034>

Maybe not, but maybe strace slowed things down enough...

I still think reverting CLOCK_MONONTONIC_RAW changes is the way to
go, can you confirm? Thanks.

--- a/lib/benchmark.rb
+++ b/lib/benchmark.rb
@@ -272,9 +272,6 @@ module Benchmark

   # :stopdoc:
   case
-  when (defined?(Process::CLOCK_MONOTONIC_RAW) and
-      (Process.clock_gettime(Process::CLOCK_MONOTONIC_RAW) rescue false))
-    BENCHMARK_CLOCK = Process::CLOCK_MONOTONIC_RAW
   when defined?(Process::CLOCK_MONOTONIC)
     BENCHMARK_CLOCK = Process::CLOCK_MONOTONIC
   else

Updated by normalperson (Eric Wong) almost 6 years ago

v.ondruch@tiscali.cz wrote:

This is the result with patch applied:

Sorry, I meant to ask whether removing _RAW support fixes the
original test case for you.

Updated by vo.x (Vit Ondruch) almost 6 years ago

The test passes with the applied patch:

$ ruby -Itest/lib/ test/benchmark/test_benchmark.rb -n test_realtime_output -v
Run options: -n test_realtime_output -v

# Running tests:

TestBenchmark#test_realtime_output = 1.00 s = .


Finished tests in 1.025177s, 0.9754 tests/s, 0.9754 assertions/s.

1 tests, 1 assertions, 0 failures, 0 errors, 0 skips

ruby -v: ruby 2.2.0dev (2014-09-03 trunk 47372) [armv7hl-linux]
#9

Updated by Anonymous almost 6 years ago

  • Status changed from Open to Closed
  • % Done changed from 0 to 100

Applied in changeset r47526.


lib/benchmark.rb: remove CLOCK_MONOTONIC_RAW support

In addition to being unaffected by offset correction,
CLOCK_MONOTONIC_RAW is also unaffected by frequency correction,
making it unsuitable for measuring real time on systems where the
clock is always running too fast or slow.

CLOCK_MONOTONIC (without RAW) is the correct clock, as it is unaffected
by _offset
correction (due to human error or battery replacement), but
still takes frequency correction into account for clocks which
consistently run too fast or slow.

Thanks to Vít Ondruch for reporting the issue on ARM [Bug #10202]

Updated by normalperson (Eric Wong) almost 6 years ago

Thanks for the confirmation! r47526 removes CLOCK_MONOTONIC_RAW.

r47526 | normal | 2014-09-11 08:09:07 +0000 (Thu, 11 Sep 2014) | 14 lines

lib/benchmark.rb: remove CLOCK_MONOTONIC_RAW support

In addition to being unaffected by offset correction,
CLOCK_MONOTONIC_RAW is also unaffected by frequency correction,
making it unsuitable for measuring real time on systems where the
clock is always running too fast or slow.

CLOCK_MONOTONIC (without RAW) is the correct clock, as it is unaffected
by _offset
correction (due to human error or battery replacement), but
still takes frequency correction into account for clocks which
consistently run too fast or slow.

Thanks to Vít Ondruch for reporting the issue on ARM [Bug #10202]

Also available in: Atom PDF