diff --git a/config/initializers/000-zeitwerk.rb b/config/initializers/000-zeitwerk.rb index 13131cbb016..b9b7c171a62 100644 --- a/config/initializers/000-zeitwerk.rb +++ b/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( diff --git a/config/site_settings.yml b/config/site_settings.yml index 27b6558b0ae..8714f818a3e 100644 --- a/config/site_settings.yml +++ b/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 diff --git a/lib/gc_stat_instrumenter.rb b/lib/gc_stat_instrumenter.rb new file mode 100644 index 00000000000..759ec0cf2d1 --- /dev/null +++ b/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 diff --git a/lib/method_profiler.rb b/lib/method_profiler.rb index 221f26f14d6..ac95db890a5 100644 --- a/lib/method_profiler.rb +++ b/lib/method_profiler.rb @@ -89,13 +89,8 @@ class MethodProfiler end def self.start(transfer = nil) - Thread.current[:_method_profiler] = if transfer - transfer - else - data = { __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) } - data[:gc_stat] = GC.stat if SiteSetting.track_gc_stat_per_request - data - end + Thread.current[:_method_profiler] = transfer || + { __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) } 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 diff --git a/lib/middleware/request_tracker.rb b/lib/middleware/request_tracker.rb index 23acf64d127..90a03d7febd 100644 --- a/lib/middleware/request_tracker.rb +++ b/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 - result = @app.call(env) + + 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) diff --git a/spec/lib/gc_stat_instrumenter_spec.rb b/spec/lib/gc_stat_instrumenter_spec.rb new file mode 100644 index 00000000000..5f02bf0e3f8 --- /dev/null +++ b/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 diff --git a/spec/lib/method_profiler_spec.rb b/spec/lib/method_profiler_spec.rb index 4324c3ccdb7..408a52defb5 100644 --- a/spec/lib/method_profiler_spec.rb +++ b/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 diff --git a/spec/lib/middleware/request_tracker_spec.rb b/spec/lib/middleware/request_tracker_spec.rb index a2ee21de7df..30705a0b897 100644 --- a/spec/lib/middleware/request_tracker_spec.rb +++ b/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, {}, []]))