diff options
7 files changed, 48 insertions, 30 deletions
diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb index c07ba2ac74..4799b693c5 100644 --- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb +++ b/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 diff --git a/activerecord/lib/active_record/log_subscriber.rb b/activerecord/lib/active_record/log_subscriber.rb index c7ae12977a..278e192e59 100644 --- a/activerecord/lib/active_record/log_subscriber.rb +++ b/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] @@ -45,4 +31,4 @@ module ActiveRecord end end -ActiveRecord::LogSubscriber.attach_to :active_record
\ No newline at end of file +ActiveRecord::LogSubscriber.attach_to :active_record diff --git a/activerecord/lib/active_record/railties/controller_runtime.rb b/activerecord/lib/active_record/railties/controller_runtime.rb index bc6ca936c0..aed1c59b00 100644 --- a/activerecord/lib/active_record/railties/controller_runtime.rb +++ b/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 diff --git a/activerecord/test/cases/log_subscriber_test.rb b/activerecord/test/cases/log_subscriber_test.rb index cbaaca764b..342daa19df 100644 --- a/activerecord/test/cases/log_subscriber_test.rb +++ b/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 diff --git a/activesupport/lib/active_support/notifications.rb b/activesupport/lib/active_support/notifications.rb index 886d7183eb..d65431a943 100644 --- a/activesupport/lib/active_support/notifications.rb +++ b/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 diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb index 441fefb491..4fc446fb2b 100644 --- a/activesupport/lib/active_support/notifications/instrumenter.rb +++ b/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 diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb index 9faa11efbc..41e8ca4ae7 100644 --- a/activesupport/test/notifications_test.rb +++ b/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 |