https://bugs.ruby-lang.org/https://bugs.ruby-lang.org/favicon.ico?17113305112014-03-13T00:31:19ZRuby Issue Tracking SystemRuby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=457442014-03-13T00:31:19Zbenweint (Ben Weintraub)benweint@gmail.com
<ul><li><strong>File</strong> <a href="/attachments/4296">standalone.rb</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/4296/standalone.rb">standalone.rb</a> added</li><li><strong>File</strong> <a href="/attachments/4297">trace-gc-standalone.sh</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/4297/trace-gc-standalone.sh">trace-gc-standalone.sh</a> added</li></ul><p>Uploading the two files from that gist, just to keep everything in one place.</p> Ruby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=457452014-03-13T00:40:27Zbenweint (Ben Weintraub)benweint@gmail.com
<ul></ul><p>Worth noting: a quick read through gc.c suggested that the missing GC sweep time might be due to me not having built with GC_PROFILE_MORE_DETAIL, but even after building with that, I still see the same discrepancy where GC::Profiler is significantly lower.</p> Ruby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=457482014-03-13T04:57:06Zbenweint (Ben Weintraub)benweint@gmail.com
<ul></ul><p>I realized that these are actually measuring different things: dtrace's timestamps measure wall clock time, whereas GC::Profiler on Mac OS X uses getrusage, which measures user CPU time. It still seems weird that the two would be so divergent though, given that GC mark and sweep should be CPU-bound.</p> Ruby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=457722014-03-13T22:53:10Zbenweint (Ben Weintraub)benweint@gmail.com
<ul></ul><p>I think I've figured out the discrepancy here: the dtrace probes wrap around the getrusage(2) calls that GC::Profiler bases its timings on for Mac OS X. The average lazy sweep time is quite short (single-digit microseconds per lazy sweep). Unfortunately, getrusage itself has an overhead of ~1.5 us per call on average on my Mac OS X box, which adds up to 3 us total per lazy sweep (since we call it once to start the timer and once to stop). That means dtrace sees a measurement for lazy sweeps that's on average 3 us higher than what GC::Profiler is able to measure. Because there are so many lazy sweeps, these 3 us chunks add up to a non-trivial amount of time.</p>
<p>I'm guessing that this is less of an issue on Linux, because clock_gettime will be used there instead of getrusage.</p>
<p>Feel free to close this out.</p> Ruby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=457882014-03-14T20:44:08Zbenweint (Ben Weintraub)benweint@gmail.com
<ul></ul><p>One minor follow-up: it's actually not that getrusage takes a 'long' time (relative to the cost of each lazy sweep invocation), it's the dtrace probes themselves firing. The conclusion remains the same, though GC::Profiler seems correct.</p> Ruby master - Bug #9629: GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurementhttps://bugs.ruby-lang.org/issues/9629?journal_id=822242019-10-21T21:38:49Zjeremyevans0 (Jeremy Evans)merch-redmine@jeremyevans.net
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Closed</i></li><li><strong>Backport</strong> deleted (<del><i>1.9.3: UNKNOWN, 2.0.0: UNKNOWN, 2.1: UNKNOWN</i></del>)</li></ul>