Thursday 21 October 2010

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!!!

No comments: