Debugging Why Your Specs Have Slowed Down

On a recent project, a client’s test suite had slowed down to a painful 15 minutes even when running with parallelization. It was great to see that the team maintained a balanced testing pyramid, but we were surprised by the completion times of even the simplest unit specs.

# spec/models/user_spec.rb

describe "associations" do
  subject(:user) { User.new }

  it { should have_many(:orders) }
  # 12 additional association specs
end

Over 3 seconds feels like an eternity for unit specs that don’t even touch the database.

Identifying Slowdowns in the spec_helper

# spec/spec_helper.rb`

RSpec.configure do |config|
  # > 300 lines of around, before and after blocks
end

A very large spec_helper file offers a lot of possible culprits. Let’s fast track our experimentation by commenting out everything and rerunning our specs.

Almost 9x faster! Now we’re talking. Next, we systematically uncomment code blocks and find the worst offenders.

Culprit 1

# spec/spec_helper.rb

config.before(:each) do
  stub_something
end

This before block is only needed for a few feature specs to pass, but is running before every single spec. Let’s isolate the logic to only run for feature specs.

# spec/spec_helper.rb

config.before(:each, type: :feature) do
  stub_something
end

This is a good start but this logic is still being used before feature specs that don’t need it. Let’s further isolate the logic using user-defined metadata.

# spec/spec_helper.rb

config.before(:each, :stub_something) do
  stub_something
end


# spec/features/user_does_something_spec.rb

scenario "user does something", :stub_something do
  # spec logic
end

Culprit 2

# spec/spec_helper.rb

config.before(:each) do |example|
  DatabaseCleaner.strategy = :truncation
end

After each spec, the test can use different database cleaning strategies to “reset” the database. We happen to be using a very slow strategy compared to transaction. To accommodate the few specs that require truncation, lets use the same fix for Culprit 1 and add user-defined metadata to the specs that need it.

# spec/spec_helper.rb

config.before(:each, :clean_database_with_truncation) do |example|
  DatabaseCleaner.strategy = :truncation
end

Identifying Slowdowns in Spec Setup

Using RSpec’s profile flag, we can identify the slowest specs in the rest of the file.

rspec spec/models/user_spec.rb --profile 5

Pulling up the slowest spec, we see:

# spec/models/user_spec.rb

it "does something" do
  user = FactoryBot.create(:user)

  # exercise on user

  # expectation on user
end

On a hunch, we comment out everything except for the FactoryBot line, and sure enough, the test barely speeds up. At this point in the audit process, we asked if FactoryBot was even needed, or if we could use build_stubbed. Turns out neither of these solutions were an option as the spec required writing to the database. We still took a peek in our factory file to see if there was room for optimization.

# spec/factories/user_factory.rb

FactoryBot.define do
  factory :user do

  # more code

  after(:create) do |user|
    create(:billing_profile, user: user)
  end
end

FactoryBot is creating active record associations that are not needed as part of our test setup. We can fix this issue by moving the association into a FactoryBot trait and rerunning our tests.

# spec/factories/user_factory.rb

FactoryBot.define do
  factory :user do

  # more code

  trait :with_billing_profile do
    after(:create) do |user|
      create(:billing_profile, user: user)
    end
  end
end

Sweet! We just made our 5 slowest specs over 2x faster. We’re not done just yet. We still have to run the full test suite and add our new trait to any specs that require a billing_profile.

Safeguarding Against Future Slowdowns

The team was concerned that other factories might be creating unnecessary records in additional tests. Using Factory Bot’s documentation on ActiveSupport Instrumentation, we were able to add this logic to give us greater visibility into the problem when needed.

# spec/spec_helper.rb

config.before(:each, :monitor_database_record_creation) do |example|
  ActiveSupport::Notifications.subscribe("factory_bot.run_factory") do |name, start, finish, id, payload|
    $stderr.puts "FactoryBot: #{payload[:strategy]}(:#{payload[:name]})"
  end
end

Now, running a spec with the metadata :monitor_database_record_creation allows us to verify if the number of records created by the test are in line with our expectations.

¹

Yikes! A single unit spec is writing to the database to create 13 records when the test setup and exercise should only have only generated 4 records. We plan to remove these mystery guests in future PRs in order to avoid test misdirection and a slow test suite.

The Benefits of Time Savings are Compounded

By removing global stubs we didn’t need, using a faster database cleaner strategy, and simplifying factories, we were able to shave a few minutes off of our test suite. That may sound nominal at first, but multiply those minutes by the number of developers on the team and the number of continuous integration builds a day. That’s an investment that will pay off very quickly.

Footnotes

1.

What’s FactoryGirl? The library was renamed to FactoryBot in 2017.
Naming history can be found here.