Why are my tests slow after upgrading rails from 3.1.0 to 3.2.0?

Question

I followed these upgrade instructions: http://railscasts.com/episodes/318-upgrading-to-rails-3-2

Here are my three small upgrade changes:

(1) Gemfile

-gem 'rails', '3.1.0'
+gem 'rails', '3.2.0'

-gem 'rack', '1.3.3'
+#gem 'rack', '1.3.3'

 group :assets do
-  gem 'sass-rails', '  ~> 3.1.0'
-  gem 'coffee-rails', '~> 3.1.0'
-  gem 'uglifier'
+  gem 'sass-rails', '  ~> 3.2.3'
+  gem 'coffee-rails', '~> 3.2.1'
+  gem 'uglifier', '     >=1.0.3'
   gem 'asset_sync'
 end

(2) config/environments/development.rb

+  config.active_record.mass_assignment_sanitizer = :strict
+  config.active_record.auto_explain_threshold_in_seconds = 0.5

(3) config/environments/test.rb

-  config.assets.allow_debugging = true
+  config.active_record.mass_assignment_sanitizer = :strict

Prior to the upgrade, my tests looked as follows (well under a second each):

...
StockroomTest:
     PASS stockroom must have a name (0.03s) 
     PASS stockroom name must be unique (0.01s) 
     PASS stockroom with name is valid (0.00s) 
...
Finished in 1.604118 seconds.
29 tests, 90 assertions, 0 failures, 0 errors, 0 skips
...
StockroomsControllerTest:
     PASS should create stockroom (0.04s)
     PASS should destroy stockroom (0.02s)
     PASS should get edit (0.14s)
     PASS should get index (0.11s)
     PASS should get new (0.03s)
     PASS should not destroy stockroom (0.04s)
     PASS should show stockroom (0.13s)
     PASS should update stockroom (0.02s)
...
Finished in 12.572911 seconds.
115 tests, 166 assertions, 0 failures, 0 errors, 0 skips
...
MiscellaneousTest:
     PASS get campaigns#index should redirect to newsletters#index (1.83s)
     PASS get /campaigns should redirect to / when logged out (0.06s)
Finished in 1.793070 seconds.
2 tests, 3 assertions, 0 failures, 0 errors, 0 skips

After (each test takes over 1 second):

StockroomTest:
     PASS stockroom must have a name (1.29s)
     PASS stockroom name must be unique (1.30s)
     PASS stockroom with name is valid (1.27s)
...
Finished in 41.135808 seconds.
29 tests, 90 assertions, 0 failures, 0 errors, 0 skips
...
StockroomsControllerTest:
     PASS should create stockroom (1.30s)
     PASS should destroy stockroom (1.29s)
     PASS should get edit (1.33s)
     PASS should get index (1.43s)
     PASS should get new (1.41s)
     PASS should not destroy stockroom (1.31s)
     PASS should show stockroom (1.36s)
     PASS should update stockroom (1.31s)
...
Finished in 161.803235 seconds.
115 tests, 166 assertions, 0 failures, 0 errors, 0 skips
...
MiscellaneousTest:
     PASS get /campaigns should redirect to /newsletters when logged in (5.27s)
     PASS get /campaigns should redirect to / when logged out (1.67s)
Finished in 7.034593 seconds.
2 tests, 3 assertions, 0 failures, 0 errors, 0 skips

The following is an example of one of the unit tests from above. It takes about 1.3s to run now (after the upgrade), compared to less than 0.01s before.

test/unit/stockroom_test.rb

require 'test_helper'

class StockroomTest < ActiveSupport::TestCase
  fixtures :stockrooms

  test "stockroom with name is valid" do
    assert stockrooms(:wine_cellar).valid?, 'tried new wine_cellar'
  end

I know that fixtures are frowned on, and I do intend to seriously look into factories, but for the time being this is my predicament. Here is the relevant fixture:

test/fixtures/stockrooms.yml

wine_cellar:
  id: 1
  name: wine cellar

The only two validations on Stockroom are presence and uniqueness.

Note: I am running another rails app on the same machine, though it is running rails 3.2.5, and a nearly identical unit test (the same assertion on the same two validations) finishes in 0.465489 seconds (less than half a second).

Here is what the relevant part of the test log looks like for the above "stockroom with name is valid" test:

 (0.9ms)  SET FOREIGN_KEY_CHECKS = 1
 (0.2ms)  BEGIN
 (84.8ms)  BEGIN
 (82.3ms)  BEGIN
 (83.4ms)  BEGIN
 (79.2ms)  BEGIN
 (82.1ms)  BEGIN
Stockroom Load (0.4ms)  SELECT `stockrooms`.* FROM `stockrooms` WHERE `stockrooms`.`id` = 1 LIMIT 1
Stockroom Exists (0.6ms)  SELECT 1 AS one FROM `stockrooms` WHERE (`stockrooms`.`name` = BINARY 'wine cellar' AND `stockrooms`.`id` != 1) LIMIT 1
 (0.1ms)  ROLLBACK
 (90.9ms)  ROLLBACK
 (85.7ms)  ROLLBACK
 (90.7ms)  ROLLBACK
 (81.4ms)  ROLLBACK
 (85.4ms)  ROLLBACK

And for comparison, here's the "equivalent" test in my rails 3.2.5 app:

 (0.2ms)  SET FOREIGN_KEY_CHECKS = 1
 (0.1ms)  BEGIN
Email Load (0.4ms)  SELECT `emails`.* FROM `emails` WHERE `emails`.`id` = 980190962 LIMIT 1
Email Exists (2.8ms)  SELECT 1 FROM `emails` WHERE (`emails`.`email` = BINARY 'MyString' AND `emails`.`id` != 980190962) LIMIT 1
 (0.2ms)  ROLLBACK

Answer 1

The only answer that I could imagine is that your tests differ in the way the transactions are processed.

If everything works correctly, rails should wrap each test in a transaction and roll the transaction back. So you basically only "simulate" the writing actions and don't have to roll back the database after each test, thereby saving a lot of time.

If so, you might find your answer here: ActiveRecord Rollback does not work in Rails test

Only you might try to turn the feature explicitly on.

Edit: as your output show you are using transactions, there might be a difference in the way the rails environment loads. Please check spec_helper.rb for strange differences.

You could have a look on this post and check if there is something strange happening while your test suite boots up: Rails 3 - Speed up Console Loading Time