Quick RubyProf action filters

A good while back I spoke about using ruby_prof and kcachegrind at LRUG.

I was asked back then if I could stick up my ruby=prof filter-code... and I've been just a *little* bit slack about getting around to that... but recently I've been profiling again, so I thought I'd bring it out again for general use.

Here's a way to quickly add ruby-prof profiling to any given *action*. Use the following around_filter on your action. Note: this will *only* profile what happens in the controller-action. I use this on our uber-heavy summary-page views to make sure that the mammoth Active Record fetches aren't themselves the problem... before getting onto a full-stack profiling-run.

  around_filter :profile_it, :only => :my_slow_action

  # profiling around-filter - just does the controller-action only
  def profile_it
    require 'ruby-prof'

    logger.info "Starting profiling"
    # profile the first set
    RubyProf.start

    # actually do the action
    yield

    result = RubyProf.stop
    logger.info "Profiling finished, printing files"

    # Print the callgraph profile
    filename = Time.now.strftime("RubyProf_#{params[:controller].gsub('/','-')}_#{params[:action].gsub('/','-')}_%Y-%m-%d_%H:%M:%S.grind")
    File.open(filename,'w') do |the_file|
      printer = RubyProf::CallTreePrinter.new(result)
      printer.print(the_file, 0)    
    end
    true
  end

or to profile the full stack through to the template render, you'll want to split the start/stop. I tend to call start_profiling at the top of the controller action (to get rid of most of the rails loading time), and then call stop_profiling at the bottom of the relevant layout.

Put this into application_controller.rb

  # Will only start the profiling... to stop, you'll need to use the helper
  # at the bottom of your template.
  # Use this pair to catch template-rendering in your profiling data
  # Pass ":wall" as a variable to use wall-time instead of process-time
  def start_profiling(time_type = nil)
    require 'ruby-prof'

    logger.info "Starting profiling"

    RubyProf.measure_mode = RubyProf::WALL_TIME if time_type == :wall

    # profile the first set
    RubyProf.start
  end

Put this into application_helper.rb

  # Use this helper in your template to stop profiling. Asumes you have
  # called "start_profiling" in your action somewhere
  # Will asplode if you haven't actually *started* a profiler
  # (eg if the previous action threw an exception before completing the profiling run)
  def stop_profiling
    if RubyProf.running?
      result = RubyProf.stop
      logger.info "Profiling finished, printing files"

      # Print the callgraph profile
      filename = Time.now.strftime("RubyProf_#{params[:controller].gsub('/','-')}_#{params[:action].gsub('/','-')}_%Y-%m-%d_%H:%M:%S.grind")
      File.open(filename,'w') do |the_file|
        printer = RubyProf::CallTreePrinter.new(result)
        printer.print(the_file, 0)    
      end
    else
      raise "Stop profiling called when no profiling started!!!"
    end
    true
  end