Improve summary of allocations and time spent rendering

It turns out emitted `render` events from Rails overlap cumulatively if you render a partial in a partial, and there's no nice way to differentiate parent partials from children, so the duration and allocations counts can be way off when the totals from the events are summed. View time can end up being twice as much as the total time, which is obviously impossible. Rails cheats a bit for it's rendering totals by taking the whole page template, but that doesn't work for SR, so allocations and rendering time have to be calculated a bit differently.

Author: Matt-Yorkley

lib/stimulus_reflex/instrumentation.rb

@@ -6,19 +6,42 @@ def self.track(reflex)
       return yield unless reflex.logger && StimulusReflex.config.instrument_reflexes
 
       events = []
+      start_allocations = current_allocations
 
-      time = Benchmark.realtime do
-        ActiveSupport::Notifications.subscribed(proc { |event| events << event }, /^sql.active_record|^render/) do
+      total_time = Benchmark.ms do
+        ActiveSupport::Notifications.subscribed(proc { |event| events << event }, /^sql.active|reflex.render|reflex.sql_render/) do
           yield
         end
       end
 
-      sql, views = events.partition { |e| e.name.match?(/^sql/) }
+      end_allocations = current_allocations
+      sql, rendering = events.partition { |e| e.name.match?(/^sql/) }
 
-      reflex.logger.info "Processed #{reflex.class.name}##{reflex.method_name} in #{(time * 1000).round(1)}ms " \
-        "(Views: #{views.sum(&:duration).round(1)}ms | " \
-        "ActiveRecord: #{sql.sum(&:duration).round(1)}ms | " \
-        "Allocations: #{events.sum(&:allocations)}) \n"
+      reflex.logger.info "Processed #{reflex.class.name}##{reflex.method_name} in #{total_time.round(1)}ms " \
+                           "(Views: #{views_total(rendering).round(1)}ms | " \
+                           "ActiveRecord: #{sql.sum(&:duration).round(1)}ms | " \
+                           "Allocations: #{end_allocations - start_allocations}) \n"
+    end
+
+    def self.instrument_render(reflex, event_name)
+      return yield unless reflex.logger && StimulusReflex.config.instrument_reflexes
+
+      callback = proc { |event| ActiveSupport::Notifications.instrument("reflex.sql_render", {sql_duration: event.duration}) }
+
+      ActiveSupport::Notifications.instrument(event_name) do
+        ActiveSupport::Notifications.subscribed(callback, /^sql.active/) do
+          yield
+        end
+      end
+    end
+
+    def self.views_total(events)
+      rendering, querying = events.partition { |event| event.name.match?(/^reflex.render/) }
+      rendering.sum(&:duration) - querying.sum { |event| event.payload[:sql_duration] }
+    end
+
+    def self.current_allocations
+      GC.stat.key?(:total_allocated_objects) ? GC.stat(:total_allocated_objects) : 0
     end
   end
 end

lib/stimulus_reflex/reflex.rb

@@ -118,7 +118,9 @@ def render(*args)
     options = args.extract_options!
     (options[:locals] ||= {}).reverse_merge!(params: params)
     args << options.reverse_merge(layout: false)
-    controller_class.renderer.new(connection.env.merge("SCRIPT_NAME" => "")).render(*args)
+    StimulusReflex::Instrumentation.instrument_render(self, "reflex.render") do
+      controller_class.renderer.new(connection.env.merge("SCRIPT_NAME" => "")).render(*args)
+    end
   end
 
   # Invoke the reflex action specified by `name` and run all callbacks