From ddcdc0c3dd650d5d1eca8a070c0d23c0de0f3c95 Mon Sep 17 00:00:00 2001
From: Matt-Yorkley <9029026+Matt-Yorkley@users.noreply.github.com>
Date: Sat, 23 Mar 2024 18:55:44 +0000
Subject: [PATCH] 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.
---
 lib/stimulus_reflex/instrumentation.rb | 28 +++++++++++++++++++-------
 lib/stimulus_reflex/reflex.rb          |  8 ++++++--
 2 files changed, 27 insertions(+), 9 deletions(-)

diff --git a/lib/stimulus_reflex/instrumentation.rb b/lib/stimulus_reflex/instrumentation.rb
index 332e55c6..b4c42d8a 100644
--- a/lib/stimulus_reflex/instrumentation.rb
+++ b/lib/stimulus_reflex/instrumentation.rb
@@ -6,19 +6,33 @@ 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_record|reflex.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: #{rendering.sum(&:duration).round(1)}ms | " \
+                           "ActiveRecord: #{sql.sum(&:duration).round(1)}ms | " \
+                           "Allocations: #{end_allocations - start_allocations}) \n"
+    end
+
+    def self.instrument(reflex, event_name)
+      return yield unless reflex.logger && StimulusReflex.config.instrument_reflexes
+
+      ActiveSupport::Notifications.instrument event_name, this: :data do
+        yield
+      end
+    end
+
+    def self.current_allocations
+      GC.stat.key?(:total_allocated_objects) ? GC.stat(:total_allocated_objects) : 0
     end
   end
 end
diff --git a/lib/stimulus_reflex/reflex.rb b/lib/stimulus_reflex/reflex.rb
index 04b7caca..e4071174 100644
--- a/lib/stimulus_reflex/reflex.rb
+++ b/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 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
@@ -154,6 +156,8 @@ def params
   # eg. `morph dom_id(@posts), render_collection(@posts)`
   def render_collection(resource, content = nil)
     content ||= render(resource)
-    tag.div(content.html_safe, id: dom_id(resource).from(1))
+    StimulusReflex::Instrumentation.instrument self, "reflex.render" do
+      tag.div(content.html_safe, id: dom_id(resource).from(1))
+    end
   end
 end