[ruby-core:104997] [Ruby master Feature#10917] Add GC.stat[:total_time] when GC profiling enabled

Issue #10917 has been updated by ko1 (Koichi Sasada).


`GC::Profiler` is not maintained well and it doesn't calculate all of GC time now.

I rework it using `clock_gettime` (so it only works on some platforms).
https://github.com/ruby/ruby/pull/4757

```ruby
pooled = Array.new(100_000){ [] }
N = 50_000_000
h1 = h2 = nil
require 'benchmark'
Benchmark.bm{|x|
  x.report{
    h1 = GC.count
    N.times{
      a = "str".upcase
    }
    h2 = GC.count
  }
}
pp GC.stat
```

This script introduces lazy sweeping and each sweep consumes only a small time. So it is worst case.

```
[RUBY_DEBUG_COUNTER]    gc_enter_start                           1,778
[RUBY_DEBUG_COUNTER]    gc_enter_mark_continue                       6
[RUBY_DEBUG_COUNTER]    gc_enter_sweep_continue                 49,547
[RUBY_DEBUG_COUNTER]    gc_enter_rest                                1
[RUBY_DEBUG_COUNTER]    gc_enter_finalizer                           1
```

It causes 1,778 GCs and 49,547 lazy sweeping. My patch counts the time about 50,000 times:

```
master:
       user     system      total        real
   3.332477   0.000425   3.332902 (  3.332915)

with time:
       user     system      total        real
   3.436177   0.000084   3.436261 (  3.436298)
{:count=>1778,
 :time=>1286,
...
```

and it 3% slows down.


```ruby=
pooled = Array.new(100_000){ [] }
N = 5_000_000
h1 = h2 = nil
require 'benchmark'
Benchmark.bm{|x|
  x.report{
    h1 = GC.count
    N.times{
      a = [[[[[[[[[[[[[[[[[[[[[[[[[]]]]]]]]]]]]]]]]]]]]]]]]]
    }
    h2 = GC.count
  }
}
pp GC.stat
```

It's shows worst case.


master:
       user     system      total        real
   5.026109   0.003133   5.029242 (  5.029301)

with time:
       user     system      total        real
   4.995175   0.000336   4.995511 (  4.995567)  ## FASTER!!
{:count=>1423,
 :time=>1229,
 ...
```

If the program contains meaningful task (in this case, `String#upcase`), the impact will be small.

Sumamry:

* It can affect performance on some cases.
* Most of case I think the penalty is enough small.

Comments:

* It adds small times so it introduces errors.
* Adding flag like `GC.measure_time = true/false (default: false)` is one idea.


----------------------------------------
Feature #10917: Add GC.stat[:total_time] when GC profiling enabled
https://bugs.ruby-lang.org/issues/10917#change-93396

* Author: jasonrclark (Jason Clark)
* Status: Open
* Priority: Normal
----------------------------------------
This patch includes a `:total_time` value in `GC.stat` as a `Fixnum` of microseconds equivalent to `GC::Profiler.total_time`. A non-zero value is only provided if GC profiling is enabled.

This avoids problems with `GC::Profiler`'s API in the presence of multiple callers. Well-behaved clients of `GC::Profiler` are expected to call `clear` periodically to constrain memory usage of the profiling structures. However, this causes problems when multiple callers--unaware of each other--rely on the value of `GC::Profiler.total_time` being unaltered since their last `clear`.

Using a single value in `GC.stat` avoids this by providing a monotonically increasing count with every GC, not influenced by `clear`.

**Considerations and Questions**

* Because the individual GC times are potentially small, I tracked the total as a double and only convert to `Fixnum` when constructing `GC.stat`'s return. Is there something better I should be doing there, in light of `GC.stat`'s insistence that the stats returned be if type `size_t`?

* What should I do (if anything) to cope with potential overflows? If Ruby is on a platform where `size_t` is 32 bits, we'd hit an overflow after 1.2 hours worth of cumulative GC time.

**Future Directions**

Is there any possibility of moving the GC timing (not the deeper profiling data) outside `GC::Profiler.enable`'s gating? I would love avoid clients needing to make code changes to track their GC time with my gem (newrelic_rpm).

As it stands invocation start times are held on the GC profiling structures, so it felt like a much bigger change to alter that, and I thought I'd pitch this simpler change first.

Any advice on whether that would be possible? Is timing too slow to do by default, or is the gating just an artifact of how it was implemented with `GC::Profiler`?

---Files--------------------------------
gc-total-time.patch (3.43 KB)


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

Unsubscribe: <mailto:[e-mail]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>