Ruby Instrumentation

around_action :log_sql_count, only: :slow_action

def slow_action
  measure("find records") do
    @records = Model.includes(:assoc).all
  end

  measure("compute stuff") do
    @computed = expensive_ruby_work(@records)
  end

  measure("render") do
    render_to_string(partial: 'results', layout: false, formats: [:html], locals: {})
  end
end

private

def log_sql_count
  sql_count = 0

  subscriber = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
    sql_count += 1 unless args.last[:name] == 'SCHEMA'
  end

  yield
ensure
  ActiveSupport::Notifications.unsubscribe(subscriber)

  Rails.logger.info "=== #{action_name} SQL queries: #{sql_count} ==="
end

def measure(label)
  start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  result = yield

  elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start

  Rails.logger.info "  [MEASURE] #{label}: #{elapsed.round(3)}s"
  result
end