Add a test for elapsed and require missing benchmark file.

actionpack/lib/action_controller/metal/instrumentation.rb

@@ -1,3 +1,4 @@
+require 'benchmark'
 require 'abstract_controller/logger'
 
 module ActionController

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -17,8 +17,8 @@ module ActiveSupport
       # and publish it. Notice that events get sent even if an error occurs
       # in the passed-in block
       def instrument(name, payload={})
-        @started = Time.now
         begin
+          @started = Time.now
           yield(payload) if block_given?
         rescue Exception => e
           payload[:exception] = [e.class.name, e.message]
@@ -30,7 +30,7 @@ module ActiveSupport
       end
 
       def elapsed
-        1000.0 * @finished.to_f - @started.to_f
+        1000.0 * (@finished.to_f - @started.to_f)
       end
 
       private

activesupport/test/notifications_test.rb

@@ -11,14 +11,11 @@ module Notifications
       @named_subscription = @notifier.subscribe("named.subscription") { |*args| @named_events << event(*args) }
     end
 
-    private
+  private
-      def event(*args)
-        ActiveSupport::Notifications::Event.new(*args)
-      end
 
-      def drain
+    def event(*args)
-        @notifier.wait
+      ActiveSupport::Notifications::Event.new(*args)
-      end
+    end
   end
 
   class UnsubscribeTest < TestCase
@@ -132,13 +129,10 @@ module Notifications
 
     def test_instrument_returns_block_result
       assert_equal 2, instrument(:awesome) { 1 + 1 }
-      drain
     end
 
     def test_instrument_yields_the_paylod_for_further_modification
       assert_equal 2, instrument(:awesome) { |p| p[:result] = 1 + 1 }
-      drain
-
       assert_equal 1, @events.size
       assert_equal :awesome, @events.first.name
       assert_equal Hash[:result => 2], @events.first.payload
@@ -154,15 +148,11 @@ module Notifications
           1 + 1
         end
 
-        drain
-
         assert_equal 1, @events.size
         assert_equal :wot, @events.first.name
         assert_equal Hash[:payload => "child"], @events.first.payload
       end
 
-      drain
-
       assert_equal 2, @events.size
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload
@@ -177,16 +167,22 @@ module Notifications
         assert_equal "FAIL", e.message
       end
 
-      drain
       assert_equal 1, @events.size
       assert_equal Hash[:payload => "notifications",
         :exception => ["RuntimeError", "FAIL"]], @events.last.payload
     end
 
+    def test_elapsed
+      instrument(:something) do
+        sleep(0.001)
+      end
+
+      # Elapsed returns duration in ms
+      assert_in_delta 1, ActiveSupport::Notifications.instrumenter.elapsed, 100
+    end
+
     def test_event_is_pushed_even_without_block
       instrument(:awesome, :payload => "notifications")
-      drain
-
       assert_equal 1, @events.size
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload