Test Timing

23rd Jan 2007 | Tags: programming rails

Since Geoff’s gem wasn’t working for me, I whipped up a test timing utility based off of it.

Rather than hook into Test::Unit::TestSuite, I’m hooking into TestCase, and providing a global report via an at_exit hook. Just add the following file to your lib folder, require it from test_helper, and most of the time it will just sit there, quietly doing nothing. Call it into action by setting the environment variable TEST_TIMER with a float, and it will output the elapsed time of any test taking longer than that.

Example run:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

# TEST_TIMER=0.25 rake test:units TEST=test/unit/creative_test.rb
/usr/bin/rake:17:Warning: require_gem is obsolete.  Use gem instead.
(in /home/jamie/dev/redvase)
/usr/bin/ruby1.8 -Ilib:test "/usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader.rb" "test/unit/creative_test.rb"
Loaded suite /usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader
Started
......................................................................................
Finished in 10.116575 seconds.

86 tests, 164 assertions, 0 failures, 0 errors

Test Benchmark Results
  0.2927 CreativeTest#test_delayed_click_count_with_third_party_stats
  0.2982 CreativeTest#test_impression_count_for_date_range_with_third_party_stats_offset
  0.3240 CreativeTest#test_global_creative_stats_should_return_correct_default_values
  6.2505 CreativeTest#test_click_count

Source file, lib/test_timer.rb

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

if ENV.has_key? 'TEST_TIMER' and
   !Test::Unit::TestCase.method_defined? :untimed_run

  class Test::Unit::TestCase
    cattr_reader :benchmark_data
    @@benchmark_data = {}
    alias untimed_run run

    def run(result, &progress_block)
      start = Time.now
      untimed_run(result, &progress_block)
      finish = Time.now
      elapsed = finish - start
      if elapsed > ENV['TEST_TIMER'].to_f
        name =~ /(.*)\((.*)\)/
        @@benchmark_data["#{$2}##{$1}"] = elapsed
      end
    end
  end

  # at_exit hooks run in reverse order, so in order to run after
  # Test::Unit's hook, we need to nest at_exit calls.
  at_exit do
    at_exit do
      results = Test::Unit::TestCase.benchmark_data
      unless results.empty?
        puts "\nTest Benchmark Results"
        results.sort{|a,b| a.last <=> b.last }.each do |key,value|
          puts " %7.4f #{key}" % value
        end
      end
    end
  end
end