Knowing why something is slow is key to making it faster. Everybody hates slow tests, so I’m sharing my approach to measuring why some RSpec tests were taking ages to run.
The starting point was a model spec that took 22 seconds to run. My immediate assumption was that the tests we are running slowly because they rely heavily on interacting with the database (IO). At this point this is just a theory and it will need to be proven before we take steps to remedy the slowness. Cue profiling ruby code with Stackprof.
Profiling RSpec 1.3 specs with Stackprof
I conjured up the following script to benchmark any RSpec (1.3) test with Stackprof.
You need to add
gem 'stackprof' to your Gemfile in order for this to run. Save
it to a file and run it like this
You can tweak the sampling interval by providing
INTERVAL=1000 and limit the
results output by providing a
The output looks something like this:
The results above list the percentage spent in various methods whilst running
the spec. From this it is clear that the biggest timesink whilst running the
ActiveRecord querying the database. Having this knowledge enabled me
to start looking into how to reduce the problem, and also to have a concrete
number to benchmark to see whether I’m making any progress.
Another offender that I hadn’t suspected was
writing the teste log to a file. This was easily reduced by adding
config.log_level = :error to
Profiling RSpec 3 specs with Stackprof
I’ve ported the script to work with RSpec 3 as that will benefit the majority of setups out there.
You cannot optimise what you can’t measure. Some tools are a bit arcane, but a bit of digging can quickly lead to tangible results that can then be improved upon.