From 06d3b358df46c357b75e2fa6c9014d4d11ba4e32 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 5325827e56a..02f8493cb68 100644 --- a/actionpack/lib/action_controller/log_subscriber.rb +++ b/actionpack/lib/action_controller/log_subscriber.rb @@ -33,7 +33,7 @@ module ActionController 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 eecbdd19c88..3582aee4e1e 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -18,7 +18,7 @@ module ActionView 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 @@ module ActionView 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 @@ module ActionView 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 @@ module ActionView 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 e19d3f349b9..aa0a20af891 100644 --- a/actionview/test/activerecord/controller_runtime_test.rb +++ b/actionview/test/activerecord/controller_runtime_test.rb @@ -68,7 +68,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase 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 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase 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 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase 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 2020cfe5f94..bcb2453dd83 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -186,14 +186,14 @@ class AVLogSubscriberTest < ActiveSupport::TestCase 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 17347901e9a..6143d1b83d4 100644 --- a/activesupport/lib/active_support/notifications/instrumenter.rb +++ b/activesupport/lib/active_support/notifications/instrumenter.rb @@ -117,6 +117,8 @@ module ActiveSupport @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 @@ module ActiveSupport 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 @@ module ActiveSupport @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 @@ module ActiveSupport 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)