Possibly faster spec runs

exp.md

This is an experiment for possible faster boot time (and consequently faster feedback) when running tests. I ask your help to try this in your apps (any Rails 3.x app) and let me know how well it works.

How to

Add the following lines inside the configuration block in config/environments/test.rb:

config.cache_classes = true
def eager_load!; end

Notice that config.cache_classes needs to be true (which is the default), some tools may not be fine that. Needless to say, just do this for test environments.

Tests

The following two benches will work only for rspec running from the command line (hopefully you don't use rake to run your specs):

1. Pick up a spec file that runs all specs under 1s (for example, a file under spec/models or spec/helpers). Run the command below before and after you apply the eager_load! patch above (the bigger your application, the faster it should boot after you apply the patch):

   time rspec spec/models/SOME_MODEL_spec.rb

2. Try running your whole suite with and without the patch. In this case, you shouldn't see any perf difference and everything should work just fine (report if it doesn't!).

Let me know how 1) and 2) goes in the comments section below.

Spec file:
Without patch:
5.30s user 1.28s system 59% cpu 11.151 total

With patch:
4.04s user 0.87s system 80% cpu 6.110 total

Whote suite:
Without patch:
15.04s user 1.60s system 44% cpu 37.148 total

With patch:
13.89s user 1.53s system 51% cpu 29.856 total

Single spec

Without patch: 1.38s (46.451s total)
With patch:    2.15s (37.033s total)

Whole suite

Without patch: 10.76s (55.702 total)
With patch:    11.56s (48.457 total)

(first number is what RSpec reports, second is from time)

Single spec:

W/o patch:  6.64s user 0.36s system 98% cpu 7.094 total
With patch: 5.94s user 0.32s system 98% cpu 6.350 total

Whole suite:

W/o patch:  24.96s user 1.17s system 77% cpu 33.656 total
With patch: 24.55s user 1.16s system 77% cpu 33.205 total

Ran my whole suite (a smaller app, around 64 tests)

real 0m15.973s
user 0m8.597s
sys 0m1.023s

after change:
real 0m7.845s
user 0m6.779s
sys 0m0.651s

Ruby 1.9.3

Tested it with 2 apps – a fairly big one (lots of models, controllers and mixins for both) with Rails 3.1.6 and a smaller one with 3.2.6. Both tests with Ruby 1.9.2-p290.

Rails 3.1.6 before patch
Finished in 1.07 seconds
8 examples, 0 failures
rspec spec/models/activity_spec.rb 13.88s user 2.05s system 94% cpu 16.829 total

Rails 3.1.6 after patch
Finished in 1.93 seconds
8 examples, 0 failures
rspec spec/models/activity_spec.rb 12.19s user 1.87s system 95% cpu 14.673 total

---

Rails 3.2.6 before patch
Finished in 0.87679 seconds
5 examples, 0 failures
rspec spec/models/cart_item_spec.rb 9.29s user 1.97s system 93% cpu 12.068 total

Rails 3.2.6 after patch
Finished in 0.90387 seconds
5 examples, 0 failures
rspec spec/models/cart_item_spec.rb 9.00s user 1.91s system 89% cpu 12.252 total

Single model (pre patch):

real    0m11.739s
user    0m9.330s
sys 0m1.433s

Single model (with the patch):

real    0m11.736s
user    0m8.790s
sys 0m1.377s

The whole suite (pre patch):

real    0m38.485s
user    0m25.273s
sys 0m3.022s

The whole suite (with the patch):

real     0m35.252s
user     0m25.079s
sys  0m2.925s

file

without patch

real    0m20.102s
user    0m16.739s
sys 0m2.609s

with patch

real    0m20.725s
user    0m16.993s
sys 0m2.628s

suite

without patch

real    2m48.028s
user    1m27.467s
sys 0m4.435s

with patch

real    2m43.010s
user    1m28.222s
sys 0m4.275s

1. Is about 0.7 seconds faster and works fine
2. Gives warnings and errors about naming within modules:

/Users/manfred/Code/offerti/test/functional/user/quotes_controller_test.rb:3: warning:
  toplevel constant QuotesController referenced by User::QuotesController

Testing with a small spec (about 0.6 sec for the run time + 10sec boot)
No patch: real 0m10.693s | user 0m10.199s | sys 0m0.340s
Patched: real 0m9.660s | user 0m9.206s | sys 0m0.290s

Whole suite:
(no difference)

The patch seem to shave about 10% off my boot time

Ran two model spec files, one that loads rails, the other that only loads active record.

Doesn't appear to have made a noticeable difference on either. Still faster just not loading the whole app when running model specs. :)

BEFORE PATCH

loading whole app

ruby-1.9.2-p290@slottd[adding_slots]$ rspec spec/models/reservation_spec.rb
Finished in 0.3089 seconds
4 examples, 0 failures
real 0m12.956s
user 0m11.146s
sys 0m1.708s

loading only active record

ruby-1.9.2-p290@slottd[adding_slots*]$ rspec spec/models/event_spec.rb
Finished in 0.29744 seconds
11 examples, 0 failures
real 0m1.830s
user 0m1.340s
sys 0m0.479s

AFTER PATCH

loading whole app

ruby-1.9.2-p290@slottd[adding_slots*]$ rspec spec/models/reservation_spec.rb
Finished in 0.37295 seconds
4 examples, 0 failures
real 0m12.642s
user 0m10.877s
sys 0m1.700s

loading only active record

ruby-1.9.2-p290@slottd[adding_slots*]$ rspec spec/models/event_spec.rb
Finished in 0.29604 seconds
11 examples, 0 failures
real 0m1.825s
user 0m1.336s
sys 0m0.476s

One file, without the patch (3 times, to guarantee caching)

# I really don't know what happened on this one....
Finished in 4.99 seconds
9 examples, 0 failures

real    0m39.277s
user    0m4.196s
sys 0m1.605s

Finished in 1.21 seconds
9 examples, 0 failures

real    0m7.300s
user    0m3.885s
sys 0m1.221s

Finished in 1.02 seconds
9 examples, 0 failures

real    0m6.185s
user    0m3.839s
sys 0m1.209s

One file, with the patch (again, 3 times to guarantee caching)

Finished in 1.15 seconds
9 examples, 0 failures

real    0m10.816s
user    0m3.152s
sys 0m1.094s

Finished in 1.18 seconds
9 examples, 0 failures

real    0m5.449s
user    0m3.156s
sys 0m1.047s

Finished in 0.93217 seconds
9 examples, 0 failures

real    0m4.952s
user    0m3.111s
sys 0m1.021s

Whole suite without the patch (3 times!)

Finished in 9.19 seconds
214 examples, 0 failures, 5 pending

real    0m16.828s
user    0m10.169s
sys 0m1.583s

Finished in 9.3 seconds
214 examples, 0 failures, 5 pending

real    0m15.611s
user    0m9.975s
sys 0m1.507s

Finished in 8.8 seconds
214 examples, 0 failures, 5 pending

real    0m14.338s
user    0m9.915s
sys 0m1.462s

Whole suite, with the patch

Finished in 8.98 seconds
214 examples, 0 failures, 5 pending

real    0m13.725s
user    0m9.639s
sys 0m1.418s

Finished in 9.27 seconds
214 examples, 0 failures, 5 pending

real    0m13.775s
user    0m9.737s
sys 0m1.416s

Finished in 9.01 seconds
214 examples, 0 failures, 5 pending

real    0m13.849s
user    0m9.765s
sys 0m1.436s

Without patch: 29.52 real 19.10 user 4.62 sys
With patch: 26.24 real 17.36 user 4.13 sys

• Single RSpec model spec

before: 11.34s, after: 9.00s✨

• Whole suite

(no difference)

Single spec
without patch
real 0m10.662s; user 0m8.287s; sys 0m0.934s;

with patch
real 0m7.848s; user 0m6.947s; sys 0m0.794s;

Whole suite
without patch
real 1m47.937s user 1m31.281s sys 0m3.974s

with patch
real 1m45.456s user 1m30.871s sys 0m3.989s
with a couple of failures

I ran 3 times

single spec

without change

real  0m4.127s
user  0m3.312s
sys 0m0.711s

real  0m4.140s
user  0m3.301s
sys 0m0.709s

real  0m4.097s
user  0m3.307s
sys 0m0.713s

with change

real  0m4.165s
user  0m3.316s
sys 0m0.713s

real  0m4.292s
user  0m3.328s
sys 0m0.725s

real  0m4.211s
user  0m3.323s
sys 0m0.727s

whole suite

without change

real  0m23.754s
user  0m13.202s
sys 0m1.562s

real  0m23.650s
user  0m12.893s
sys 0m1.710s

real  0m17.917s
user  0m12.983s
sys 0m1.505s

with change

real  0m20.474s
user  0m12.993s
sys 0m1.621s

eal 0m18.962s
user  0m12.867s
sys 0m1.493s

real  0m41.156s
user  0m13.029s
sys 0m1.794s

Singe test:
before: 15 seconds
after: 14 seconds

whole suite:
no difference

ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-darwin11.4.0]

Spec file before

real    12.14s
user    10.15s
sys 1.63s

Spec file after

real    9.46s
user    7.98s
sys 1.35s

Spec file: 1 example, 0 failures. Same results with and without change.

Suite before

real    369.67s
user    164.59s
sys 13.26s

Suite after

real    366.51s
user    163.93s
sys 13.06s

Whole suite: 848 examples, 0 failures, 92 pending. Same results with and without change.

Most of the other comments are against pretty small sets, so I ran this against one of our larger projects (~1500 examples). This is Rails 3.2.6 on Ruby 1.9.3-p194.

I ran the tests several times. The results below are medians.

Model

Baseline

real    0m5.960s
user    0m5.360s
sys     0m0.524s

Patched

real    0m5.907s
user    0m5.386s
sys     0m0.515s

## Suite

Baseline

real    5m3.711s
user    4m58.806s
sys     0m3.704s

Patched

real    5m8.955s
user    5m2.633s
sys     0m3.643s

Entire suite

Baseline

Finished in 4 minutes 3.04 seconds
2699 examples, 0 failures, 3 pending

real  4m10.776s
user  4m2.966s
sys 0m6.156s

Patched

Finished in 4 minutes 3.63 seconds
2699 examples, 0 failures, 3 pending

real  4m10.949s
user  4m3.393s
sys 0m5.989s

Single spec file - 3 runs with each

Baseline

12 examples, 0 failures
Finished in 0.20853 seconds
Finished in 0.20797 seconds
Finished in 0.20495 seconds

real  0m4.882s 0m4.921s 0m4.914s
user  0m4.374s 0m4.365s 0m4.362s
sys   0m0.664s 0m0.705s 0m0.704s

Patched

12 examples, 0 failures
Finished in 0.26532 seconds
Finished in 0.27075 seconds
Finished in 0.26828 seconds

real  0m3.816s 0m3.749s 0m3.760s
user  0m3.428s 0m3.435s 0m3.440s
sys 0m0.528s 0m0.480s 0m0.484s