[ruby-core:61448] [ruby-trunk - Bug #9629] GC::Profiler.total_time under-reports GC time compared to dtrace GC probe measurement

Issue #9629 has been updated by Ben Weintraub.


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.

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

* 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)


-- 
http://bugs.ruby-lang.org/