JSON Serialization Performance Enigma

Question

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")  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?

If you typed the first code snippet correctly, it uses @location and the second @locations. Are you serializing the same object? — Steve Ross, May 30 '11 at 20:13
Steve, Steve, Steve, you rock. That was causing a huge red herring. If I fix my typo the "as_json" step takes 1.3 secs and the "js user" step lasts a very short amount of time. So it must be loading the AR objects in memory and whatever asks for them first takes time. — Dan Hixon, May 31 '11 at 01:47

score 0 · Answer 1 · edited May 23 '17 at 12:19

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.

JSON Serialization Performance Enigma

1 Answers1