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.

Author: byroot

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(" | ")})"

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

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,27 +77,27 @@ 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
     get :db_after_render
     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

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
 

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)