GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurement
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):
The high-level summary of what that does is:
- Call GC::Profiler.enable
- Save GC::Profiler.total_time
- Instrument with a dtrace script that tracks mark and sweep start/stop and keeps a running total of GC time
- Run some code that exercises GC
- Calculate elapsed GC time with GC::Profiler.total_time - <saved value from step 2>
- 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!