Ruby 1.9 slower than Ruby 1.8?

Question

I have a Rails 2.3.8 app with an action that pulls a large amount of data from a database and renders it with anywhere from 300-600 partials (recursively rendering a tree-type structure). Benchmarking one request gives me response times of about 7 seconds.

I thought that upgrading my Ruby version to 1.9 from 1.8 would give me a performance gain, but as I benchmark the 1.9 version, I'm getting response times of about 9 seconds (2 seconds slower than on 1.8). This was quite surprising to me.

What factors would cause Ruby 1.9 to execute slower than Ruby 1.8?

Below is a portion of the log file.

Ruby 1.8

Rendered family_index/descendants/_fi_hover (0.5ms)
Rendered family_index/descendants/_descendant (4.6ms)
Rendered search/_search_div (0.1ms)
Rendered family_index/descendants/_fi_hover (0.7ms)
Rendered family_index/descendants/_descendant (4.7ms)
Rendered search/_search_div (0.1ms)
Rendered family_index/descendants/_fi_hover (0.5ms)
Rendered family_index/descendants/_descendant (4.5ms)
Rendered family_index/descendants/_fi_hover (0.5ms)
Rendered family_index/descendants/_descendant (37.9ms)
Rendered family_index/surname_groups/_pedigree (3162.9ms)
Rendered shared/_headers (4.6ms)
Rendered shared/_new_messages (0.6ms)
Rendered shared/_home_logo (1.1ms)
Rendered shared/_login_box (4.0ms)
Rendered shared/_navigation (13.6ms)
Rendered shared/_flash_messages (0.8ms)
Rendered shared/_footer (1.0ms)
Rendered shared/_analytics (0.8ms)
Completed in 4552ms (View: 3352, DB: 147) | 200 OK [http://localhost/family_index/surname_groups/31]

Ruby 1.9

Rendered family_index/descendants/_fi_hover (0.3ms)
Rendered family_index/descendants/_descendant (1.9ms)
Rendered search/_search_div (0.1ms)
Rendered family_index/descendants/_fi_hover (0.4ms)
Rendered family_index/descendants/_descendant (2.0ms)
Rendered search/_search_div (0.1ms)
Rendered family_index/descendants/_fi_hover (0.3ms)
Rendered family_index/descendants/_descendant (1.9ms)
Rendered family_index/descendants/_fi_hover (0.3ms)
Rendered family_index/descendants/_descendant (15.1ms)
Rendered family_index/surname_groups/_pedigree (762.8ms)
Rendered shared/_headers (2.6ms)
Rendered shared/_new_messages (0.7ms)
Rendered shared/_home_logo (0.9ms)
Rendered shared/_login_box (3.6ms)
Rendered shared/_navigation (7.3ms)
Rendered shared/_flash_messages (0.7ms)
Rendered shared/_footer (0.8ms)
Rendered shared/_analytics (0.6ms)
Completed in 5736ms (View: 942, DB: 128) | 200 OK [http://localhost/family_index/surname_groups/31]

It appears that Ruby 1.9 is rendering the views and processing the database faster, but is still completing the request slower.

Ruby 1.8:

Completed in 4552ms (View: 3352, DB: 147) | 200 OK [http://localhost/family_index/surname_groups/31]

Ruby 1.9:

Completed in 5736ms (View: 942, DB: 128) | 200 OK [http://localhost/family_index/surname_groups/31]

Update 10-26-2010

I've found the bottleneck in my code. It comes from a line that loads up a ton of ActiveRecord items using the lazy-eager loaded associations. The DB time is small, but I'm guessing that all of the object allocation is taking a toll. Here is my association:

has_many  :deep_branches,
            :class_name => "FamilyIndex::Branch",
            :include => {
              :descendant => [:state, :county, {:wives => {:marriage => [:state,:county,:reference] }}, :reference, {
                :children => [:state, :county, {:wives => {:marriage => [:state,:county,:reference] }}, :reference, {
                  :children => [:state, :county, {:wives => {:marriage => [:state,:county,:reference] }}, :reference, {
                    :children => [:state, :county, {:wives => {:marriage => [:state,:county,:reference] }}, :reference] # add marriages to this data
                  }]
                }]
              }]
            }

Without doing the eager loading, the complete action takes about 40 seconds to complete, so using the :include gives about a 10x performance increase. Still looking for a way to speed this up. Perhaps caching is the only way to go from here.

Answer 1

One area where 1.9 can be slower than 1.8 is string handling.

Since 1.9 has proper unicode support indexing or a slicing a unicode-encoded string can take significantly longer than in 1.8 because in 1.8 string[i] will just return the ith byte, while in 1.9 it has to go through the string to find the ith character.

If you do a lot of string handling and do not need proper unicode support, you can just set the encoding to ASCII or possibly binary, which should speed up the string handling considerably.

Answer 2

So the area of my request that was taking the longest time to process was the massive load of data through ActiveRecord's lazy eager loading (see the association listed in the question). I'm not familiar enough with the internals of ActiveRecord 2.3.8, so ultimately I'm unsure of what was causing the "slowness".

I ended up doing my own type of eager loading—fetching all person records in one query, all states in one query, and other associated objects that I needed, putting them in a Hash and then stitching them together into their tree structure.

This has improved performance greatly, bringing the request time down to 1-1.5 seconds. The improvement benefits the app running in both 1.8 and 1.9 and now my app is a little bit faster running in 1.9.

Thanks everyone for your help!