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

40% speedup using Nokogiri!

Cut to the chase...

To cut your XML-processing time dramatically, sudo gem install nokogiri then add the following to config/environment.rb inside the Rails initializer.

config.gem "nokogiri"
ActiveSupport::XmlMini.backend='Nokogiri'

Back-story and pretty pics

The problem

So, our site makes heavy use of ActiveResource [1], meaning that most of our data is located remotely.

Not surprisingly, some of our pages are *really* slow, so I landed the task of speeding them up. Apart from page-caching (not possible), fragment caching (only helps on the *second* hit), or some complicated messy idea of data-caching locally (tedious and likely to be evil); my first thought was to reduce the number of network hits. Clearly that's a high pain point, especially on our heavy pages that have many resource fetches.

Before I dove into performance hacks and updating the business logic into twisty little data reuse-patterns for network-hit reduction... I decided to actually try profiling.

I've been setting up a ruby-prof and kcachegrind recently[2]... and figured I should at least give that a look-at to see if my assumptions are correct.

I'm really glad I did, because when I ran it over our heaviest action, I saw that all the highest-weight method-calls led back to some form of ReXML parsing.

Searching on the ReXML components showed that the heaviest ReXML method took up a whopping 1 million process cycles. When our total process-cycles came to 5.8 million - that's a significant chunk of time spent in that one library.

As I mentioned - our site makes heavy use of ActiveResource, and one *big* problem with ActiveResource is that all your objects are parsed and re-parsed as xml for every fetch of data... so, in hindsight, it's fairly obvious that our site would spend a *lot* of time in the XML-parsing library. Any speedup in that department would help us immensely.

The solution?

We've recently been to Rails underground, and one of the lectures[3] had a slide comparing the speed of ReXML to several other ruby XML-parsing libraries[4]. Nokogiri came out as a clear winner in the speed department. The loser was equally clear... that being the Rails-default: ReXML

So, switching out the library would be an obvious speed win.

As it turns out - it's really easy to do this. Just install the gem, and require it in your Rails initializer using the instructions at the top of this post

But did it really help?

It seemed faster... but can we prove it?

Yup.

---

Notes

[1] through the HyperactiveResource plugin
[2]I'll be giving a talk at LRUG on 12/08/2009 on how to use and interpret ruby-prof and kcachegrind
[3]During the talk by Maik Schmidt on Sneaking Ruby & Rails Into Big Companies
[4] I'm not sure, but it's possibly the one from this page comparing Ruby-XML performance benchmarks