Instrument Reflex processing in development and log a summary

lib/stimulus_reflex/configuration.rb

@@ -14,7 +14,7 @@ def configuration
   end
 
   class Configuration
-    attr_accessor :on_failed_sanity_checks, :on_missing_default_urls, :parent_channel, :logging, :logger, :middleware, :morph_operation, :replace_operation, :precompile_assets
+    attr_accessor :on_failed_sanity_checks, :on_missing_default_urls, :parent_channel, :logging, :logger, :middleware, :morph_operation, :replace_operation, :precompile_assets, :instrument_reflexes
 
     DEFAULT_LOGGING = proc { "[#{session_id}] #{operation_counter.magenta} #{reflex_info.green} -> #{selector.cyan} via #{mode} Morph (#{operation.yellow})" }
 
@@ -36,6 +36,7 @@ def initialize
       @morph_operation = :morph
       @replace_operation = :inner_html
       @precompile_assets = true
+      @instrument_reflexes = Rails.env.development?
     end
   end
 end

lib/stimulus_reflex/instrumentation.rb

@@ -0,0 +1,47 @@
+# frozen_string_literal: true
+
+module StimulusReflex
+  class Instrumentation
+    def self.track(reflex)
+      return yield unless reflex.logger && StimulusReflex.config.instrument_reflexes
+
+      events = []
+      start_allocations = current_allocations
+
+      total_time = Benchmark.ms do
+        ActiveSupport::Notifications.subscribed(proc { |event| events << event }, /^sql.active|reflex.render|reflex.sql_render/) do
+          yield
+        end
+      end
+
+      end_allocations = current_allocations
+      sql, rendering = events.partition { |e| e.name.match?(/^sql/) }
+
+      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

@@ -2,6 +2,7 @@
 
 require "stimulus_reflex/cable_readiness"
 require "stimulus_reflex/version_checker"
+require "stimulus_reflex/instrumentation"
 
 class StimulusReflex::Reflex
   prepend StimulusReflex::CableReadiness
@@ -117,12 +118,16 @@ 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
   def process(name, *args)
-    run_callbacks(:process) { public_send(name, *args) }
+    StimulusReflex::Instrumentation.track(self) do
+      run_callbacks(:process) { public_send(name, *args) }
+    end
   end
 
   # Indicates if the callback chain was halted via a throw(:abort) in a before_reflex callback.