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
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
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.
As an aside, 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!
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:
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
Then run a quick measurement using the
1 2 3 4 5 6
As you can see you get an extra 5 seconds added onto your query (because it’s a sleep it shows up in real, not in user or system.) Hopefully this code wouldn’t make its way into production but you can see how damaging a poorly written
after_intialize hook can be!