#413 Fast Tests pro

A slow test suite can be really discouraging when trying to do test-driven development. Each time we make a change we run the specs and slowly watch the green dots appear across the screen to see if we’ve broken anything and as our application grows, along with its test suite, this takes longer and longer to complete/This can lead to us running the tests less often which brings the risk of committing something that breaks our application. In this episode we’ll show some tips on how we can improve the speed of a test suite and selectively choose what we want to test so that this doesn’t happen.

First Steps

We have an application with a test suite that currently takes around 18 seconds to run in addition to the start-up time. This is too long to have to wait for feedback each time we make a change to our application. Before we start improving it let’s take a look at the app to see what we’re working with. It is very simple, with just a single controller and model. The EpisodesController is written in the RESTful style with the standard seven actions while the model has several methods in it to convert a time code to a number of seconds along with some validations and a scope. The app is tested in a similar way to that that demonstrated in episode 275 using RSpec and Factory Girl and all the testing is done in two spec files. We have a features spec file containing specs to simulate user behaviour at a high level and a model spec file which tests the logic at a lower level. The reason these specs take so long to run is that for each spec file we also have twenty symbolic links in a subdirectory that point to it to simulate a larger test suite. Let’s get started and see what we can do to improve the tests’ performance.

The way we run our tests can have a large effect on how quickly they run. Using rake isn’t generally a good idea as it adds some overhead. We can see this by using the time command.

$ time bundle exec rake spec:models

Finished in 0.77065 seconds
129 examples, 0 failures

Randomized with seed 2083


real  0m11.832s
user  0m8.772s
sys 0m1.665s

The time that RSpec displays is the time that the green dots took to march across the screen. Below that we can see the total amount of time, including the boot-up time, which is around four seconds longer. If we run the tests through RSpec we’ll see a difference in the time taken. Running the tests this way gives a total time of 7.7 seconds, about four seconds quicker.

$ time bundle exec rspec spec/models
Run options: include {:focus=>true}

All examples were filtered out; ignoring {:focus=>true}
.................................................................................................................................

Finished in 0.85975 seconds
129 examples, 0 failures

Randomized with seed 54380


real  0m7.701s
user  0m6.382s
sys 0m1.069s 

We can shave off more time by avoiding bundle exec as this also adds some overhead. We’ll run bundle binstubs to create a binstub for the rspec-core. This will make a file that we can run and we’ll use it to run the model specs again.

$ bundle binstubs rspec-core
$ time bin/rspec spec/models
Run options: include {:focus=>true}

All examples were filtered out; ignoring {:focus=>true}
.................................................................................................................................

Finished in 0.80396 seconds
129 examples, 0 failures

Randomized with seed 51207


real  0m6.987s
user  0m5.677s
sys 0m0.993s

This time it takes just under 7 seconds to run, about 10 percent faster than before.

Boot-up Time

We’ve improved the speed that our tests run at quite a lot but we’ve still got the biggest overhead, which is the time it takes to boot up our Rails application. This is the reason why there’s such a difference between the total run time and the time taken to run the specs. One solution is to preload our Rails app with a tool like Zeus, which we covered in episode 412. If we use zeus start to start up our Rails application we can use it in a new terminal tab to run the tests.

$ time zeus test spec/models
Run options: include {:focus=>true}

All examples were filtered out; ignoring {:focus=>true}
.................................................................................................................................

Finished in 0.81326 seconds
129 examples, 0 failures

Randomized with seed 0


real  0m2.308s
user  0m0.577s
sys 0m0.177s

Selective Testing

Running all of the tests still takes quite a while and we don’t want to have to do this every time we make a change to our application. To get around this we can use selective testing which is one of the best things we can do to improve to improve our testing workflow. No matter how long an app’s test suite takes to process we ideally want results back within a couple of seconds each time we make a change. With selective testing we can quickly see the results of the tests that we’re working on. One option is to map a key command in our text editor to run the currently selected test through Zeus or something else. How to do this was explained in more detail in episode 412. In this episode we’ll show you some alternatives to selective testing, one of these is to use tagging in RSpec. For example if we want to focus on the spec below for a while we can add a :focus tag to it.

it "scopes published episodes", :focus do
  published = create(:episode, published_on: 2.days.ago)
  unpublished = create(:episode, published_on: 2.days.from_now)
  Episode.published.should eq([published])
end

This is a tag that we’ve configured in our spec_helper file with the lines below.

config.treat_symbols_as_metadata_keys_with_true_values = true
config.filter_run focus: true
config.run_all_when_everything_filtered = true

These lines are useful in any Rails app that uses RSpec for testing as they enable us to selectively run certain tests or to run everything when no test is selected. If we run our specs now only the ones we’ve focussed on will be run.

Tagging is also useful as a way of skipping slow tests. We can mark a slow spec with a :slow tag in the same way that we added the :focus one then add a configuration option to exclude the specs marked with this tag. It’s a good idea to have a way to disable this in some way so we’ve make this configuration item dependent on an environment variable.

config.filter_run_excluding :slow unless ENV["SLOW_SPECS"]

When we run our specs now the slow ones are excluded by default unless we set that environment variable. Note that if we’re using Zeus we’ll need to set this environment variable before we start the Zeus server.

$ rspec spec/models
Run options:
  include {:focus=>true}
  exclude {:slow=>true}

All examples were filtered out; ignoring {:focus=>true}

Finished in 0.84062 seconds
128 examples, 0 failures

$ SLOW_SPECS=true rspec spec/models
Run options: include {:focus=>true}

All examples were filtered out; ignoring {:focus=>true}

Finished in 0.90219 seconds
129 examples, 0 failures

This is particularly useful if we have some integration specs that use JavaScript as we can use this approach to skip them. We can find out which specs are the slowest by running RSpec with the -p option. This shows the ten slowest specs in our suite.

Top 10 slowest examples (1.39 seconds, 7.1% of total time):
  Episodes destroy action removes the record
    0.21934 seconds ./spec/features/filler/episodes_06_spec.rb:121
  Episodes update action with valid episode has updated title
    0.14467 seconds ./spec/features/filler/episodes_05_spec.rb:104
  Episodes update action with valid episode says the record was updated
    0.13629 seconds ./spec/features/filler/episodes_02_spec.rb:100
  Episodes create action with valid episode has minutes
    0.12972 seconds ./spec/features/filler/episodes_12_spec.rb:71
(other specs omitted)

We could add the :slow tag to some of these and run them less frequently, maybe when we deploy our application or when we’re working on that part of it. If we run this command multiple times we may find that the results are a little inconsistent. This is partly due to Ruby’s garbage collection as this can happen at any point during the test run and takes a substantial proportion of the test’s time. This brings us to another great way to improve the speed of our tests. We can defer garbage collection so that it only happens between the specs. We do this by adding the following lines to the spec helper.

config.before(:each) { GC.disable }
config.after(:each) { GC.enable }

This simple change shaves off a couple of seconds from our full test run in this case but we can do better by further customizing the garbage collection. A solution, originally presented on the Signal vs Noise blog, is explained in this blog post. To use it we need to create a support file containing the class that’s shown there.

class DeferredGarbageCollection

  DEFERRED_GC_THRESHOLD = (ENV['DEFER_GC'] || 15.0).to_f

  @@last_gc_run = Time.now

  def self.start
    GC.disable if DEFERRED_GC_THRESHOLD > 0
  end

  def self.reconsider
    if DEFERRED_GC_THRESHOLD > 0 && Time.now - @@last_gc_run >= DEFERRED_GC_THRESHOLD
      GC.enable
      GC.start
      GC.disable
      @@last_gc_run = Time.now
    end
  end
end

We also need to add a few lines to the spec_helper file.

config.before(:all) do
  DeferredGarbageCollection.start
end

config.after(:all) do
  DeferredGarbageCollection.reconsider
end

In our application this shaves another second or two off the time that our test suite takes to run.

Parallelization

Next we’ll look at another way to improve our test speed. This involves using the ParallelTests gem which takes advantage of all the cores of our machine’s processor to run tests in parallel. To use it we need to add it to our gemfile in the development and test groups. For Zeus support we can also add the zeus-parallel_tests gem. As ever we’ll also need to run bundle to install the gems.

group :test, :development do
  gem "rspec-rails"
  gem "parallel_tests"
  gem "zeus-parallel_tests"
end

We’ll also need to make a change to our database YAML file. ParallelTests will use a different database for each core so we’ll need to add this to the name of the test database. It seems to be necessary for this number to be at the end of the file name so we’ve removed the .sqlite3 extension.

test:
  adapter: sqlite3
  database: db/test<%= ENV['TEST_ENV_NUMBER'] %>
  pool: 5
  timeout: 5000

To finish setting this up we’ll need run a few commands that the gems provide.

$ rake parallel:create
$ rake parallel:prepare
$ zeus-parallel_tests init

The first of these commands creates the databases while the second imports the schema and we’ll need to run this every time we run the migrations. The final command gives us Zeus support. When we start up Zeus again now it is configured to support parallel tests and we can run them by running this command:

$ zeus parallel_rspec spec

This will split up the specs into different processes, depending on the number of cores our machine has. This means that our tests will complete much sooner, running about twice as quickly as they did before.

Using Guard

What’s really useful is that this is all compatible with Guard. We already have this set up in our application and we showed how to do it in episode 264. To use Zeus with Guard it seems to be necessary to add the zeus gem to the test environment in the gemfile. Next we’ll need to configure the guardfile. We already use a couple of options here which it’s worth considering using in your own apps if you have a long test suite. We set both all_on_start and all_after_pass to false so that Guard doesn’t automatically run the entire test suite unless we want it to. We’ll add to these options so that Guard also uses Zeus and parallel testing.

guard 'rspec', all_on_start: false, all_after_pass: false, zeus: true, parallel: true, bundler: false do

Now we can run the guard command and it will detect any file changes and run the tests through Zeus and in parallel.

Running the tests in parallel does add some overheads so it may not be worth using it with Guard if we’re just running one small spec file. If we’re running all the specs then it’s generally worth running them in parallel.

Improving The Tests

Let’s change gear a little. Until now we’ve focussed on general tools and techniques to improve the performance of any test suite but we can often find the biggest saving by changing the tests themselves. We’ll start this by taking a look at our features spec. This is usually the slowest part of a test suite as it tests the entire app at a high level. One of the biggest things we need to look out for here is over-testing. If we have any complex logic or branching paths we don’t want to test them all at this level. For example, validations: in this spec we test the validations for the Episode model but these tests don’t really belong here. It’s better to do a general validation check to ensure that the page displays an error message when it should.

it "displays validation errors" do
  click_on "Create"
  page.should have_content("error prohibited this")
end

We can already have similar validation tests in the model layer specs so by removing them from the feature specs we’re removing duplication in our tests.

it "validates presence of name" do
  build(:episode, name: "").should have(1).errors_on(:name)
end

it "validates presence of description" do
  build(:episode, description: "").should have(1).errors_on(:description)
end

Another thing to watch out for in high-level feature specs is before blocks. The code in these is run multiple times and we can often move these into one spec. Even though this will leave our specs less well organized it helps with performance as the code in the before block can be expensive to run. We have before blocks scattered throughout our feature specs so we’ll merge them into one spec.

require 'spec_helper'

describe "Episodes" do
  it "lists published episodes" do
    create(:episode, name: "Blast from the Past", published_on: 2.days.ago)
    create(:episode, name: "Back to the Future", published_on: 2.days.from_now)
    visit episodes_path
    page.should have_content("Blast from the Past")
    page.should_not have_content("Back to the Future")
  end

  it "shows episode details" do
    episode = create(:episode, name: "Hello World", description: "Lorem ipsum", published_on: "2013-04-06")
    visit episode_path(episode)
    page.should have_content("Lorem ipsum")
    page.should have_content("April 6, 2013")
  end

  # etc
end

We could probably merge these further so that they’d run even quicker but we’ll keep them separate based on the different user operations that are performed. With these changes made our test suite completes more quickly.

Let’s move on to the model layer specs. One of thing to watch out for here is creating database records unnecessarily. In some specs we want to create database records, for example if we’re testing scopes we’ll need to query the database, but many other specs we can get by by manually creating an instance of a record instead of creating one from a database record. As we’re using Factory Girl we can use build instead of create to achieve this when ever we just want to test the behaviour of a model instead of dealing with the persistence of it.

it "parses timecode into seconds" do
  build(:episode, timecode: '10:03').seconds.should eq(603)
  build(:episode, timecode: '').seconds.should be_nil
end

If we have associations set up in Factory Girl we should consider using the build_stubbed method instead which will make a record look like it’s persisted but if an attempt is made to access the database an exception will be raised. This also sets up associations so it can often be a better approach if we have more complex scenarios.

Decoupling Code From Rails

Another thing to look out for while we’re building our app is behaviour that we can decouple from Rails so that it can be tested in isolation without loading our Rails app. This is a technique popularized by Corey Haines and it can work well in our application. We have a lot of logic for handling timecode conversions that we can execute and test outside Rails. There are three methods in our Episode model that aren’t really dependent on Rails at all. We’ll extract them out into a TimeDuration class in the /lib directory which our Episode model can then delegate to.

class Episode < ActiveRecord::Base
  attr_accessible :description, :name, :seconds, :published_on, :timecode
  validates_presence_of :name, :description
  scope :published, lambda { where('published_on <= ?', Time.now.to_date) }
  delegate :timecode, :minutes, to: :duration

  def duration
    @duration ||= TimeDuration.new(seconds)
  end

  def timecode=(timecode)
    duration.timecode = timecode
    self.seconds = duration.seconds
  end
end

The TimeDuration class is a plain Ruby object that handles the logic so that we don’t have to have it in the model layer.

class TimeDuration
  attr_accessor :seconds

  def initialize(seconds)
    @seconds = seconds
  end

  def timecode
    if @seconds
      min, sec = *seconds.divmod(60)
      [min, sec.to_s.rjust(2, '0')].join(':')
    end
  end

  def timecode=(timecode)
    if timecode && !timecode.present?
      min, sec = *timecode.split(':').map(&:to_i)
      @seconds = min*60 + sec
    end
  end

  def minutes
    (seconds/60.0).round if seconds
  end
end

To test this class we create a file under the /spec/lib directory which tests the class just like we would any other Ruby object.

require "time_duration"

describe TimeDuration do
  it "translates single digit seconds into timecode with minutes" do
    TimeDuration.new(60*8+3).timecode.should eq('8:03')
  end

  # Other specs omitted.
end

Note that we only require one file here, not spec_helper which would load in the entire Rails application and we don’t want to do that here. To test this we’ll go through a binstub, like this:

$ ./bin/rspec spec/lib

This completes really quickly, although there’s a little overhead from Bundler. Almost all the tests pass but there’s one that doesn’t because there’s no present? method available to call on a string. This is because our class doesn’t have ActiveSupport loaded in. We could load it in, but doing so adds some overhead to the test, so instead we’ll change the code so it doesn’t rely on any ActiveSupport method and use empty? instead. When we run our tests now they all pass.

We could argue that this technique isn’t as necessary now that we can use tools like Zeus to preload the Rails app and get results nearly as quickly but there are benefits aside from the speed increase. In particular this can help with design because we’re modelling the domain outside the Rails application and this, in theory, can lead to a more maintainable application, although not everyone subscribes to this view.

Finally we’ll mention the VCR gem. If we need to test an application that communicates with an external API we can use this to record the response then play it back through our test suite so that we don’t have to constantly make the same request each time we run the tests. This was covered in episode 291.