DEV: Seperate concerns of tracking GC stat from MethodProfiler (#22921)

Why this change?

This is a follow up to e8f7b62752.
Tracking of GC stats didn't really belong in the `MethodProfiler` class
so we want to extract that concern into its own class.

As part of this PR, the `track_gc_stat_per_request` site setting has
also been renamed to `instrument_gc_stat_per_request`.

config/initializers/000-zeitwerk.rb

@@ -43,6 +43,7 @@ Rails.autoloaders.each do |autoloader|
     "json" => "JSON",
     "ssrf_detector" => "SSRFDetector",
     "http" => "HTTP",
+    "gc_stat_instrumenter" => "GCStatInstrumenter",
   )
 end
 Rails.autoloaders.main.ignore(

config/site_settings.yml

@@ -2148,7 +2148,7 @@ developer:
   max_sidebar_section_links:
     default: 50
     hidden: true
-  track_gc_stat_per_request:
+  instrument_gc_stat_per_request:
     default: false
     hidden: true
 

lib/gc_stat_instrumenter.rb

@@ -0,0 +1,17 @@
+# frozen_string_literal: true
+
+class GCStatInstrumenter
+  def self.instrument
+    start_gc_stat = GC.stat
+    yield
+    end_gc_stat = GC.stat
+
+    {
+      gc: {
+        time: (end_gc_stat[:time] - start_gc_stat[:time]) / 1000.0,
+        major_count: end_gc_stat[:major_gc_count] - start_gc_stat[:major_gc_count],
+        minor_count: end_gc_stat[:minor_gc_count] - start_gc_stat[:minor_gc_count],
+      },
+    }
+  end
+end

lib/method_profiler.rb

@@ -89,13 +89,8 @@ class MethodProfiler
   end
 
   def self.start(transfer = nil)
-    Thread.current[:_method_profiler] = if transfer
+    Thread.current[:_method_profiler] = transfer ||
-      transfer
+      { __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) }
-    else
-      data = { __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) }
-      data[:gc_stat] = GC.stat if SiteSetting.track_gc_stat_per_request
-      data
-    end
   end
 
   def self.clear
@@ -109,15 +104,6 @@ class MethodProfiler
       Thread.current[:_method_profiler] = nil
       start = data.delete(:__start)
       data[:total_duration] = finish - start
-
-      if start_gc_stat = data.delete(:gc_stat)
-        end_gc_stat = GC.stat
-
-        data[:gc] ||= {}
-        data[:gc][:time] = (end_gc_stat[:time] - start_gc_stat[:time]) / 1000.0
-        data[:gc][:major_count] = end_gc_stat[:major_gc_count] - start_gc_stat[:major_gc_count]
-        data[:gc][:minor_count] = end_gc_stat[:minor_gc_count] - start_gc_stat[:minor_gc_count]
-      end
     end
 
     data

lib/middleware/request_tracker.rb

@@ -201,6 +201,7 @@ class Middleware::RequestTracker
   def call(env)
     result = nil
     info = nil
+    gc_stat_timing = nil
 
     # doing this as early as possible so we have an
     # accurate counter
@@ -225,7 +226,13 @@ class Middleware::RequestTracker
     env["discourse.request_tracker"] = self
 
     MethodProfiler.start
+
+    if SiteSetting.instrument_gc_stat_per_request
+      gc_stat_timing = GCStatInstrumenter.instrument { result = @app.call(env) }
+    else
       result = @app.call(env)
+    end
+
     info = MethodProfiler.stop
 
     # possibly transferred?
@@ -263,7 +270,11 @@ class Middleware::RequestTracker
         end
       end
     end
-    log_request_info(env, result, info, request) if !env["discourse.request_tracker.skip"]
+
+    if !env["discourse.request_tracker.skip"]
+      info.merge!(gc_stat_timing) if gc_stat_timing
+      log_request_info(env, result, info, request)
+    end
   end
 
   def log_later(data)

spec/lib/gc_stat_instrumenter_spec.rb

@@ -0,0 +1,18 @@
+# frozen_string_literal: true
+
+RSpec.describe GCStatInstrumenter do
+  describe ".instrument" do
+    it "returns a hash with the GC time, major and minor GC count for executing the given block" do
+      result =
+        described_class.instrument do
+          GC.start(full_mark: true) # Major GC
+          GC.start(full_mark: false) # Minor GC
+        end
+
+      expect(result[:gc]).to be_present
+      expect(result[:gc][:time]).to be >= 0.0
+      expect(result[:gc][:major_count]).to eq(1)
+      expect(result[:gc][:minor_count]).to eq(1)
+    end
+  end
+end

spec/lib/method_profiler_spec.rb

@@ -37,24 +37,4 @@ RSpec.describe MethodProfiler do
 
     expect(result[:at_beach][:calls]).to eq(2)
   end
-
-  it "profiles GC stat information when `track_gc_stat_per_request` site setting has been enabled" do
-    MethodProfiler.start
-    GC.start(full_mark: false) # Minor GC
-    result = MethodProfiler.stop
-
-    expect(result[:gc]).not_to be_present
-
-    SiteSetting.track_gc_stat_per_request = true
-
-    MethodProfiler.start
-    GC.start(full_mark: true) # Major GC
-    GC.start(full_mark: false) # Minor GC
-    result = MethodProfiler.stop
-
-    expect(result[:gc]).to be_present
-    expect(result[:gc][:time]).to be >= 0.0
-    expect(result[:gc][:major_count]).to eq(1)
-    expect(result[:gc][:minor_count]).to eq(1)
-  end
 end

spec/lib/middleware/request_tracker_spec.rb

@@ -661,6 +661,7 @@ RSpec.describe Middleware::RequestTracker do
       lambda do |env|
         sql_calls.times { User.where(id: -100).pluck(:id) }
         redis_calls.times { Discourse.redis.get("x") }
+        yield if block_given?
         result
       end
     end
@@ -749,6 +750,36 @@ RSpec.describe Middleware::RequestTracker do
       expect(headers["X-Runtime"].to_f).to be > 0
     end
 
+    it "correctly logs GC stats when `instrument_gc_stat_per_request` site setting has been enabled" do
+      tracker =
+        Middleware::RequestTracker.new(
+          app([200, {}, []]) do
+            GC.start(full_mark: true) # Major GC
+            GC.start(full_mark: false) # Minor GC
+          end,
+        )
+
+      tracker.call(env)
+
+      expect(@data[:timing][:gc]).to eq(nil)
+
+      SiteSetting.instrument_gc_stat_per_request = true
+
+      tracker =
+        Middleware::RequestTracker.new(
+          app([200, {}, []]) do
+            GC.start(full_mark: true) # Major GC
+            GC.start(full_mark: false) # Minor GC
+          end,
+        )
+
+      tracker.call(env)
+
+      expect(@data[:timing][:gc][:time]).to be > 0.0
+      expect(@data[:timing][:gc][:major_count]).to eq(1)
+      expect(@data[:timing][:gc][:minor_count]).to eq(1)
+    end
+
     it "can correctly log messagebus request types" do
       tracker = Middleware::RequestTracker.new(app([200, {}, []]))