JSON Serialization Performance Enigma

I am pulling my hair out trying to optimize one of my controller actions. I've encountered a very strange issue where if I pass in a custom option to my as_json method it seems to slow down the serialization. Below is a comparison benchmark. @location is an array with about 60 location ActiveRecord objects.

x.report("as_json") do
   @location.as_json(:methods => [:nearby_categories]) 
end

x.report("js user") 开发者_JAVA技巧 do 
  @json = @locations.as_json(
    :user_data => {:favorites => [], :rank_rewards => []}, 
    :methods => [:nearby_categories]) 
end

Here is the difference:

as_json  0.000000   0.000000   0.000000 (  0.000031)
js user  1.320000   0.060000   1.380000 (  1.390047)

I have overidden the serializable_hash method on my location model:

def serializable_hash(options = {})
  only = %w(address business_id city franchise_name id lat lng phone rating state total_reviews zip)
  options ||= {}
  options[:only] ||= only.map(&:to_sym)
  hash = super(:only => options[:only], :except => options[:except], :methods => options[:methods])

# ... 
# omitted code which sets additional attributes
# ...

if options && (data = options[:user_data])
  fav =
  if data && favs = data[:favorites]
    favs.select { |f| f.location_id == self.id }.first
  else
    user.favorites.find_by_location_id(self.id)
  end
  hash["favorite_id"] =  fav ? fav.id : nil

  if data && ranks = data[:rank_rewards]
    if rank = ranks.select {|urr| urr.location_id == self.id }.first
      hash["user_rank_level"] = {:name => rank.rank_reward_level.name, :user_rank_reward_id => rank.id}
    end
  else
    hash["user_rank_level"] = self.user_rank(user)
  end
 end

 hash
end

Now passing in two empty arrays should not have any effect on this code and just to make double-sure I tried passing in an option that I'm not handling:

x.report("js user")  do 
  @json = @locations.as_json(
    :garbage => {}, 
    :methods => [:nearby_categories]) 
end

And I get the same result:

js user  1.230000   0.070000   1.300000 (  1.295439)

I'm not even passing any non-standard options to super. How can this be happening?

---

One way to find this kind of problem is by measuring various pieces.

Another way is to trap it in the act. If you use the rdb debugger you can randomly pause it and say where to display the stack. The more time it's costing, the better the chance of catching it.

Do it several times. Any line of code you see on more than one stack sample, if you can optimize it, will save substantial time. That's the random-pause technique. Here's an example, which happens to be in python but works in any language.