IdolHands.com :: Days in the Life of an Alpha Geek
As the number of tests goes up in your Rails project, you'll find yourself spending more and more time staring at the field of green dots waiting for the RSpec to finish.
You may notice some pauses, and be tempted to tail the test log file to figure out what's slowing things down, but thankfully there's a better way.
Passing the --profile flag to RSpec produces some additional output, namely the running times of the ten slowest examples in your specs. So this:
spec -p spec/*/*_spec.rb --colour --format profile
Produces this output in Terminal:
Profiling enabled.
........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ........................................................................ ..................................................................*..... ........................................................................ ...............*........................................................ ........................................................................ ........................................................................ ........................................................................ .............................................................
Top 10 slowest examples:
4.3889370 TemplatesController GET index lists templates admins 4.1541390 TemplatesController DELETE destroy with invalid params redirects to 404 0.7026320 FaqsController GET index lists all faqs for clients 0.6740070 FaqsController DELETE destroy with invalid params redirects admins to 404 0.6539990 FaqsController GET index lists all faqs for admins 0.6461050 FaqsController DELETE destroy with invalid params redirects clients to 404 0.4606460 SiteSection updates its site pages' URLs if its root_url changes 0.3915220 SitePage navigation items navbar items defaults link text 0.3357780 SitePage root page identifies root pages 0.3300710 SitePage url generation generates a url for a child page
Finished in 56.601493 seconds
1357 examples, 0 failures, 2 pending
This gives us a good place to start: based on the total number of examples (in this case, 1357) and the total running time (56.601493), the average example takes around .04 seconds to run. The slow examples that RSpec shows above range from almost 10 to over 100 times slower than the average, and definitely warrant investigation.
Once you've eliminated the most egregious bottlenecks in your examples, the big performance gains in your overall tests are behind you. But fractions of seconds add up, and you can squeeze out a little more time by narrowing your focus.
You can get more granular results by pointing RSpec at a subset of specs, changing the pattern that you pass in to target specific sets of tests. For example, to find the slowest examples in your controller specs:
spec -p spec/controllers/*_spec.rb --colour --format profile
You can even limit it to examples in a single spec file (notice the omission of the -p flag):
spec spec/controllers/faqs_controller_spec.rb --colour --format profile
If you're using autospec or rake:spec to run your examples, you can add support for the profiler to your settings in spec/spec.opts by replacing the format's progress option with profile:
--colour
--loadby mtime
--reverse
--format profile
Alternatively, you can write the profiling information to a file instead by providing a relative path and filename. (Caveat: don't write this file inside the spec folder, or you'll find that RSpec's modification trigger will kick in after it's written, causing another run of your examples.)
--colour
--format progress
--loadby mtime
--reverse
--format profile:doc/profile.txt
At the time of this writing, there's a bug in RSpec that causes the profile file output to become garbled if you have enabled color output using the colour flag. A fix has been submitted, but it's not available in the core yet.
If you let your tests get too slow, you'll end up testing less frequently than you should, a path which either leads to hell or one of its suburbs. Keeping your examples lean and fast, and refactoring when you need to, ensures that you get the most out of TDD and keep up your good habits.
