Profiling inside of procs

I've been using ruby-prof and kcachegrind to delve into our code recently - in an attempt to speed up some of our heaviest views - these are mainly big admin pages listing, say, all orders that are waiting on backordered products.

One of the joys of kcachegrind is the ability to see the actual lines of source-code with the actual time spent in each LOC nicely indicated. You can then click on that line and it'll jump into the slow method that is called by that line.. so you can dig down to where the actual pain is being caused in your app.

One of the problems with with the source-code tracking, though is that it just doesn't deal well with ruby procs. Kcachegrind assumes it's some kind of method-call, but when you click on that LOC, it doesn't take you to the code inside that proc, but you instead end up diving into the *ruby* source-code itself... definitions of blocks and procs etc... which are all aggregated together and thus you can't tease out the bits that you actually want (ie the code operating inside the proc itself).

So if you have something such as the following wrapping almost your entire view page:

   @orders.each do |order|
      # tons of lines....
      # displaying and formatting the order values follow...
      # ...
   end

You'll often only get a single, aggregated line of information n the "orders.each" line... and clicking it only takes you to Ruby's Array#each rather than your actual code.

Entirely unhelpful.

For the sake of profiling that code, though, you can unroll it into a while loop - just to check which LOC are the ones giving the pain by switching it (temporarily) to:

   idx = 0
   while idx < @orders.size do
      order = @orders[idx]
      idx +=1 # don't forget this line or it will take some time to finish.. ;)
      # tons of lines....
      # displaying and formatting the order values follow...
      # ...
   end

It's a dirty hack, but in the absence of "each" it's kind of a necessary evil - and it works. Just make sure to remove it once you're done!!!

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

Faking startup and shutdown with ActiveSupport::TestCase

Time-was we didn't just have setup and teardown in our Tests (which are run for every single test case)... we could also have a startup/shutdown pair that ran once per proper Test-case class (ie once at the beginning of all tests in a set).

This was a perfect place to put run-once-only things - especially useful if, say, you wanted to run ruby-prof over your tests. You could put the RubyProf.start in startup and have it print out a callgraph in the shutdown...

ActiveSupport::TestCase doesn't let us have our startup/shutdown anymore... so what to do?

Fake it with at_exit

  # quick-and-dirty class var to tell us if we've already registered the
  # at_exit RubyProf function.
  @@register_done = false
  # register the stop-ruby-prof stuff
  # We want it to spit out a RubyProf callgraph after it's run this test
  # case.
  # You can either: call this function directly in a single test case or
  # test-suite eg: "register_rubyprof"
  # If you pass a value to "RUN_RUBY_PROF" on the command-line - it will
  # also run this register function for you. eg:
  # RUN_RUBY_PROF=true rake test:units TEST=test/unit/widget_test.rb
  def register_rubyprof
    require 'ruby-prof'
    return if @@register_done
    p "starting RubyProf"
    RubyProf.start

    path_base = "#{RAILS_ROOT}/tmp/performance/ruby-prof"

    p "started! Now registering exit-function"
    at_exit do
      p "All done - stopping RubyProf" 
      result = RubyProf.stop

      p "Stopped! now printing call graph"
      timestamp = Time.now.strftime('%Y-%m-%d-%H-%M-%S')
      # try and make the callgraph filename meaningful to the test-run
      filename_base = "rubyprof_#{self.class.name}_#{timestamp}"

      # Print a call tree profile to text for kcachegrind to use
      printer = RubyProf::CallTreePrinter.new(result)
      printer.print(File.open("#{path_base}/#{filename_base}_calltree.txt", 'w'), 0)
      p "All Done. Good luck profiling!"
      end
    @@register_done = true
  end
  # will setup the reguster-rubyprof function if we have set the
  # RUN_RUBYPROF constant to true
  setup :register_rubyprof if RUN_RUBY_PROF