Why are those specs SO slow?
There is a stage of every mature Ruby On Rails project when developers start asking that question. Everything was fine at the beginning of the project; everybody tried their best in writing isolated, well maintained, and blah, blah, blah, tests. And then suddenly your tests are slow again! Why?
OK. We are here already. Our test coverage is pretty good: we have thousands of tests. But it takes hours to run all those tests locally. Everybody waits for CI results instead. That makes the Feedback Loop much longer. Refactoring is a challenge now. It might take days to fix all those tests!
So we decided to look into those tests and identify why they are so slow. But (surprise!) slow tests make it difficult to determine why they are so slow. We have to run them, again and again, to understand what is wrong. I have spent weeks trying to understand the reason for the slowness. Sometimes it was just one easily fixable bottleneck, but other times the diagnosis was much gloomier.
In this post, I will try to consolidate all those pieces of information that I gathered during my long and sometimes frustrating battle for faster tests. I do hope that it will make the process a little bit easier for you.
Two packages were used for stats generation and identifying bottlenecks:
Active Support Instrumentation makes it possible to track various application profiling information based on events.
TestProf by Evil Martians is a meta-package that makes using Active Support Instrumentation more convenient.
Most common bottlenecks
Here I’m going to concentrate on the four most common reasons for the slowness of the specs that I observed so far. This list is far from being comprehensive and based solely on my personal experience.
Render views. By default, RSpec does not render views while running controller specs. If you want to inspect ActionView content, you will have to turn this option on either for the given spec group:
Or you can do it globally in the config file, but that might decrease spec performance:
Enabling views rendering might decrease specs performance drastically.
FactoryBot. Instance creation can be tricky and time-consuming, especially for model unit tests.
DB. Sometimes interaction with DB might take most of the specs running time, and it’s not easy to separate it from other activities.
before(:each)/after(:each)blocks. Tend to grow with the project and take a significant amount of time.
Generate the report
So now, let’s get some stats to find out why our specs are not flying but crawling.
As was said above, I’m going to use Active Support Instrumentation to gather all the data. Out of the box, it supports many useful events. Also, many libraries like FactoryBot add their events as well. And it’s possible to add custom events.
So here are the current events that will be used below:
render_template.action_view. This event is published every time when RSpec renders a view and is useful for measuring how much time it takes.
factory_bot.run_factory. FactoryBot raises it every time it runs a factory.
sql.active_record. This can be used to get how much time is taken by the interaction with the database.
And you need to wrap the content of your global
before(:each)block to understand how much time RSpec spends running it:
With this update
ActiveSupport::Notification will publish the event
rspec.before_each every time the block
before(:each) is run. You can do the same with the
after(:each) block if you want to measure its performance as well.
OK. So all preparation is done and now it’s time to run the tests:
bundle exec rspec --exclude-pattern "spec/features/**/*_spec.rb"
Be aware, please, that I intentionally excluded feature specs here because they are inherently slow and require completely different optimization approaches.
Presumably, this command will take some time to complete (your tests are slow…). But as a result, you will see all the stats on your screen. That will look something like this:
As an example, I provided an excerpt from the stats that I gathered over the real project I’m working on right now.
How To Read The Report
The first column contains the type of tests.
controller stands for controller specs,
model stands for model specs and so on.
Let’s review the stats for controller specs in detail:
That means that 4015 controller specs were run (
total column), they took approximately 47 mins 36 secs (
time column), 711 milliseconds each on average (
avgcolumn). Also, we can see that all DB requests that were made through
ActiveRecordtook approximately 2 mins 20 secs (
sql.active_record column). Factories took 6 mins 11 secs (
factory_bot.run_factory column), and views rendering took approximately 3 mins 22 secs (
render_template.action_view column). Based on these stats we can say that our controller tests are relatively fast and we do not see obvious bottlenecks there.
Let’s review the model stats now:
Here we can see an obvious bottleneck candidate:
FactoryBot factories that took approximately 22 mins. And you can see also that all SQL requests took only 3 mins. So objects instantiation took most of the time — 18 mins.
So now knowing where the bottleneck is we can either optimize our factories or introduce fixtures to eliminate it.
before(:each) block is another possible bottleneck. It took 11 mins. That is obviously too much.
And DB interactions took 3 mins only. That means that DB is healthy and not a problem in this case.
In my opinion, tests are the litmus paper that exposes the quality of the code. Slow and nondescriptive tests are the first signs something wrong in the codebase.
In most cases, it is the code itself that should be modularized and cleaned to get fast and clean specs. But sometimes it is possible to make tests faster by detecting and removing only a couple of performance bottlenecks. I hope this post will help you speed up your tests.