use a hash to collect optional statistics about the instrumentation

activerecord/lib/active_record/connection_adapters/abstract_adapter.rb

@@ -36,9 +36,12 @@ module ActiveRecord
 
       define_callbacks :checkout, :checkin
 
+      @@row_even = true
+
       def initialize(connection, logger = nil) #:nodoc:
         @active = nil
         @connection, @logger = connection, logger
+        @runtime = 0
         @query_cache_enabled = false
         @query_cache = {}
       end
@@ -89,6 +92,11 @@ module ActiveRecord
         false
       end
 
+      def reset_runtime #:nodoc:
+        rt, @runtime = @runtime, 0
+        rt
+      end
+
       # QUOTING ==================================================
 
       # Override to return the quoted table name. Defaults to column quoting.
@@ -191,10 +199,16 @@ module ActiveRecord
 
         def log(sql, name)
           name ||= "SQL"
-          ActiveSupport::Notifications.instrument("sql.active_record",
-            :sql => sql, :name => name, :connection_id => object_id) do
+          instrumenter = ActiveSupport::Notifications.instrumenter
+          info = {}
+
+          result = instrumenter.instrument("sql.active_record",
+            {:sql => sql, :name => name, :connection_id => object_id}, info) do
             yield
           end
+          @runtime += info[:elapsed]
+
+          result
         rescue Exception => e
           message = "#{e.class.name}: #{e.message}: #{sql}"
           @logger.debug message if @logger

activerecord/lib/active_record/log_subscriber.rb

@@ -1,25 +1,11 @@
 module ActiveRecord
   class LogSubscriber < ActiveSupport::LogSubscriber
-    def self.runtime=(value)
-      Thread.current["active_record_sql_runtime"] = value
-    end
-
-    def self.runtime
-      Thread.current["active_record_sql_runtime"] ||= 0
-    end
-
-    def self.reset_runtime
-      rt, self.runtime = runtime, 0
-      rt
-    end
-
     def initialize
       super
       @odd_or_even = false
     end
 
     def sql(event)
-      self.class.runtime += event.duration
       return unless logger.debug?
 
       name = '%s (%.1fms)' % [event.payload[:name], event.duration]

activerecord/lib/active_record/railties/controller_runtime.rb

@@ -11,9 +11,9 @@ module ActiveRecord
 
       def cleanup_view_runtime
         if ActiveRecord::Base.connected?
-          db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime
+          db_rt_before_render = ActiveRecord::Base.connection.reset_runtime
           runtime = super
-          db_rt_after_render = ActiveRecord::LogSubscriber.reset_runtime
+          db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
           self.db_runtime = db_rt_before_render + db_rt_after_render
           runtime - db_rt_after_render
         else

activerecord/test/cases/log_subscriber_test.rb

@@ -57,8 +57,4 @@ class LogSubscriberTest < ActiveRecord::TestCase
     wait
     assert_equal 0, @logger.logged(:debug).size
   end
-
-  def test_initializes_runtime
-    Thread.new { assert_equal 0, ActiveRecord::LogSubscriber.runtime }.join
-  end
 end

activesupport/lib/active_support/notifications.rb

@@ -47,11 +47,21 @@ module ActiveSupport
       attr_writer :notifier
       delegate :publish, :unsubscribe, :to => :notifier
 
-      def instrument(name, payload = {})
+      def instrument(name, payload = {}, info = nil)
         if @instrumenters[name]
-          instrumenter.instrument(name, payload) { yield payload if block_given? }
+          instrumenter.instrument(name, payload, info) {
+            yield payload if block_given?
+          }
         else
-          yield payload if block_given?
+          value = nil
+          if block_given?
+            if info
+              info[:elapsed] = Benchmark.ms { value = yield payload }
+            else
+              value = yield payload
+            end
+          end
+          value
         end
       end
 

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -14,16 +14,19 @@ 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
-      def instrument(name, payload={})
-        started = Time.now
-
+      def instrument(name, payload={}, info = nil)
         begin
+          started = Time.now
           yield
         rescue Exception => e
           payload[:exception] = [e.class.name, e.message]
           raise e
         ensure
-          @notifier.publish(name, started, Time.now, @id, payload)
+          finished = Time.now
+          if info
+            info[:elapsed] = 1000.0 * (finished.to_f - started.to_f)
+          end
+          @notifier.publish(name, started, finished, @id, payload)
         end
       end
 

activesupport/test/notifications_test.rb

@@ -172,6 +172,15 @@ module 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")
       assert_equal 1, @events.size