The problem

When I first launched this blog I decided to benchmark how long it takes to generate various pages on my web site, I have found that the two slowest pages to generate are my atom and rss feeds. They take on average 150ms to generate.

So, I decided to dig down and figure out why this is so slow. After watching the Railscast episode about request profiling I decided to try it out on my atom feed.

So, I installed the ruby-prof gem and created a little script (“get ‘/posts.atom’”) and ran it 30 times:

script/performance/request -n 30 lib/profile_atom_feed.rb  

Next up I dug into the output (which is in the rails tmp folder)

I discovered there were a TON of calls being made to the function String#to_xs, they all seemed to be originating from builder and they were taking more than 50% of the time. (It turns out profiler lies and they were taking more than 90% of the time)

orginal_stringxs833×114 13.3 KB

Let’s look at the source code in builder:

class Fixnum
  XChar = Builder::XChar if ! defined?(XChar)

  # XML escaped version of chr
  def xchr
    n = XChar::CP1252[self] || self
    case n when *XChar::VALID
      XChar::PREDEFINED[n] or (n<128 ? n.chr : "&##{n};")
    else
      '*'
    end
  end
end

class String
  # XML escaped version of to_s
  def to_xs
    unpack('U*').map {|n| n.xchr}.join # ASCII, UTF-8
  rescue
    unpack('C*').map {|n| n.xchr}.join # ISO-8859-1, WIN-1252
  end
end

Ok, so string_xs is a method for turning a string into an xml safe string. It will call Fixnum::xchr for every letter it is passed. Builder needs to ensure that all the text it renders is xml safe. So there you are, once per letter (barring xml tags) in my atom feed, a call is made to Fixnum::xchr, this involved a complex bit of lookup logic in ranges. Nothing is wrong with this code, but it does involve looking up a value in up to 2 hashs (CP1252 and PREDEFINED) and 1 range lookup (VALID). This all adds up, especially if you have a big rss document.

I explored some mini optimizations:

This monkey patch

class Fixnum
  alias_method :xchr_old, :xchr  

  def xchr
    @@XChar_Cache ||= (0..255).map{|x| x.send :xchr_old} 
    @@XChar_Cache[self] or xchr_old 
  end 

end

Gives me 2X speed improvement. I suspect that with a bit of Ruby fu you could get this down to a 4x speed improvement. But… I decided to Google a bit.

The solution

The easiest thing to do is

sudo gem install fast_xs 

This makes my feed generation 10x faster. What it does is natively implement String::to_xs, the good news is that rails 2.0.2 and later, is aware of this patch and all you need to do is install the gem and restart your rails app.

Here is a screenshot of the state of affairs after the patch.

after_patch_stringxs712×85 9.88 KB