Instrument Reflex processing in development and log summary

Author: Matt-Yorkley

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/instrumenter.rb

@@ -0,0 +1,24 @@
+# frozen_string_literal: true
+
+module StimulusReflex
+  class Instrumenter
+    def self.instrument(reflex)
+      return yield unless reflex.logger && StimulusReflex.config.instrument_reflexes
+
+      events = []
+
+      time = Benchmark.realtime do
+        ActiveSupport::Notifications.subscribed(lambda{|event| events << event }, /^sql.active_record|^render/) do
+          yield
+        end
+      end
+
+      sql, views = 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{|e| e.duration }.round(1)}ms | " +
+                           "ActiveRecord: #{sql.sum{|e| e.duration }.round(1)}ms | " +
+                           "Allocations: #{events.sum{|e| e.allocations }}) \n"
+    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/instrumenter"
 
 class StimulusReflex::Reflex
   prepend StimulusReflex::CableReadiness
@@ -122,7 +123,9 @@ def render(*args)
 
   # Invoke the reflex action specified by `name` and run all callbacks
   def process(name, *args)
-    run_callbacks(:process) { public_send(name, *args) }
+    StimulusReflex::Instrumenter.instrument(reflex) 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.