diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb index b2c119d7e4..b08d9a8434 100644 --- a/actionpack/lib/action_controller/metal/instrumentation.rb +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -1,3 +1,4 @@ +require 'benchmark' require 'abstract_controller/logger' module ActionController diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb index ff2b19bc65..e98189f899 100644 --- a/activesupport/lib/active_support/notifications/instrumenter.rb +++ b/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 diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb index 73c85be87c..41e8ca4ae7 100644 --- a/activesupport/test/notifications_test.rb +++ b/activesupport/test/notifications_test.rb @@ -11,14 +11,11 @@ module Notifications @named_subscription = @notifier.subscribe("named.subscription") { |*args| @named_events << event(*args) } end - private - def event(*args) - ActiveSupport::Notifications::Event.new(*args) - end + private - def drain - @notifier.wait - end + def event(*args) + ActiveSupport::Notifications::Event.new(*args) + 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