Merge pull request rails#51770 from Shopify/gc-time

Replace allocations count by GC time in request logs

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)