Why are those specs SO slow?

Introduction

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.

Instrumentation

Two packages were used for stats generation and identifying bottlenecks:

1. Active Support Instrumentation
2. Package TestProf by Evil Martians

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.

Global 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 blockbefore(: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:

TAG_PROF=type \
TAG_PROF_EVENT='sql.active_record,factory_bot.run_factory,render_template.action_view,rspec.before_each' \
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:

time                           47:36.967
sql.active_record              02:20.415
factory_bot.run_factory        06:11.566
render_template.action_view    03:22.463
rspec.before_each              05:32.551
total                          4015
%total                         16.01
%time                          35.08
avg                            00:00.711

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:

time                           27:59.610
sql.active_record              03:31.499
factory_bot.run_factory        22:45.682
render_template.active_view    00:00.064
rspec.before_each              11:21.385
total                          8291
%total                         33.07
%time                          20.62
%avg                           00:00.202

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.

The global 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.

Epilogue

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.