Peter's Blog

I was working on this site and noticed how slow it was, particularly on rss feeds. This was just after managing to completely screw up my ruby gem installation (apt-get remove rubygems/apt-get install rubygems didn't reinstall rubygems) which I only cured by upgrading the server to ubuntu hardy. I wasn't sure whether I had blown something in the upgrade (the server did a fsck when I rebooted it but maybe only because it had been 'up' for 100 days) or whether the code was just slow.

How to pinpoint the cause of the slowness? Profiling. Some research revealed I can profile ruby code as follows:

• install a ruby profiler:

  gen install ruby-prof
  

• insert some profiling code around your suspect slow code (in my case around the rss formatting):

     1  gem install ruby-prof
     2  
     3     require 'ruby-prof'
     4  
     5     RubyProf.start
     6  
     7     {code to profile}
     8  
     9   result = RubyProf.stop
    10     printer = RubyProf::FlatPrinter.new(result)
    11     printer.print(File.open( '/tmp/prof.txt', "w"), 0)
  

• run script/server and try downloading rss
• wait because it is very slow
• examine the profile

  vim /tmp/prof.txt
  

• lament

This told me that 70% of my time was being spent in a gsub in my wilki code that I added last week. gsub was being called 1800 times (!) and when I commented out the new gsub call the rss was rendered much faster.

The thing is, my wilki formatting is supposed to be cached, it should only be done when a posting is modified, not every time the post is rendered. Turns out to be because updating a field in an ActiveRecord doesn't automatically cause it to be saved because it is dirty, an explicit save helped. Problem solved, now downloading the rss feed doesn't max out my cpu for 20 seconds

NB (clarification): the rss doesn't go through the rails fragment cache.