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