Showing your longest running tests

Slow builds got you down? Have no idea where that slow test is? Get the latest in monkey-patched hotness:

require 'test/unit/ui/console/testrunner'
Test::Unit::UI::Console::TestRunner.class_eval do
 @@test_times = []

 old_attach_to_mediator_method = instance_method(:attach_to_mediator)

 define_method :attach_to_mediator do
   old_attach_to_mediator_method.bind(self).call
   @mediator.add_listener(Test::Unit::TestCase::STARTED, &method(:record_start_time))
   @mediator.add_listener(Test::Unit::TestCase::FINISHED, &method(:record_elapsed_time))
   @mediator.add_listener(Test::Unit::UI::TestRunnerMediator::FINISHED, &method(:print_times))
 end

 def record_start_time(name)
   @start_time = Time.now
 end

 def record_elapsed_time(name)
   @@test_times << {:name => name, :time => (Time.now - @start_time)}
 end

 def print_times(suite_elapsed_time)
   unless @@test_times.empty?
     puts ''
     puts "Displaying 10 longest running tests:"
     @@test_times.sort_by { |t| t[:time] }.reverse[0...10].each do |test_timing|
       puts "#{test_timing[:time]} seconds for #{test_timing[:name]}"
     end
   end
 end

end

And you get some output like this:

Displaying 10 longest running tests:
0.159756 seconds for test_awarding_0.04_points_per_passing_yard(Units::PlayerStatsTest)
0.000432 seconds for test_awarding_6_points_per_return_touchdown(Units::PlayerStatsTest)
0.000367 seconds for test_give_1_point_per_point_after_touchdown_made(Units::PlayerStatsTest)
0.000316 seconds for test_awarding_6_points_per_receiving_touchdown(Units::PlayerStatsTest)
0.000305 seconds for test_awarding_0.1_points_per_receiving_yard(Units::PlayerStatsTest)
0.000297 seconds for test_copping_out_and_giving_3_points_per_field_goal(Units::PlayerStatsTest)
0.00029 seconds for test_awarding_6_points_per_rushing_touchdowns(Units::PlayerStatsTest)
0.00029 seconds for test_penalizing_-2_points_for_fumbles_lost(Units::PlayerStatsTest)
0.000288 seconds for test_penalizing_-1_points_for_interceptions(Units::PlayerStatsTest)
0.000282 seconds for test_awarding_0.1_points_per_rushing_yard(Units::PlayerStatsTest)

Test Driven Deployment

Let me start by saying the I think TDD is the best way to develop quality software. It helps you develop a rhythm, keeps you focused, and has the nice side effect of leaving your application surrounded by unit tests. I have always felt uncomfortable doing work in environments where the rhythm of TDD was not possible. Lately, I have been feeling this pain while developing deployment scripts for a rails application.

Utilizing the power of capistrano, Paul and I came up with a rather novel way to test that our deployment scripts were working.

namespace :verify do
 
  task :mongrels, :roles => :app do
    (0...mongrel_count).each do |port_offset|
      assert_status_code '200', "http://localhost:#{mongrel_port + port_offset}/pulse"
    end
  end

  task :ha_proxy, :roles => :app do
    assert_status_code '200', "http://localhost:#{proxy_port}/pulse"
  end
   
  task :apache, :roles => :app do
    assert_status_code '200', "http://localhost:#{apache_port}/monit/token"
  end
end

def assert_status_code expected, url
  assert_equal expected, %{curl -s -o /dev/null -w '%{http_code}' #{url} }
end

def assert_equal expected, command
  errors = []
  run command do |ssh_channel, stream, output|
    errors << "Expected: #{expected} but was #{output} on #{ssh_channel.connection.host}" unless output == expected
    end
  raise "Errors on servers: \n  #{errors.join("\n  ")}\n\n" unless errors.empty?
end

We then execute these 'verify' tasks after the deploy task has completed.

after :deploy do
  verify.mongrels
  verify.ha_proxy
  verify.apache
end

More on this later!

Suite setup and teardown in Test::Unit

Test::Unit does not provide an easy way for suite setup and suite tear down methods to be executed. However, like most things in ruby, if there is a will there is a way. Today we managed to implement them using exit hooks.

Before I show you that code, it is important that we understand exactly how Test::Unit works. Here is a simple test:

require 'test/unit'

class ExampleTest < Test::Unit::TestCase
  def test_truth
    puts 'testing truth'
    assert true
  end
end

The part that I am most interested in is the require 'test/unit'. Hidden in the bottom of the code for this class is this code:

at_exit do
  unless $! || Test::Unit.run?
    exit Test::Unit::AutoRunner.run
  end
end

In short, this is the code that allows you to execute your test case rb file and have it actually run the test. This code will be called just before the interpreter exits. To prove to yourself that this is true (don't take my word for it) add this line to your test case anywhere after the require.

at_exit { exit! }

exit! will cause the interpreter to quit while ignoring any exit hooks. Since exit hooks are executed in reverse order of registration, this will effectively short circuit the execution of Test::Unit's exit hook.

Now we are getting somewhere. Using what we have just learned, we can now implement suite setup and teardown. Check it out:

require 'test/unit'

class ExampleTest < Test::Unit::TestCase
  def test_one; puts 'one'; end
  def test_two; puts 'two'; end
end

successful = false
at_exit { exit! successful }
at_exit { puts 'suite tear down' }
at_exit do
  unless $! || Test::Unit.run?
    successful = Test::Unit::AutoRunner.run
  end
end
at_exit { puts 'suite setup' }

When you run this, it will print:

suite setup
Loaded suite *the file*
Started
one
.two
.
Finished in 0.000564 seconds.

2 tests, 0 assertions, 0 failures, 0 errors
suite tear down

Enjoy!