A few months ago, Ruby Inside wrote about using Spork with RSpec 2 and Rails 3 in order to get a more sprightly spec run. Unfortunately, using the techniques in the article with our fledgling codebase’s test suite left us with somewhat disappointing results, so I decided to dig deeper and see if I could do better.

With and Without Spork

First, let’s see what things look like with and without Spork running on our raw test suite.

Note: The machine I’m using is a spanking-new 15" MacBook Pro with the 2.2Ghz quad i7 and running Ruby 1.9.2-p180.

time rspec spec without Spork running:

1
2
3
4
5
6

Finished in 15.78 seconds
75 examples
 
real    0m22.334s
user    0m17.952s
sys     0m2.643s

We can see that we’re not overly I/O bound (real vs. user+sys), but we are spending a LOT of time doing “real work”. Ugh.

time rspec spec with Spork running:

1
2
3
4
5
6

Finished in 16.82 seconds
75 examples
 
real    0m17.340s
user    0m0.214s
sys     0m0.065s

This didn’t exactly equate to a big boost! (Editor notes: Most of Spork’s win is in running specs over and over rather than once-off speed, but I’ll let this slide for now ;-)) Just for clarity, here’s our barebones spec_helper.rb file showing what runs in the prefork as well as on each further run:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

require 'spork'
 
Spork.prefork do
  ENV["RAILS_ENV"] ||= 'test'
  require File.expand_path("../../config/environment", __FILE__)
  require 'rspec/rails'
 
  RSpec.configure do |config|
    config.mock_with :rspec
    config.use_transactional_fixtures = true
  end
end
 
Spork.each_run do
  # This code will be run each time you run your specs.
  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}
end

Cutting out MySQL

So, where are we spending out time and what can we do about it? First I’ll try cutting MySQL out of the picture and use an in-memory SQLite DB for our tests. This article was a helpful starting point for me, but I discovered quickly that the spec_helper.rb addition needed must be placed in the Spork.each_run block - not the Spork.prefork block.

Unfortunately, the silence_stream call winds up being superfluous because Spork has captured it already, and ActiveRecord isn’t writing to STDOUT anymore. This will make the tests a bit noisier when the Spork server is running, but that’s not a huge deal.

Our spec_helper.rb file’s each_run section now becomes this:

1
2
3
4
5
6
7
8
9
10

Spork.each_run do
  # This code will be run each time you run your specs.
  load_schema = lambda {
    load "#{Rails.root.to_s}/db/schema.rb" # use db agnostic schema by default
    # ActiveRecord::Migrator.up('db/migrate') # use migrations
  }
  silence_stream(STDOUT, &load_schema)
 
  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}
end

time rspec spec without Spork running:

1
2
3
4
5
6

Finished in 14.95 seconds
75 examples
 
real    0m21.866s
user    0m17.826s
sys     0m2.688s

A little bit better - and every win helps - but not huge. Let’s see how things look with the Spork server running.

time rspec spec with Spork running:

1
2
3
4
5
6

Finished in 14.83 seconds
75 examples
 
real    0m15.504s
user    0m0.222s
sys     0m0.064s

Things are beginning to look a bit better, but there is still room for improvement.

Cutting out Garbage Collection

The most obvious candidate is garbage collection. Turning off GC outright makes things faster, but at an unacceptable cost: The spec runner bloats from a peak of 81MB to a peak of 418MB. It turns out though that we can make a bit of a trade-off here by explicitly running GC periodically and finding a sweet-spot between too much time spent in GC and too much memory growth.

Our new spec_helper.rb disables GC in general, and forces a run after every 10th test. I didn’t go for an exhaustive analysis of the time/space tradeoff here, but converged to this as a “good enough” option after a handful of tests.

Here’s the new spec_helper.rb file (a lot more changes this time):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

Spork.prefork do
  # Loading more in this block will cause your tests to run faster. However,
  # if you change any configuration or code from libraries loaded here, you'll
  # need to restart spork for it take effect.
  ENV["RAILS_ENV"] ||= 'test'
  require File.expand_path("../../config/environment", __FILE__)
  require 'rspec/rails'
 
  counter = -1
  RSpec.configure do |config|
    config.mock_with :rspec
    config.use_transactional_fixtures = true
 
    config.after(:each) do
      counter += 1
      if counter > 9
        GC.enable
        GC.start
        GC.disable
        counter = 0
      end
    end
 
    config.after(:suite) do
      counter = 0
    end
  end
end
 
Spork.each_run do
  GC.disable
 
  # From: http://www.osmonov.com/2011/01/in-memory-sqlite-database-for-testing.html
  load_schema = lambda {
    load "#{Rails.root.to_s}/db/schema.rb" # use db agnostic schema by default
    # ActiveRecord::Migrator.up('db/migrate') # use migrations
  }
  silence_stream(STDOUT, &load_schema)
 
  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}
end

time rspec spec without Spork running:

1
2
3
4
5
6

Finished in 14.78 seconds
75 examples
 
real    0m21.384s
user    0m16.421s
sys     0m2.830s

time rspec spec with Spork running:

1
2
3
4
5
6

Finished in 13.36 seconds
75 examples
 
real    0m13.981s
user    0m0.218s
sys     0m0.061s

These runs used 145MB and 142MB of memory respectively. A considerable increase in memory, but not bad given the time win for controlling our GC behavior. The tradeoff time-wise (versus just disabling GC) turns out to be small — about half a second. I can live with that.

But all we’ve really been doing so far is shaving off some rough corners. We haven’t addressed the real issue head-on — the 13+ seconds of “real work” being done.

Taming Devise

My next step was to bust out perftools.rb and do some for-real profiling. I’m going to get a bit hand-wavy, cut to the chase and tell you what I found to be the single biggest culprit: Devise.

As with many in Rails-land, we’re using Devise to implement our user account and authentication functionality. Devise utilizes a “work factor” mechanism to make the computational cost of computing a password hash relatively high. This is to make brute-forcing the system that much harder for potential attackers, and it’s a very important mechanism.

Most of our models have an association to our User class, and we’re using the Devise-recommended choice of bcrypt with the default 10 stretches for hashing passwords right now. Obviously, anything that involves creating users is going to add up relatively fast. In hind-sight, this should have been fairly obvious. D'oh.

So, what do we do in test-mode? In test-mode we don’t care is the test data includes easy-to-brute-force passwords. We can’t just set stretches to 0, because bcrypt won’t let us. One little monkey-patch to Devise later, and we can get past that!

Our updated spec_helper.rb has an extended Spork.prefork section:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46

Spork.prefork do
  # Loading more in this block will cause your tests to run faster. However,
  # if you change any configuration or code from libraries loaded here, you'll
  # need to restart spork for it take effect.
  ENV["RAILS_ENV"] ||= 'test'
  require File.expand_path("../../config/environment", __FILE__)
  require 'rspec/rails'
 
  # Don't need passwords in test DB to be secure, but we would like 'em to be
  # fast -- and the stretches mechanism is intended to make passwords
  # computationally expensive.
  module Devise
    module Models
      module DatabaseAuthenticatable
        protected
 
        def password_digest(password)
          password
        end
      end
    end
  end
  Devise.setup do |config|
    config.stretches = 0
  end
 
  counter = -1
  RSpec.configure do |config|
    config.mock_with :rspec
    config.use_transactional_fixtures = true
 
    config.after(:each) do
      counter += 1
      if counter > 9
        GC.enable
        GC.start
        GC.disable
        counter = 0
      end
    end
 
    config.after(:suite) do
      counter = 0
    end
  end
end

time rspec spec without Spork running:

1
2
3
4
5
6

Finished in 6.34 seconds
75 examples
 
real    0m12.982s
user    0m9.567s
sys     0m2.699s

time rspec spec with Spork running:

1
2
3
4
5
6

Finished in 6.32 seconds
75 examples
 
real    0m6.935s
user    0m0.219s
sys     0m0.058s

Bingo. So now we’ve gone from around 17s to around 7s. And that is how you make your specs faster.

While Spork can make multiple runs faster, it’s not the be-all and end-all of making your spec runs faster generally, so see if there are other wins to be had as well.