Skip to content

Commit

Permalink
Only report gc_time metric if profiler is enabled (#877)
Browse files Browse the repository at this point in the history
Let's only report the `gc_time` metric when there's an actual value to
report to avoid confusion of very small GC times.

If the Profiler is disabled, it reports 0.0 as the value for this
metric. We know when the profiler is enabled by asking it
`GC::Profiler.enabled?`.

By directly asking the Ruby GC profiler, instead of our wrapper based on
the `enable_gc_instrumentation` config option, we allow users to enable
and disable the profiler temporarily with `GC::Profiler.enable` and
`GC::Profiler.disable` calls in their app.

If the profiler is enabled, disabled, and then enabled again, it
remembers the total time from the last time it was enabled. By not
reporting 0 when it is disabled we don't reset the cache and don't
trigger a very high duration being reported the next time it's enabled.

```ruby
> GC::Profiler.total_time
# => 0.0

> GC::Profiler.enable
> GC::Profiler.total_time
=> 0.001
> 10000.times { SecureRandom.uuid }
# => Does stuff for a long time
> GC::Profiler.total_time
# => 58.93548299997067

> GC::Profiler.disable
> GC::Profiler.total_time
# => 0.0
> 10000.times { SecureRandom.uuid }
# => Does stuff for a long time
> GC::Profiler.total_time
# => 0.0
> GC::Profiler.enable
> GC::Profiler.total_time
# => 58.93548299997067
# Same as before it was disabled without the GC time of the code that
# was run when it was disabled
```

Part of #868
  • Loading branch information
tombruijn authored Aug 5, 2022
1 parent ee0dc5d commit ffe49cf
Show file tree
Hide file tree
Showing 3 changed files with 45 additions and 2 deletions.
6 changes: 6 additions & 0 deletions .changesets/support-temporarily-disabling-gc-profiling.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
---
bump: "patch"
type: "add"
---

Support temporarily disabling GC profiling without reporting inaccurate `gc_time` metric durations. The MRI probe's `gc_time` will not report any value when the `GC::Profiler.enabled?` returns `false`.
6 changes: 4 additions & 2 deletions lib/appsignal/probes/mri.rb
Original file line number Diff line number Diff line change
Expand Up @@ -31,8 +31,10 @@ def call
)

set_gauge("thread_count", Thread.list.size)
gauge_delta(:gc_time, @gc_profiler.total_time) do |gc_time|
set_gauge("gc_time", gc_time) if gc_time > 0
if GC::Profiler.enabled?
gauge_delta(:gc_time, @gc_profiler.total_time) do |gc_time|
set_gauge("gc_time", gc_time) if gc_time > 0
end
end

gc_stats = GC.stat
Expand Down
35 changes: 35 additions & 0 deletions spec/lib/appsignal/probes/mri_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ def set_gauge(*args) # rubocop:disable Naming/AccessorMethodName
let(:hostname) { nil }
before do
allow(gc_profiler_mock).to receive(:total_time)
allow(GC::Profiler).to receive(:enabled?).and_return(true)
end

it "should track vm metrics" do
Expand Down Expand Up @@ -70,6 +71,40 @@ def set_gauge(*args) # rubocop:disable Naming/AccessorMethodName
end
end

context "when GC profiling is disabled" do
it "does not report a gc_time metric" do
allow(GC::Profiler).to receive(:enabled?).and_return(false)
expect(gc_profiler_mock).to_not receive(:total_time)
probe.call # Normal call, create a cache
probe.call # Report delta value based on cached value
metrics = appsignal_mock.gauges.map { |(key)| key }
expect(metrics).to_not include("gc_time")
end

it "does not report a gc_time metric while disable" do
# While enabled
allow(GC::Profiler).to receive(:enabled?).and_return(true)
expect(gc_profiler_mock).to receive(:total_time).and_return(10, 15)
probe.call # Normal call, create a cache
probe.call # Report delta value based on cached value
expect_gauges([["gc_time", 5]])

# While disabled
allow(GC::Profiler).to receive(:enabled?).and_return(false)
probe.call # Call twice to make sure any caches resets wouldn't mess up the assertion
probe.call
# Does not include any newly reported metrics
expect_gauges([["gc_time", 5]])

# When enabled after being disabled for a while, it only reports the
# newly reported time since it was renabled
allow(GC::Profiler).to receive(:enabled?).and_return(true)
expect(gc_profiler_mock).to receive(:total_time).and_return(25)
probe.call
expect_gauges([["gc_time", 5], ["gc_time", 10]])
end
end

it "tracks GC run count" do
expect(GC).to receive(:count).and_return(10, 15)
expect(GC).to receive(:stat).and_return(
Expand Down

0 comments on commit ffe49cf

Please sign in to comment.