Rails Lighthouse ticket #4594

add_start_events_2.diff

From 65f8a6adcc14d576446a4edfe1e98496b8b898bd Mon Sep 17 00:00:00 2001
From: Justin George <justin.george@gmail.com>
Date: Thu, 13 May 2010 14:07:40 -0700
Subject: [PATCH] all instrumentation events that include a block now fire a start event before the block is yielded [#4594 state:resolved]

In many situations, we want to instrument when something starts, as well as when it has finished.

A canonical example is AR transactions, which are helpful when they log which model started/ended them.
---
 .../active_support/notifications/instrumenter.rb   |   13 ++++--
 activesupport/test/notifications_test.rb           |   48 +++++++++++++++----
 .../application/initializers/notifications_test.rb |    1 +
 3 files changed, 48 insertions(+), 14 deletions(-)

diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb
index 7e89402..4aaadb3 100644
--- a/activesupport/lib/active_support/notifications/instrumenter.rb
+++ b/activesupport/lib/active_support/notifications/instrumenter.rb
@@ -11,13 +11,18 @@ module ActiveSupport
         @notifier = notifier
       end
 
-      # Instrument the given block by measuring the time taken to execute it
-      # and publish it. Notice that events get sent even if an error occurs
-      # in the passed-in block
+      # Instrument the given block by measuring the time taken to
+      # execute it and publish it. Notice that events get sent even if
+      # an error occurs in the passed-in block, and that events that
+      # include a block also automatically include a start event
       def instrument(name, payload={})
         time = Time.now
+        
         begin
-          yield(payload) if block_given?
+          if block_given?
+            @notifier.publish("#{name}.start", time, time, @id, payload.dup)
+            yield(payload)
+          end
         rescue Exception => e
           payload[:exception] = [e.class.name, e.message]
           raise e
diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb
index e11de5f..a501196 100644
--- a/activesupport/test/notifications_test.rb
+++ b/activesupport/test/notifications_test.rb
@@ -135,13 +135,13 @@ module Notifications
       drain
     end
 
-    def test_instrument_yields_the_paylod_for_further_modification
+    def test_instrument_yields_payload_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
+      assert_equal 2, @events.size
+      assert_equal :awesome, @events.last.name
+      assert_equal Hash[:result => 2], @events.last.payload
     end
 
     def test_instrumenter_exposes_its_id
@@ -149,21 +149,32 @@ module Notifications
     end
 
     def test_nested_events_can_be_instrumented
+      # fires 'awesome.start'
       instrument(:awesome, :payload => "notifications") do
+        drain
+        assert_equal 1, @events.size
+        assert_equal 'awesome.start', @events.last.name
+        
+        # fires 'wot.start'
         instrument(:wot, :payload => "child") do
-          1 + 1
+          # innermost instrumented block
+          drain
+          assert_equal 2, @events.size
+          assert_equal 'wot.start', @events.last.name
+          #fires :wot
         end
 
         drain
 
-        assert_equal 1, @events.size
-        assert_equal :wot, @events.first.name
-        assert_equal Hash[:payload => "child"], @events.first.payload
+        assert_equal 3, @events.size
+        assert_equal :wot, @events.last.name
+        assert_equal Hash[:payload => "child"], @events.last.payload
+        # fires :awesome
       end
 
       drain
 
-      assert_equal 2, @events.size
+      assert_equal 4, @events.size
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload
     end
@@ -178,7 +189,7 @@ module Notifications
       end
 
       drain
-      assert_equal 1, @events.size
+      assert_equal 2, @events.size
       assert_equal Hash[:payload => "notifications",
         :exception => ["RuntimeError", "FAIL"]], @events.last.payload
     end
@@ -191,6 +202,23 @@ module Notifications
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload
     end
+
+    def test_start_event_fires_with_block
+      instrument(:awesome, :payload => 'notifications') do
+        #noop
+      end
+      drain
+
+      assert_equal 2, @events.size
+      assert_equal 'awesome.start', @events.first.name
+    end
+
+    def test_start_event_not_fired_without_block
+      instrument(:awesome, :payload => 'notifications')
+      drain
+      assert_equal 1, @events.size
+      assert_equal :awesome, @events.first.name
+    end
   end
 
   class EventTest < TestCase
diff --git a/railties/test/application/initializers/notifications_test.rb b/railties/test/application/initializers/notifications_test.rb
index 276950c..9e719dd 100644
--- a/railties/test/application/initializers/notifications_test.rb
+++ b/railties/test/application/initializers/notifications_test.rb
@@ -38,6 +38,7 @@ module ApplicationTests
       ActiveRecord::Base.logger = logger = MockLogger.new
 
       # Mimic ActiveRecord notifications
+      instrument "sql.active_record.start", :name => "SQL", :sql => "SHOW tables"
       instrument "sql.active_record", :name => "SQL", :sql => "SHOW tables"
       wait
 
-- 
1.7.0.3

add_start_events_3.diff

From c304496e08c14a938d816ca7faf009da9e007f17 Mon Sep 17 00:00:00 2001
From: Roger Leite <roger.barreto+github@gmail.com>
Date: Tue, 4 Jan 2011 16:55:05 -0200
Subject: [PATCH] [PATCH] all instrumentation events that include a block now fire a start event before the block is yielded [#4594 state:resolved]
 In many situations, we want to instrument when something starts, as well as when it has finished.
 A canonical example is AR transactions, which are helpful when they log which model started/ended them.

---
 activesupport/lib/active_support/notifications.rb  |    6 +-
 .../active_support/notifications/instrumenter.rb   |    8 +++-
 activesupport/test/notifications_test.rb           |   43 +++++++++++++++----
 3 files changed, 43 insertions(+), 14 deletions(-)

diff --git a/activesupport/lib/active_support/notifications.rb b/activesupport/lib/active_support/notifications.rb
index fd79188..35d8d9d 100644
--- a/activesupport/lib/active_support/notifications.rb
+++ b/activesupport/lib/active_support/notifications.rb
@@ -47,11 +47,11 @@ module ActiveSupport
       attr_writer :notifier
       delegate :publish, :to => :notifier
 
-      def instrument(name, payload = {})
+      def instrument(name, payload = {}, &block)
         if @instrumenters[name]
-          instrumenter.instrument(name, payload) { yield payload if block_given? }
+          instrumenter.instrument(name, payload, &block)
         else
-          yield payload if block_given?
+          block.call(payload) if block_given?
         end
       end
 
diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb
index 441fefb..81bee34 100644
--- a/activesupport/lib/active_support/notifications/instrumenter.rb
+++ b/activesupport/lib/active_support/notifications/instrumenter.rb
@@ -13,12 +13,16 @@ module ActiveSupport
 
       # Instrument the given block by measuring the time taken to execute it
       # and publish it. Notice that events get sent even if an error occurs
-      # in the passed-in block
+      # in the passed-in block, and that events that include a block also 
+      # automatically include a start event
       def instrument(name, payload={})
         started = Time.now
 
         begin
-          yield
+          if block_given?
+            @notifier.publish("#{name}.start", started, started, @id, payload)
+            yield payload
+          end
         rescue Exception => e
           payload[:exception] = [e.class.name, e.message]
           raise e
diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb
index 9faa11e..93c5ddb 100644
--- a/activesupport/test/notifications_test.rb
+++ b/activesupport/test/notifications_test.rb
@@ -133,9 +133,9 @@ module Notifications
 
     def test_instrument_yields_the_paylod_for_further_modification
       assert_equal 2, instrument(:awesome) { |p| p[:result] = 1 + 1 }
-      assert_equal 1, @events.size
-      assert_equal :awesome, @events.first.name
-      assert_equal Hash[:result => 2], @events.first.payload
+      assert_equal 2, @events.size
+      assert_equal :awesome, @events.last.name
+      assert_equal Hash[:result => 2], @events.last.payload
     end
 
     def test_instrumenter_exposes_its_id
@@ -144,16 +144,23 @@ module Notifications
 
     def test_nested_events_can_be_instrumented
       instrument(:awesome, :payload => "notifications") do
+        #assert 'awesome.start' event
+        assert_equal 1, @events.size
+        assert_equal 'awesome.start', @events.last.name
+
         instrument(:wot, :payload => "child") do
-          1 + 1
+          dummy_sum = 1 + 1
+          #assert 'wot.start' event
+          assert_equal 2, @events.size
+          assert_equal 'wot.start', @events.last.name
         end
 
-        assert_equal 1, @events.size
-        assert_equal :wot, @events.first.name
-        assert_equal Hash[:payload => "child"], @events.first.payload
+        assert_equal 3, @events.size
+        assert_equal :wot, @events.last.name
+        assert_equal Hash[:payload => "child"], @events.last.payload
       end
 
-      assert_equal 2, @events.size
+      assert_equal 4, @events.size
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload
     end
@@ -167,7 +174,9 @@ module Notifications
         assert_equal "FAIL", e.message
       end
 
-      assert_equal 1, @events.size
+      assert_equal 2, @events.size
+      assert_equal 'awesome.start', @events.first.name
+      assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications",
         :exception => ["RuntimeError", "FAIL"]], @events.last.payload
     end
@@ -178,6 +187,22 @@ module Notifications
       assert_equal :awesome, @events.last.name
       assert_equal Hash[:payload => "notifications"], @events.last.payload
     end
+
+    def test_start_event_fires_with_block
+      instrument(:awesome, :payload => 'notifications') do
+        #noop
+      end
+
+      assert_equal 2, @events.size
+      assert_equal 'awesome.start', @events.first.name
+    end
+
+    def test_start_event_not_fired_without_block
+      instrument(:awesome, :payload => 'notifications')
+      assert_equal 1, @events.size
+      assert_equal :awesome, @events.first.name
+    end
+
   end
 
   class EventTest < TestCase
-- 
1.7.0.4

instrument_with_start.diff

From 4168abcf1ed6cc23649853f1438f61ad6333414f Mon Sep 17 00:00:00 2001
From: Justin George <justin.george@gmail.com>
Date: Thu, 13 May 2010 14:07:40 -0700
Subject: [PATCH] add start event api to allow instrumentation of start events framework-wide [#4594 state:resolved]

Useful for places where we care about when things start more than how long they take
---
 activesupport/lib/active_support/notifications.rb  |    2 +-
 .../active_support/notifications/instrumenter.rb   |   11 +++++
 activesupport/test/notifications_test.rb           |   41 +++++++++++++++++++-
 3 files changed, 52 insertions(+), 2 deletions(-)

diff --git a/activesupport/lib/active_support/notifications.rb b/activesupport/lib/active_support/notifications.rb
index 3f1fe64..5448b9f 100644
--- a/activesupport/lib/active_support/notifications.rb
+++ b/activesupport/lib/active_support/notifications.rb
@@ -45,7 +45,7 @@ module ActiveSupport
     class << self
       attr_writer :notifier
       delegate :publish, :subscribe, :unsubscribe, :to => :notifier
-      delegate :instrument, :to => :instrumenter
+      delegate :instrument, :instrument_with_start, :to => :instrumenter
 
       def notifier
         @notifier ||= Notifier.new
diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb
index 7e89402..3d40852 100644
--- a/activesupport/lib/active_support/notifications/instrumenter.rb
+++ b/activesupport/lib/active_support/notifications/instrumenter.rb
@@ -26,6 +26,17 @@ module ActiveSupport
         end
       end
 
+      def instrument_with_start(name, payload={})
+        if block_given?
+          instrument("#{name}.start", payload.dup)
+          instrument(name, payload) do
+            yield(payload)
+          end
+        else
+          instrument(name, payload)
+        end
+      end
+
       private
         def unique_id
           SecureRandom.hex(10)
diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb
index e11de5f..277a49e 100644
--- a/activesupport/test/notifications_test.rb
+++ b/activesupport/test/notifications_test.rb
@@ -127,6 +127,45 @@ module Notifications
       end
   end
 
+  class InstrumentWithStartTest < TestCase
+    delegate :instrument_with_start, :to => ActiveSupport::Notifications
+
+    def test_instrument_with_start_returns_block_result
+      assert_equal 4, instrument_with_start(:even_better) { 2 + 2 }
+    end
+
+    def test_instrument_with_start_creates_one_event_with_no_block
+      instrument_with_start(:do_stuff_man)
+      drain
+      assert_equal 1, @events.size
+      assert_equal :do_stuff_man, @events.first.name
+    end
+
+    def test_instrument_with_start_creates_two_events_when_given_block
+      instrument_with_start(:do_stuff_man) { nil }
+      drain
+      assert_equal 2, @events.size
+    end
+
+    def test_instrument_with_start_uses_correct_start_event_name
+      instrument_with_start(:do_stuff_man) { nil }
+      drain
+      assert_equal 2, @events.size
+      assert_equal 'do_stuff_man.start', @events.first.name
+    end
+
+    def test_instrument_with_start_yields_payload_to_second_notification
+      assert_equal 4, instrument_with_start(:even_better) { |p| p[:result] = 2 + 2 }
+      drain
+
+      assert_equal 2, @events.size
+      assert_equal :even_better, @events.last.name
+      assert_equal Hash[:result => 4], @events.last.payload
+    end
+
+  end
+
+
   class InstrumentationTest < TestCase
     delegate :instrument, :to => ActiveSupport::Notifications
 
@@ -135,7 +174,7 @@ module Notifications
       drain
     end
 
-    def test_instrument_yields_the_paylod_for_further_modification
+    def test_instrument_yields_payload_for_further_modification
       assert_equal 2, instrument(:awesome) { |p| p[:result] = 1 + 1 }
       drain
 
-- 
1.7.0.3