diff --git a/lib/stimulus_reflex/instrumentation.rb b/lib/stimulus_reflex/instrumentation.rb index 332e55c6..db7047b3 100644 --- a/lib/stimulus_reflex/instrumentation.rb +++ b/lib/stimulus_reflex/instrumentation.rb @@ -6,19 +6,39 @@ 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/) } + render, sql_render = rendering.partition { |e| e.name.match?(/^reflex.render/) } + render_time = render.sum(&:duration) - sql_render.sum{|event| event.payload[:sql_duration] } - 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: #{render_time.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.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..8418906c 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_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