This post originated from an RSS feed registered with Ruby Buzz by Eric Hodel. Original Post: Test Profiling by Lines Logged Feed Title: Segment7 Feed URL: http://blog.segment7.net/articles.rss Feed Description: Posts about and around Ruby, MetaRuby, ruby2c, ZenTest and work at The Robot Co-op. Latest Ruby Buzz Posts Latest Ruby Buzz Posts by Eric Hodel Latest Posts From Segment7

At work I’ve been cleaning up the tests and trying to make them run faster. One way of doing this is profiling the tests and fixing the slow spots. That only works so well, especially if there’s lots of duplication or extra work in the tests. With Rails you can go about this a different way, since you have a second source of information on your tests’ operation, the log file.

I added the following code to test/test_helper.rb:

raise 'require\'d test/test_helper twice!, you broke it!' if
  ENV['RAILS_ENV'] == 'test'

At the very top, even above ENV["RALIS_ENV"] = "test" to make sure that the hack to Test::Unit::TestCase below happens only once, then the magic to figure out which test outputs which log lines:

class Test::Unit::TestCase
  alias unlogged_run run
  def run(result, &block)
    RAILS_DEFAULT_LOGGER.debug "RUNNING #{self.class} #{@method_name}" 
    unlogged_run result, &block
  end
end if ENV['PROFILE_LOG']

Each test run will be prefixed with text like RUNNING SomeTest test_blah which I can then run this script on:

#!/usr/local/bin/ruby -w

test = nil
tests = Hash.new 0

File.open 'log/test.log' do |fp|
  fp.each_line do |line|
    if line.strip =~ /^RUNNING (.*)/ then
      test = $1
    else
      tests[test] += 1
    end
  end
end

tests.sort_by { |test, count| -count }.each do |test, count|
  puts "%5d %s" % [count, test]
end

To get the profile information, I run:

rake log:clear; PROFILE_LOG=y rake && script/count_logs

When run on Firebrigade, I get the following output (top 10 only):

<samp>  130 ProjectViewTest test_show
   74 DummyControllerTest test_error_500
   59 OwnerTest test_class_owner_count
   42 ProjectControllerTest test_index
   39 HomeControllerTest test_index_no_builds
   38 RestControllerTest test_add_build
   35 ProjectControllerTest test_show_no_versions
   35 ProjectControllerTest test_search_many_matches
   34 RestControllerTest test_add_project
   33 RestControllerTest test_add_version</samp>

Now I can quickly discover good candidates for refactoring. #test_error_500 above dumps an email into the logs, so it is a bogus result. That leaves ProjectViewTest#test_show as a candidate for simplification or refactoring.