console_helpers.rb

require 'rblineprof'

module Rblineprof
  module ConsoleHelpers
    include Rblineprof::Helpers

    def lineprof_block(options = {}, &block)
      profile = lineprof(rblineprof_profiler_regex(options[:lineprofiler])) do
        ret = yield
      end
      profile_text(profile, options)
    end

    def profile_text(profile, options)
      sort = options[:lineprofiler_sort]
      mode = options[:lineprofiler_mode] || 'cpu'
      min  = (options[:lineprofiler_min] || 10).to_i * 1000
      summary = options[:lineprofiler_summary]

      # Sort each file by the longest calculated time
      per_file = profile.map do |file, lines|
        total, child, excl, total_cpu, child_cpu, excl_cpu = lines[0]
        wall = summary == 'exclusive' ? excl : total
        cpu  = summary == 'exclusive' ? excl_cpu : total_cpu
        idle = summary == 'exclusive' ? (excl - excl_cpu) : (total - total_cpu)

        [
          file, lines,
          wall, cpu, idle,
          sort == 'idle' ? idle : sort == 'cpu' ? cpu : wall
        ]
      end.sort_by{ |a,b,c,d,e,f| -f }

      div = "\n#{"-" * 80}\n"
      output = []
      per_file.each do |file_name, lines, file_wall, file_cpu, file_idle, file_sort|

        show_src = file_sort > min
        output << div
        subed_name = file_name.sub(Rails.root.to_s + '/', '')
        if mode == 'cpu'
          output << sprintf("% 8.1fms + % 8.1fms (% 5d) | #{subed_name}", file_cpu / 1000.0, file_idle / 1000.0, 1)
        else
          output << sprintf("% 8.1fms | #{subed_name}", file_wall/1000.0)
        end
        next unless show_src
        output << div

        times = []
        File.readlines(file_name).each_with_index do |line, i|
          wall, cpu, calls = lines[i + 1]

          if calls && calls > 0
            if mode == 'cpu'
              idle = wall - cpu
              times << sprintf("% 8.1fms + % 8.1fms (% 5d) |  %5d | ", cpu / 1000.0, idle / 1000.0, calls, i) + line
            else
              times << sprintf("% 8.1fms (% 5d) | %5d | ", wall / 1000.0, calls, i) + line
            end
          end
        end
        output << times
      end
      output.flatten.join
    end

  end
end

helpers.rb

require 'rblineprof'

module Rblineprof
  module Helpers

    def rblineprof_profiler_regex(which)
      escaped_rails_root = Regexp.escape(Rails.root.to_s)
      case which
      when 'app'
        %r{^#{escaped_rails_root}/(app|lib)}
      when 'views'
        %r{^#{escaped_rails_root}/app/view}
      when 'gems'
        %r|^#{escaped_rails_root}/vendor/gems|
      when 'all'
        %r|^#{escaped_rails_root}|
      when 'stdlib'
        %r|^#{Regexp.escape RbConfig::CONFIG['rubylibdir']}|
      else
        %r{^#{escaped_rails_root}/(app|config|lib|vendor/plugin)}
      end
    end

  end
end

ppprofiler

#!/usr/bin/env ruby
require File.dirname(__FILE__) + '/../config/environment'

Paperless::Profiler.new(ARGV[0], ARGV[1].try(:to_i)).run

profiler.rb

require 'benchmark'
require 'rblineprof'
require 'rblineprof/console_helpers'

module Paperless
  class Profiler
    include Rblineprof::ConsoleHelpers

    BENCHMARK_FORMAT = "User  %u  | System  %y  | Total %t  | Wall  %r"

    def initialize(profilee, n)
      @profilee = profilee
      @cache_enabled = Paperless::Content::Cacheable.enabled
      @benchmark_times = n || 100
      instance_eval <<-EOT
        def wrapped_profilee
          Rails.logger.debug "==================="
          #{@profilee}
          Rails.logger.debug "==================="
        end
      EOT
    end

    def run_subscriber
      @counts ||= {}
      GC.start
      start = ObjectSpace.count_objects[:TOTAL] - ObjectSpace.count_objects[:FREE]
      counts = {}
      counts[:sql] = subscribe_and_count('sql.active_record') do
        counts[:redis] = subscribe_and_count('execute_command.redis') do
          counts[:cache_read] = subscribe_and_count('cache_read.active_support') do
            counts[:cache_write] = subscribe_and_count('cache_write.active_support') do
              wrapped_profilee
            end
          end
        end
      end
      finish = ObjectSpace.count_objects[:TOTAL] - ObjectSpace.count_objects[:FREE]
      counts[:objects] = [finish - start, 0]
      @counts[@cache_enabled] = counts
    end

    def run_benchmark
      @benchmark ||= {}
      @benchmark[@cache_enabled] = Benchmark.measure { @benchmark_times.times { wrapped_profilee } }
    end

    def run_lineprof
      @lineprof_output ||= {}
      @lineprof_output[@cache_enabled] = lineprof_block do
        wrapped_profilee
      end
    end

    def run
      output_header
      # prime
      toggle_caching
      run_subscriber
      toggle_caching
      run_subscriber

      toggle_caching
      run_benchmark
      toggle_caching
      run_benchmark

      toggle_caching
      run_lineprof
      toggle_caching
      run_lineprof

      output_to_console
    end

    def hr
      puts "\n#{"=" * 80}\n\n"
    end

    def output_header
      hr
      puts "#### Running `#{@profilee}`"
      puts
      puts "#### Revision #{CURRENT_REVISION}"
      puts
      puts "[#{Time.now}] Running the profile"
    end

    def output_to_console
      puts "[#{Time.now}] Done"
      hr
      puts "## Basic Stats: "
      puts
      puts "### Cache on"
      puts
      puts format_benchmark(@benchmark[true])
      puts
      puts "### Cache off"
      puts
      puts format_benchmark(@benchmark[false])
      puts
      hr
      puts "## Events"
      puts
      puts "### Cache on"
      puts
      puts format_counts(@counts[true])
      puts
      puts "### Cache off"
      puts
      puts format_counts(@counts[false])
      hr
      puts "## Lineprof"
      puts
      puts "### Cache on"
      puts
      puts "```ruby"
      puts @lineprof_output[true]
      puts "```"
      puts
      puts "### Cache off"
      puts
      puts "```ruby"
      puts @lineprof_output[false]
      puts "```"
    end

    private
    def format_counts(counts)
      output = []
      counts.each do |name, (count, time)|
        output << "- #{name.to_s.humanize} #{count} in #{'%0.2f' % time}ms"
      end
      output.join("\n")
    end

    def format_benchmark(benchmark)
      out = ""
      out << "- #{@benchmark_times} | #{benchmark.format(BENCHMARK_FORMAT)}\n"
      out << "- 1 | #{(benchmark / @benchmark_times).format(BENCHMARK_FORMAT)}\n"
      out
    end

    def subscribe_and_count(to, &block)
      count = 0
      duration = 0
      subscriber = ActiveSupport::Notifications.subscribe(to) do |*args|
        e = ActiveSupport::Notifications::Event.new(*args)
        count += 1
        duration += e.duration
      end
      yield
      ActiveSupport::Notifications.unsubscribe(subscriber)
      [count, duration]
    end

    def toggle_caching
      @cache_enabled = !@cache_enabled
      Rails.cache.clear if @cache_enabled
      Paperless::Content::Cacheable.enabled = @cache_enabled
      ActionController::Base.perform_caching = @cache_enabled
      wrapped_profilee
    end

  end
end