Ruby: how to spot slow tests in your test suite

This is actually my first post in english and also my first post on Ruby/Rails stuff. Twice as hard!

Anyway, we’re working on a Rails project, and we’re experiencing the classical debate in all Rails project (at least the ones with tests!): why our test suite is so damn slow?!
Ok, we know that ActiveRecord is one of the key components in Rails and is at the root of its philosophy of web development. And along with ActiveRecord comes the strong tight between the model and the database. So each test, even the unit tests, will touch the database (ok, technically speaking they cannot be defined unit-tests, I know. Sorry Michael Feathers for betraying your definition).
The very first consequence of this approach is that as your test suite grows with your project, it will become slower and slower.

Let’s take our current project. This is our actual test suite composition:

  • Unit: 317 tests, 803 assertions
  • Functional: 245 tests, 686 assertions
  • Integration: 50 tests, 218 assertions

So we have 612 test methods, for a resulting number of 1707 assertions.
As a side note, our code-to-test ratio is 1:2.3, that is, for each line of production code we have 2.3 lines of tests.
The suite takes about 115 seconds to execute (on my MacBook Pro Core 2 Duo).

So, what can we do to speed up our tests and have a more “feedback-friendly” test suite?
The first step toward the solution of this issue is to have some metrics to reflect on, and so I developed this little ruby module to collect test duration times.
This is how you can use it too:

First, create a file called “test_time_tracking.rb” in the test folder of your Rails project. This should be its content:

module TestTimeTracking
    class ActiveSupport::TestCase
      def self.should_track_timing?
        not(ENV["tracking"].nil?)
      end

      setup :mark_test_start_time if should_track_timing?
      teardown :record_test_duration if should_track_timing?

      def mark_test_start_time
        @start_time = Time.now
      end

      def record_test_duration
        File.open("/tmp/test_metrics.csv", "a") do |file|
          file.puts "#{name().gsub(/,/, '_')},#{Time.now - @start_time}"
        end
      end

    end
end

Then, edit your “test_helper.rb” (again, under the test folder), to require and include the previous module.
E.g.

*test_helper.rb*

ENV["RAILS_ENV"] = "test"
  require File.expand_path(File.dirname(__FILE__) + "/../config/environment")
  require "test_time_tracking"

  class ActiveSupport::TestCase
    include TestTimeTracking
    ...

then, all you have to do is executing your rake task with the “tracking” option set, e.g.
tracking=on rake

At the end of the test suite execution you’ll find a CSV file (test_metrics.csv) in your /tmp folder.
This file contains a line for each test method executed, along with its duration in seconds.
I use to upload this file in google docs, and then apply a formula to sort out the methods from the slowest to the fastest.
A good formula is the following:
=Sort(A2:B612, B2:B612, FALSE)

The main limitation in the current implementation of this module is that every time the suite is executed with rake, the new time metrics collected are appended at the end of the previous file (if it exists), so each time you should remember to move the file to a different location. I’m working on this issue, so I’m expecting to find a better solution. Stay tuned!

4 thoughts on “Ruby: how to spot slow tests in your test suite

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s