Forum: Ruby-core GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurement

85a7af756b7f36df3ae80a7cb448214e?d=identicon&s=25 unknown (Guest)
on 2014-03-13 05:57
(Received via mailing list)
Issue #9629 has been updated by Ben Weintraub.


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.

----------------------------------------
Bug #9629: GC::Profiler.total_time under-reports GC time compared to
dtrace GC probe measurement
https://bugs.ruby-lang.org/issues/9629#change-45748

* Author: Ben Weintraub
* Status: Open
* Priority: Normal
* Assignee:
* Category:
* Target version:
* ruby -v: ruby 2.1.1p76 (2014-02-24 revision 45161) [x86_64-darwin13.0]
* Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN, 2.1: UNKNOWN
----------------------------------------
I'm trying to square the numbers that I'm getting from
GC::Profiler.total_time against those that I'm getting out of
instrumentation with the GC dtrace probes embedded in Ruby, and having a
hard time getting the two sources to agree.

I'm not sure if this is due to a legitimate bug in Ruby, or a
misunderstanding on my part about what the two measurements mean.

You can reproduce this using the scripts in this gist (run standalone.rb
first, it will prompt you for what to do next):
https://gist.github.com/benweint/9519384

The high-level summary of what that does is:
1. Call GC::Profiler.enable
2. Save GC::Profiler.total_time
3. Instrument with a dtrace script that tracks mark and sweep start/stop
and keeps a running total of GC time
4. Run some code that exercises GC
5. Calculate elapsed GC time with GC::Profiler.total_time - <saved value
from step 2>
6. Compare the Ruby-measured total GC time to the dtrace-measured total
GC time

It seems that the measurement from GC::Profiler is consistently lower
than the dtrace measurement, by a non-trivial margin (15-20% in my
testing).

Looking at GC::Profiler.raw_data, the bulk of the difference seems to be
in the sweep time measurement (mark times line up pretty closely between
the two ways of measuring).

Any insight into whether this represents a legitimate bug, an error in
my measurement technique, or a misunderstanding of these measurements
would be greatly appreciated!

---Files--------------------------------
standalone.rb (926 Bytes)
trace-gc-standalone.sh (1.01 KB)
This topic is locked and can not be replied to.