From 67f481717bd4109c685f82fdff7a6936c6f78b5c Mon Sep 17 00:00:00 2001 From: Jean Boussier Date: Wed, 8 May 2024 22:23:36 +0200 Subject: [PATCH] Replace allocations count by GC time in request logs Allocations count is often an interesting proxy for performance, but not necessarily the most relevant thing to include in request logs, given they aren't a per thread metric, so the reporting is widely innacurate in multi-threaded environments. Since Ruby 3.1 there is now `GC.total_time` which is a monotonically increasing counter of time spent in GC. It still isn't really a per thread metric, but is is more interesting because it uses the same unit as the response time, allowing to better see when you have a GC pause performance issue. --- .../lib/action_controller/log_subscriber.rb | 2 +- actionview/lib/action_view/log_subscriber.rb | 8 ++++---- .../activerecord/controller_runtime_test.rb | 10 +++++----- .../test/template/log_subscriber_test.rb | 4 ++-- .../notifications/instrumenter.rb | 20 +++++++++++++++++++ 5 files changed, 32 insertions(+), 12 deletions(-) diff --git a/actionpack/lib/action_controller/log_subscriber.rb b/actionpack/lib/action_controller/log_subscriber.rb index 5325827e56a55..02f8493cb68d6 100644 --- a/actionpack/lib/action_controller/log_subscriber.rb +++ b/actionpack/lib/action_controller/log_subscriber.rb @@ -33,7 +33,7 @@ def process_action(event) status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name) end - additions << "Allocations: #{event.allocations}" + additions << "GC: #{event.gc_time.round(1)}ms" message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms" \ " (#{additions.join(" | ")})" diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb index eecbdd19c886e..3582aee4e1e3a 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -18,7 +18,7 @@ def render_template(event) info do message = +" Rendered #{from_rails_root(event.payload[:identifier])}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] - message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)" end end subscribe_log_level :render_template, :debug @@ -27,7 +27,7 @@ def render_partial(event) debug do message = +" Rendered #{from_rails_root(event.payload[:identifier])}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] - message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)" message << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil? message end @@ -37,7 +37,7 @@ def render_partial(event) def render_layout(event) info do message = +" Rendered layout #{from_rails_root(event.payload[:identifier])}" - message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)" end end subscribe_log_level :render_layout, :info @@ -48,7 +48,7 @@ def render_collection(event) debug do message = +" Rendered collection of #{from_rails_root(identifier)}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] - message << " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message << " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)" message end end diff --git a/actionview/test/activerecord/controller_runtime_test.rb b/actionview/test/activerecord/controller_runtime_test.rb index e19d3f349b92e..9d6c202a56a18 100644 --- a/actionview/test/activerecord/controller_runtime_test.rb +++ b/actionview/test/activerecord/controller_runtime_test.rb @@ -68,7 +68,7 @@ def test_log_with_active_record wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC [\d\.]+ms\)/, @logger.logged(:info)[1]) end def test_runtime_reset_before_requests @@ -77,20 +77,20 @@ def test_runtime_reset_before_requests wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC [\d\.]+ms\)/, @logger.logged(:info)[1]) end def test_log_with_active_record_when_post post :create wait - assert_match(/ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2]) + assert_match(/ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| GC [\d\.]+ms\)/, @logger.logged(:info)[2]) end def test_log_with_active_record_when_redirecting get :redirect wait assert_equal 3, @logger.logged(:info).size - assert_match(/\(ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2]) + assert_match(/\(ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC [\d\.]+ms\)/, @logger.logged(:info)[2]) end def test_include_time_query_time_after_rendering @@ -98,6 +98,6 @@ def test_include_time_query_time_after_rendering wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| GC [\d\.]+ms\)/, @logger.logged(:info)[1]) end end diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb index 2020cfe5f94ce..bcb2453dd83dc 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -186,14 +186,14 @@ def test_render_uncached_outer_partial_with_inner_cached_partial_wont_mix_cache_ wait *, cached_inner, uncached_outer = @logger.logged(:debug) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner) - assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) + assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| GC: .*?\)$/, uncached_outer) # Second render hits the cache for the _cached_customer partial. Outer template's log shouldn't be affected. @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait *, cached_inner, uncached_outer = @logger.logged(:debug) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner) - assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) + assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| GC: .*?\)$/, uncached_outer) end end diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb index 17347901e9a41..6143d1b83d4de 100644 --- a/activesupport/lib/active_support/notifications/instrumenter.rb +++ b/activesupport/lib/active_support/notifications/instrumenter.rb @@ -117,6 +117,8 @@ def initialize(name, start, ending, transaction_id, payload) @cpu_time_finish = 0.0 @allocation_count_start = 0 @allocation_count_finish = 0 + @gc_time_start = 0 + @gc_time_finish = 0 end def time @@ -144,12 +146,14 @@ def record # :nodoc: def start! @time = now @cpu_time_start = now_cpu + @gc_time_start = now_gc @allocation_count_start = now_allocations end # Record information at the time this event finishes def finish! @cpu_time_finish = now_cpu + @gc_time_finish = now_gc @end = now @allocation_count_finish = now_allocations end @@ -173,6 +177,12 @@ def allocations @allocation_count_finish - @allocation_count_start end + # Returns the time spent in GC (in milliseconds) between the call to #start! + # and the call to #finish! + def gc_time + (@gc_time_finish - @gc_time_start) / 1_000_000.0 + end + # Returns the difference in milliseconds between when the execution of the # event started and when it ended. # @@ -206,6 +216,16 @@ def now_cpu end end + if GC.respond_to?(:total_time) + def now_gc + GC.total_time + end + else + def now_gc + 0 + end + end + if GC.stat.key?(:total_allocated_objects) def now_allocations GC.stat(:total_allocated_objects)