Quick dive into Ruby ORM object initialization


Yesterday I did some quick digging into how ORM objects are initialized and the performance cost associated to that. In other words, I wanted to see what’s going on when you initialize an ActiveRecord object.

Before I show you the benchmark numbers and you jump to conclusions, it’s important to realize that in the grand scheme of things, the performance cost we are talking is small enough that it is certainly not the main reason why your application is slow. Spoiler alert: ActiveRecord is slow but the cost of initialization isn’t by far the worse part of ActiveRecord. Also, even though this article doesn’t make activeRecord look good, and I’m not trying to diss it. It’s a decent ORM that does a great job in most cases.

Let’s get started by the benchmarks number to give us an idea of the damage (using Ruby 1.9.3 p125):

 

                                                             | Class | Hash  | AR 3.2.1 | AR no protection | Datamapper | Sequel |
--------------------------------------------------------------------------------------------------------------------------------------
.new() x100000                                               | 0.037 | 0.049 | 1.557    | 1.536            | 0.027      | 0.209  |
.new({:id=>1, :title=>"Foo", :text=>"Bar"}) x100000          | 0.327 | 0.038 | 6.784    | 5.972            | 4.226      | 1.986  |

 

You can see that I am comparing the allocation of a Class instance, a Hash and some ORM models. The benchmark suite tests the allocation of an empty object and one with passed attributes. The benchmark in question is available here.

As you can see there seems to be a huge performance difference between allocating a basic class and an ORM class. Instantiating an ActiveRecord class is 20x slower than instantiating a normal class, while ActiveRecord offers some extra features, why is it so much slower, especially at initialization time?

The best way to figure it out is to profile the initialization. For that, I used perftools.rb and I generated a graph of the call stack.

Here is what Ruby does (and spends its time) when you initialize a new Model instance (click to download the PDF version):

 

Profiler diagram of AR model instantiation by Matt Aimonetti

 

This is quite a scary graph but it shows nicely the features you are getting and their cost associated. For instance, the option of having the before and after initialization callback cost you 14% of your CPU time per instantiation, even though you probably almost never use these callbacks. I’m reading that by interpreting the node called ActiveSupport::Callback#run_callbacks, 3rd level from the top. So 14.1% of the CPU time is spent trying to run callbacks. As a quick note, note that 90.1% of the CPU time is spent initializing objects, the rest is spent in the loop and in the garbage collection (because the profiler runs many loops). You can then follow the code and see how the code works, creating a dynamic class callback method on the fly (the one with the long name) and then recreating the name of this callback to call it each time the object is allocated. It sounds like that’s a good place for some micro optimizations which could yield up to 14% performance increase in some cases.

Another major part of the CPU time is spent in ActiveModel’s sanitization. This is the piece of code that allows you to block some model attributes to be mass assigned. This is useful when you don’t want to sanitize your incoming params but want to create or update a model instance by using all the passed user params. To avoid malicious users to modify some specific params that might be in your model but not in your form, you can protect these attributes. A good example would be an admin flag on a User object. That said, if you manually initialize an instance, you don’t need this extra protection, that’s why in the benchmark above, I tested and without the protection. As you can see, it makes quite a big difference. The profiler graph of the same initialization without the mass assignment protection logically ends up looking quite different:

 


Matt Aimonetti shows the stack trace generated by the instantiation of an Active Record model

 

Update: My colleague Glenn Vanderburg pointed out that some people might assuming that the shown code path is called for each record loaded from the database. This isn’t correct, the graph represents instances allocated by calling #new. See the addition at the bottom of the post for more details about what’s going on when you fetch data from the DB.

I then decided to look at the graphs for the two other popular Ruby ORMs:

Datamapper

 

and Sequel

 

 

While I didn’t give you much insight in ORM code, I hope that this post will motivate you to sometimes take a look under the cover and profile your code to see what’s going on and why it might be slow. Never assume, always measure. Tools such as perftools are a great way to get a visual feedback and get a better understanding of how the Ruby interpreter is handling your code.

UPDATE:

I heard you liked graphs so I added some more, here is what’s going on when you do Model.first:

 

Model.all

 

And finally this is the code graph for a call to Model.instantiate which is called after a record was retrieved from the database to convert into an Object. (You can see the #instantiate call referenced in the graph above).

 


Similar Posts

, , , ,

  1. #1 by johno - February 23rd, 2012 at 11:56

    I don’t know man. If I were to instantiate 100K AR objects the 5s overhead would be the smallest problem. Think memory, DB inserts… Seems like classic microbenchmark flaw and premature optimization to me.

    However, nice graphs and good to know. Thanks.

    • #2 by Matt Aimonetti - February 23rd, 2012 at 12:03

      I agree and that’s what I say at the beginning of the article. Now it doesn’t mean that it’s a reason for AR to not be optimized.
      That said, my only purpose was to profile the initialization of a model and to see what’s going on under the cover.

      One thing I didn’t show and I should have, is the path taken when a record is retrieved from the DB and converted into an object.

  2. #3 by wut - February 23rd, 2012 at 12:05

    lets talk microseconds, not percents!

    but yeah, nice graph. thanks!

  3. #4 by Alex Shar - February 23rd, 2012 at 12:41

    Nice post, Matt. I was trying to do something similar with Bundler about a week ago, and I couldn’t remember which project I was looking for, and it was perftools, so thanks! Very interesting stuff about AR.

  4. #5 by Robert Klemme - February 24th, 2012 at 01:39

    Thank you for those insights!

  5. #6 by Michel Pigassou - February 28th, 2012 at 14:26

    Interesting. Maybe you could suggest ways to optimize AR?
    On a side note what tool do you use to generate your graphs?

  6. #7 by Matt Aimonetti - February 28th, 2012 at 22:52

    AR is a complex beast, if one wanted to optimize the initialization of objects, the callbacks should be the main area of optimization. As you can see these callbacks are expensive even tho they are most of the time not being used. Caching the dynamic callback class method if possible would help. But I think it’s more of a design problem than an optimization one.

    Regarding the graphs, I used graphivz via perftools.

  7. #8 by Bogdan Gusiev - February 29th, 2012 at 01:19

    I put a lot of work on AS::Callbacks in previous two month

    My concern was primarily start up performance, but runtime was also improved.
    https://github.com/rails/rails/commits/master/activesupport/lib/active_support/callbacks.rb
    I rip out about 30% of code that implements #run_callbacks method.

    It would be great if you could run your tests with Rails master with all my patches.

    As I understand: you are saying that the following line of code cause performance issue:
    https://github.com/rails/rails/blob/master/activesupport/lib/active_support/callbacks.rb#L355
    (note that the code looks like this only in rails master)
    It is hard to believe that construct a string is a problem.
    But I try to rip it out any way.

    Thanks for putting up more sense in a work I did.

  8. #9 by Chris Griego - March 2nd, 2012 at 05:57

    The overhead of ORM object initialization had a profound impact on how ActiveAttr was put together. Nearly all of the features in ActiveAttr affect initialization in some way, and without loading from or saving to a database to overshadow the performance, it quickly adds up. That is why ActiveAttr is implemented as fine grained feature modules that users can pick and choose, so they can have the features they need without the overhead of those they do not.

    Support for an after initialization callback is an open issue, but one I am still waiting on a good reason before adding. Even then then I wouldn’t include it by default in the Model rollup module.

  1. No trackbacks yet.

Comments are closed.