https://redmine.ruby-lang.org/https://redmine.ruby-lang.org/favicon.ico?17113305112014-09-03T17:59:13ZRuby Issue Tracking SystemRuby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486412014-09-03T17:59:13Znormalperson (Eric Wong)normalperson@yhbt.net
<ul></ul><p><a href="mailto:v.ondruch@tiscali.cz" class="email">v.ondruch@tiscali.cz</a> wrote:</p>
<blockquote>
<p>I observe following error on ARM:</p>
<pre><code> 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.
</code></pre>
</blockquote>
<p>The real bug might be a timer firing too soon.</p>
<p>Can you show us the output of: strace -Tvf ruby -e 'sleep 1'</p>
<p>I mainly care about the timing of FUTEX_WAIT_BITSET(_PRIVATE) and poll<br>
syscalls. Thank you.</p>
<blockquote>
<p>It seems to be introduced by r47360. Reverting the commit makes test<br>
suite to pass once again.</p>
</blockquote>
<p>Reverting just the change to lib/benchmark.rb? Or reverting the test<br>
case, too?</p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486442014-09-04T07:12:44Zvo.x (Vit Ondruch)v.ondruch@tiscali.cz
<ul></ul><blockquote>
<p>The real bug might be a timer firing too soon.</p>
<p>Can you show us the output of: strace -Tvf ruby -e 'sleep 1'</p>
<p>I mainly care about the timing of FUTEX_WAIT_BITSET(_PRIVATE) and poll<br>
syscalls. Thank you.</p>
</blockquote>
<p><a href="http://paste.fedoraproject.org/130884/81461414/" class="external">http://paste.fedoraproject.org/130884/81461414/</a></p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486452014-09-04T08:48:53Znormalperson (Eric Wong)normalperson@yhbt.net
<ul></ul><p><a href="mailto:v.ondruch@tiscali.cz" class="email">v.ondruch@tiscali.cz</a> wrote:</p>
<blockquote>
<p><a href="http://paste.fedoraproject.org/130884/81461414/" class="external">http://paste.fedoraproject.org/130884/81461414/</a></p>
</blockquote>
<p>So I think everything looks right with FUTEX_WAIT_BITSET_PRIVATE<br>
taking > 1.0s according to strace.</p>
<p>And your CLOCK_MONOTONIC output seems about right, but _RAW may not<br>
be...</p>
<p>Reading more about it[1], CLOCK_MONOTONIC_RAW is probably not be the<br>
right clock to use for us since NTP corrects for <em>frequency</em> adjustments<br>
which we're likely to want for Benchmark.realtime measurements.</p>
<p>Furthermore, futex syscalls (for sleep duration) takes into account the<br>
NTP adjustments which CLOCK_MONOTONIC_RAW ignores. Same goes for other<br>
sleep mechanisms exposed to userspace (select/poll).</p>
<p>I'm leaning towards ignoring the existence of CLOCK_MONOTONIC_RAW<br>
entirely.</p>
<p>Just curious, can you show strace with Benchmark.realtime {} wrapped<br>
around sleep? Now I'm willing to bet CLOCK_MONOTONIC_RAW is off in<br>
your case.</p>
<p>[1] this thread, where John Stultz explains how CLOCK_MONOTONIC<br>
is frequency (but not offset) corrected:<br>
<a href="https://lkml.org/lkml/2014/7/17/718" class="external">https://lkml.org/lkml/2014/7/17/718</a></p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486482014-09-04T10:38:46Zvo.x (Vit Ondruch)v.ondruch@tiscali.cz
<ul></ul><blockquote>
<p>Just curious, can you show strace with Benchmark.realtime {} wrapped<br>
around sleep? Now I'm willing to bet CLOCK_MONOTONIC_RAW is off in<br>
your case.</p>
</blockquote>
<p><a href="http://paste.fedoraproject.org/130924/14098270/" class="external">http://paste.fedoraproject.org/130924/14098270/</a></p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486602014-09-04T17:12:31Znormalperson (Eric Wong)normalperson@yhbt.net
<ul></ul><p><a href="mailto:v.ondruch@tiscali.cz" class="email">v.ondruch@tiscali.cz</a> wrote:</p>
<blockquote>
<p><a href="http://paste.fedoraproject.org/130924/14098270/" class="external">http://paste.fedoraproject.org/130924/14098270/</a></p>
</blockquote>
<pre><code>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>
</code></pre>
<p>Maybe not, but maybe <code>strace</code> slowed things down enough...</p>
<p>I still think reverting <code>CLOCK_MONONTONIC_RAW</code> changes is the way to<br>
go, can you confirm? Thanks.</p>
<pre><code class="diff syntaxhl" data-language="diff"><span class="gd">--- a/lib/benchmark.rb
</span><span class="gi">+++ b/lib/benchmark.rb
</span><span class="p">@@ -272,9 +272,6 @@</span> module Benchmark
# :stopdoc:
case
<span class="gd">- when (defined?(Process::CLOCK_MONOTONIC_RAW) and
- (Process.clock_gettime(Process::CLOCK_MONOTONIC_RAW) rescue false))
- BENCHMARK_CLOCK = Process::CLOCK_MONOTONIC_RAW
</span> when defined?(Process::CLOCK_MONOTONIC)
BENCHMARK_CLOCK = Process::CLOCK_MONOTONIC
else
</code></pre> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486772014-09-05T08:48:44Zvo.x (Vit Ondruch)v.ondruch@tiscali.cz
<ul></ul><p>This is the result with patch applied:</p>
<p><a href="http://paste.fedoraproject.org/131177/90664414" class="external">http://paste.fedoraproject.org/131177/90664414</a></p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=486862014-09-05T18:30:53Znormalperson (Eric Wong)normalperson@yhbt.net
<ul></ul><p><a href="mailto:v.ondruch@tiscali.cz" class="email">v.ondruch@tiscali.cz</a> wrote:</p>
<blockquote>
<p>This is the result with patch applied:</p>
</blockquote>
<p>Sorry, I meant to ask whether removing _RAW support fixes the<br>
original test case for you.</p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=488432014-09-11T07:52:20Zvo.x (Vit Ondruch)v.ondruch@tiscali.cz
<ul></ul><p>The test passes with the applied patch:</p>
<pre><code>$ 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]
</code></pre> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=488442014-09-11T08:09:18ZAnonymous
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Closed</i></li><li><strong>% Done</strong> changed from <i>0</i> to <i>100</i></li></ul><p>Applied in changeset r47526.</p>
<hr>
<p>lib/benchmark.rb: remove CLOCK_MONOTONIC_RAW support</p>
<p>In addition to being unaffected by <em>offset</em> correction,<br>
CLOCK_MONOTONIC_RAW is also unaffected by <em>frequency</em> correction,<br>
making it unsuitable for measuring real time on systems where the<br>
clock is always running too fast or slow.</p>
<p>CLOCK_MONOTONIC (without _RAW) is the correct clock, as it is unaffected<br>
by <em>offset</em> correction (due to human error or battery replacement), but<br>
still takes <em>frequency</em> correction into account for clocks which<br>
consistently run too fast or slow.</p>
<p>Thanks to Vít Ondruch for reporting the issue on ARM [Bug <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: TestBenchmark#test_realtime_output breaks on ARM (Closed)" href="https://redmine.ruby-lang.org/issues/10202">#10202</a>]</p> Ruby master - Bug #10202: TestBenchmark#test_realtime_output breaks on ARMhttps://redmine.ruby-lang.org/issues/10202?journal_id=488452014-09-11T08:11:50Znormalperson (Eric Wong)normalperson@yhbt.net
<ul></ul><p>Thanks for the confirmation! r47526 removes CLOCK_MONOTONIC_RAW.</p>
<p>r47526 | normal | 2014-09-11 08:09:07 +0000 (Thu, 11 Sep 2014) | 14 lines</p>
<p>lib/benchmark.rb: remove CLOCK_MONOTONIC_RAW support</p>
<p>In addition to being unaffected by <em>offset</em> correction,<br>
CLOCK_MONOTONIC_RAW is also unaffected by <em>frequency</em> correction,<br>
making it unsuitable for measuring real time on systems where the<br>
clock is always running too fast or slow.</p>
<p>CLOCK_MONOTONIC (without _RAW) is the correct clock, as it is unaffected<br>
by <em>offset</em> correction (due to human error or battery replacement), but<br>
still takes <em>frequency</em> correction into account for clocks which<br>
consistently run too fast or slow.</p>
<p>Thanks to Vít Ondruch for reporting the issue on ARM [Bug <a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: TestBenchmark#test_realtime_output breaks on ARM (Closed)" href="https://redmine.ruby-lang.org/issues/10202">#10202</a>]</p>