Are you ready to hear the dirty little secret that ActiveRecord is hiding from you? ActiveRecord isn’t telling you how long your queries actually take!

It may come as a surprise that when ActiveRecord says a query takes 10ms to run it’s not telling you the whole truth. That time doesn’t include how long it took to create your objects!

Let’s break this down into a super simple example to see this in action. Here’s a database with 500 User objects and we’re going to load them all up at once:

1 2 3 User . all . to_a # => User Load (10.4ms) SELECT "users".* FROM "users" # => [#<User id: 263, ... >, #<User id: 264, ... >, #<User id: 265, ... >, ... ]

If you haven’t discovered this dirty secret yet, you’d think this query took 10.4ms to run. Let’s take a look using the Benchmark class to see what the true cost of running this query is:

1 2 3 puts Benchmark . measure { User . all . to_a } user system total real 0 . 143333 0 . 000000 0 . 143333 ( 0 . 163123 )

As you can see from the benchmark (using total time) that the query really takes 143.3ms. That’s over a 10x difference! And the majority of that time is spent building ActiveRecord models.

When timing your database code use the total time for your benchmark. I’ll write another post soon to breakdown the times because I still have to double check these numbers from time to time!

Application

How can you use this knowledge to improve the performance of your Rails apps? One way is to start looking more closely at your ActiveRecord query times.

Here’s an example response that I recently pulled out of an app:

1 Completed 200 OK in 1308 ms ( Views : 278 . 5 ms | ActiveRecord : 89 . 8 ms )

Database queries totalling 89.8ms are high but most of use would look to optimize the views at 278.5ms first. However when I dug further into this response, it turned out that there were multiple queries creating 750+ objects, costing over 500ms. Ouch! By tuning the request using methods like pluck and select I was able to reduce this request time by 50%.

Another place where object creation cost can be hidden is inside ActiveRecord after_initialize hooks. For those of you that are unfamiliar with it after_initialize is a callback that runs (you guessed it!) after initialization of an ActiveRecord object. In the event that your code has an expensive operation in an after_initialize hook your object load times will increase!

If you’d like to try this in your own code, drop the following lines into any ActiveRecord model:

1 2 3 4 5 6 7 8 9 class ActiveRecordModel after_initialize :test def test puts "start hook" sleep 5 puts "end hook" end end

Then run a quick measurement using the first method:

1 2 3 4 5 6 Benchmark . measure { ActiveRecordModel . first } # => start hook # => ... (5 second delay) # => end hook user system total real 0 . 010000 0 . 000000 0 . 010000 ( 5 . 00233 8 )