From 405367b0d50d8152f5c6203468a83f83f61a9ff2 Mon Sep 17 00:00:00 2001
From: Tom de Bruijn <tom@tomdebruijn.com>
Date: Fri, 5 Aug 2022 12:29:40 +0200
Subject: [PATCH] Only report gc_time metric if profiler is enabled

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
---
 ...port-temporarily-disabling-gc-profiling.md |  6 ++++
 lib/appsignal/probes/mri.rb                   |  6 ++--
 spec/lib/appsignal/probes/mri_spec.rb         | 35 +++++++++++++++++++
 3 files changed, 45 insertions(+), 2 deletions(-)
 create mode 100644 .changesets/support-temporarily-disabling-gc-profiling.md

diff --git a/.changesets/support-temporarily-disabling-gc-profiling.md b/.changesets/support-temporarily-disabling-gc-profiling.md
new file mode 100644
index 000000000..d9900e7f9
--- /dev/null
+++ b/.changesets/support-temporarily-disabling-gc-profiling.md
@@ -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`.
diff --git a/lib/appsignal/probes/mri.rb b/lib/appsignal/probes/mri.rb
index b7a86502c..21973cb52 100644
--- a/lib/appsignal/probes/mri.rb
+++ b/lib/appsignal/probes/mri.rb
@@ -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
diff --git a/spec/lib/appsignal/probes/mri_spec.rb b/spec/lib/appsignal/probes/mri_spec.rb
index 5e2789fd6..255a36322 100644
--- a/spec/lib/appsignal/probes/mri_spec.rb
+++ b/spec/lib/appsignal/probes/mri_spec.rb
@@ -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
@@ -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(