From af0d1fa8920793a95fae456d1f5debdc50287eb3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Wed, 7 Oct 2009 11:17:50 -0300 Subject: Update Orchestra instrumentations and move part of logging to Orchestra. --- actionpack/lib/abstract_controller/logger.rb | 12 +++++----- .../lib/action_controller/caching/fragments.rb | 26 ++++++--------------- actionpack/lib/action_controller/caching/pages.rb | 10 ++------ actionpack/lib/action_controller/instrument.rb | 6 +++++ actionpack/lib/action_view/template/template.rb | 2 +- actionpack/test/controller/caching_test.rb | 9 +------- activerecord/lib/active_record/base.rb | 2 ++ .../connection_adapters/abstract_adapter.rb | 14 ++++------- activerecord/lib/active_record/instrument.rb | 5 ++++ activesupport/lib/active_support/cache.rb | 11 ++++----- .../lib/active_support/cache/mem_cache_store.rb | 11 +++++---- activesupport/lib/active_support/orchestra.rb | 4 ++-- activesupport/test/orchestra_test.rb | 27 +++++++++++++++++++--- 13 files changed, 72 insertions(+), 67 deletions(-) create mode 100644 actionpack/lib/action_controller/instrument.rb create mode 100644 activerecord/lib/active_record/instrument.rb diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index f4d017b8e5..cf1a6f1240 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -10,14 +10,14 @@ module AbstractController module ClassMethods #:nodoc: # Logs a message appending the value measured. - def log_with_time(message, time, log_level=::Logger::DEBUG) + def log(message, log_level=::Logger::DEBUG) return unless logger && logger.level >= log_level - logger.add(log_level, "#{message} (%.1fms)" % time) + logger.add(log_level, message) end # Silences the logger for the duration of the block. def silence - old_logger_level, logger.level = logger.level, ::Logger::ERROR if logge + old_logger_level, logger.level = logger.level, ::Logger::ERROR if logger yield ensure logger.level = old_logger_level if logger @@ -47,7 +47,7 @@ module AbstractController # Override process_action in the AbstractController::Base # to log details about the method. def process_action(action) - event = ActiveSupport::Orchestra.instrument(:process_action, + result = ActiveSupport::Orchestra.instrument(:process_action, :controller => self, :action => action) do super end @@ -56,13 +56,13 @@ module AbstractController log = DelayedLog.new do "\n\nProcessing #{self.class.name}\##{action_name} " \ "to #{request.formats} (for #{request_origin}) " \ - "(%.1fms) [#{request.method.to_s.upcase}]" % event.duration + "[#{request.method.to_s.upcase}]" end logger.info(log) end - event.result + result end private diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb index 59e24619e3..00fb55f843 100644 --- a/actionpack/lib/action_controller/caching/fragments.rb +++ b/actionpack/lib/action_controller/caching/fragments.rb @@ -51,40 +51,32 @@ module ActionController #:nodoc: # Writes content to the location signified by key (see expire_fragment for acceptable formats) def write_fragment(key, content, options = nil) return content unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Orchestra.instrument(:write_fragment, :key => key) do + + ActiveSupport::Orchestra.instrument(:write_fragment, :key => key) do cache_store.write(key, content, options) end - - self.class.log_with_time("Cached fragment miss: #{key}", event.duration) content end # Reads a cached fragment from the location signified by key (see expire_fragment for acceptable formats) def read_fragment(key, options = nil) return unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Orchestra.instrument(:read_fragment, :key => key) do + + ActiveSupport::Orchestra.instrument(:read_fragment, :key => key) do cache_store.read(key, options) end - - self.class.log_with_time("Cached fragment hit: #{key}", event.duration) - event.result end # Check if a cached fragment from the location signified by key exists (see expire_fragment for acceptable formats) def fragment_exist?(key, options = nil) return unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Orchestra.instrument(:fragment_exist?, :key => key) do + + ActiveSupport::Orchestra.instrument(:fragment_exist?, :key => key) do cache_store.exist?(key, options) end - - self.class.log_with_time("Cached fragment exists?: #{key}", event.duration) - event.result end # Removes fragments from the cache. @@ -106,11 +98,10 @@ module ActionController #:nodoc: # method (or delete_matched, for Regexp keys.) def expire_fragment(key, options = nil) return unless cache_configured? - key = fragment_cache_key(key) unless key.is_a?(Regexp) message = nil - event = ActiveSupport::Orchestra.instrument(:expire_fragment, :key => key) do + ActiveSupport::Orchestra.instrument(:expire_fragment, :key => key) do if key.is_a?(Regexp) message = "Expired fragments matching: #{key.source}" cache_store.delete_matched(key, options) @@ -119,9 +110,6 @@ module ActionController #:nodoc: cache_store.delete(key, options) end end - - self.class.log_with_time(message, event.duration) - event.result end end end diff --git a/actionpack/lib/action_controller/caching/pages.rb b/actionpack/lib/action_controller/caching/pages.rb index 4fb154470f..72551d1fd6 100644 --- a/actionpack/lib/action_controller/caching/pages.rb +++ b/actionpack/lib/action_controller/caching/pages.rb @@ -64,12 +64,9 @@ module ActionController #:nodoc: return unless perform_caching path = page_cache_path(path) - event = ActiveSupport::Orchestra.instrument(:expire_page, :path => path) do + ActiveSupport::Orchestra.instrument(:expire_page, :path => path) do File.delete(path) if File.exist?(path) end - - log_with_time("Expired page: #{path}", event.duration) - event.result end # Manually cache the +content+ in the key determined by +path+. Example: @@ -78,13 +75,10 @@ module ActionController #:nodoc: return unless perform_caching path = page_cache_path(path) - event = ActiveSupport::Orchestra.instrument(:cache_page, :path => path) do + ActiveSupport::Orchestra.instrument(:cache_page, :path => path) do FileUtils.makedirs(File.dirname(path)) File.open(path, "wb+") { |f| f.write(content) } end - - log_with_time("Cached page: #{path}", event.duration) - event.result end # Caches the +actions+ using the page-caching approach that'll store the cache in a path within the page_cache_directory that diff --git a/actionpack/lib/action_controller/instrument.rb b/actionpack/lib/action_controller/instrument.rb new file mode 100644 index 0000000000..00888c425f --- /dev/null +++ b/actionpack/lib/action_controller/instrument.rb @@ -0,0 +1,6 @@ +require 'active_support/orchestra' + +ActiveSupport::Orchestra.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |event| + human_name = event.name.to_s.humanize + ActionController::Base.log("#{human_name} (%.1fms)" % event.duration) +end diff --git a/actionpack/lib/action_view/template/template.rb b/actionpack/lib/action_view/template/template.rb index 0f64c23649..84105bd05d 100644 --- a/actionpack/lib/action_view/template/template.rb +++ b/actionpack/lib/action_view/template/template.rb @@ -30,7 +30,7 @@ module ActionView ActiveSupport::Orchestra.instrument(:render_template, :identifier => identifier) do method_name = compile(locals, view) view.send(method_name, locals, &block) - end.result + end rescue Exception => e if e.is_a?(TemplateError) e.sub_template_of(self) diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb index 495b431307..99d7192a9e 100644 --- a/actionpack/test/controller/caching_test.rb +++ b/actionpack/test/controller/caching_test.rb @@ -628,20 +628,13 @@ class FragmentCachingTest < ActionController::TestCase def test_fragment_for_logging fragment_computed = false - - listener = [] - ActiveSupport::Orchestra.register listener + ActiveSupport::Orchestra.queue.expects(:publish).times(4) buffer = 'generated till now -> ' @controller.fragment_for(buffer, 'expensive') { fragment_computed = true } - assert_equal 1, listener.count { |e| e.name == :fragment_exist? } - assert_equal 1, listener.count { |e| e.name == :write_fragment } - assert fragment_computed assert_equal 'generated till now -> ', buffer - ensure - ActiveSupport::Orchestra.unregister listener end end diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb index 283aa7ddfc..eae59dfad7 100755 --- a/activerecord/lib/active_record/base.rb +++ b/activerecord/lib/active_record/base.rb @@ -1,3 +1,4 @@ +require 'benchmark' require 'yaml' require 'set' require 'active_support/dependencies' @@ -11,6 +12,7 @@ require 'active_support/core_ext/hash/indifferent_access' require 'active_support/core_ext/hash/slice' require 'active_support/core_ext/string/behavior' require 'active_support/core_ext/symbol' +require 'active_support/core_ext/benchmark' require 'active_support/core_ext/object/metaclass' module ActiveRecord #:nodoc: diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb index 694e1e561c..b411fe7526 100755 --- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb +++ b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb @@ -1,4 +1,3 @@ -require 'benchmark' require 'date' require 'bigdecimal' require 'bigdecimal/util' @@ -12,8 +11,6 @@ require 'active_record/connection_adapters/abstract/connection_pool' require 'active_record/connection_adapters/abstract/connection_specification' require 'active_record/connection_adapters/abstract/query_cache' -require 'active_support/core_ext/benchmark' - module ActiveRecord module ConnectionAdapters # :nodoc: # ActiveRecord supports multiple database systems. AbstractAdapter and @@ -33,6 +30,7 @@ module ActiveRecord include Quoting, DatabaseStatements, SchemaStatements include QueryCache include ActiveSupport::Callbacks + define_callbacks :checkout, :checkin @@row_even = true @@ -193,6 +191,7 @@ module ActiveRecord end def log_info(sql, name, ms) + @runtime += ms if @logger && @logger.debug? name = '%s (%.1fms)' % [name || 'SQL', ms] @logger.debug(format_log_entry(name, sql.squeeze(' '))) @@ -200,13 +199,8 @@ module ActiveRecord end protected - def log(sql, name) - event = ActiveSupport::Orchestra.instrument(:sql, :sql => sql, :name => name) do - yield if block_given? - end - @runtime += event.duration - log_info(sql, name, event.duration) - event.result + def log(sql, name, &block) + ActiveSupport::Orchestra.instrument(:sql, :sql => sql, :name => name, &block) rescue Exception => e # Log message and raise exception. # Set last_verification to 0, so that connection gets verified diff --git a/activerecord/lib/active_record/instrument.rb b/activerecord/lib/active_record/instrument.rb new file mode 100644 index 0000000000..06d3e40080 --- /dev/null +++ b/activerecord/lib/active_record/instrument.rb @@ -0,0 +1,5 @@ +require 'active_support/orchestra' + +ActiveSupport::Orchestra.subscribe("sql") do |event| + ActiveRecord::Base.connection.log_info(event.payload[:sql], event.payload[:name], event.duration) +end diff --git a/activesupport/lib/active_support/cache.rb b/activesupport/lib/active_support/cache.rb index a415686020..dfd53462af 100644 --- a/activesupport/lib/active_support/cache.rb +++ b/activesupport/lib/active_support/cache.rb @@ -219,7 +219,6 @@ module ActiveSupport end def increment(key, amount = 1) - log("incrementing", key, amount) if num = read(key) write(key, num + amount) else @@ -228,7 +227,6 @@ module ActiveSupport end def decrement(key, amount = 1) - log("decrementing", key, amount) if num = read(key) write(key, num - amount) else @@ -247,13 +245,14 @@ module ActiveSupport payload = { :key => key } payload.merge!(options) if options.is_a?(Hash) - event = ActiveSupport::Orchestra.instrument(:"cache_#{operation}", payload, &block) - log("#{operation} (%.1fms)" % event.duration, key, options) - event.result + # Cache events should be logged or not? + # log(operation, key, options) + ActiveSupport::Orchestra.instrument(:"cache_#{operation}", payload, &block) end def log(operation, key, options) - logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}") if logger && !silence? + return unless logger && !silence? + logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}") end end end diff --git a/activesupport/lib/active_support/cache/mem_cache_store.rb b/activesupport/lib/active_support/cache/mem_cache_store.rb index 516af99ce9..bec9de86ed 100644 --- a/activesupport/lib/active_support/cache/mem_cache_store.rb +++ b/activesupport/lib/active_support/cache/mem_cache_store.rb @@ -103,17 +103,20 @@ module ActiveSupport end def increment(key, amount = 1) # :nodoc: - log("incrementing", key, amount) + response = instrument(:increment, key, :amount => amount) do + @data.incr(key, amount) + end - response = @data.incr(key, amount) response == Response::NOT_FOUND ? nil : response rescue MemCache::MemCacheError nil end def decrement(key, amount = 1) # :nodoc: - log("decrement", key, amount) - response = @data.decr(key, amount) + response = instrument(:decrement, key, :amount => amount) do + @data.decr(key, amount) + end + response == Response::NOT_FOUND ? nil : response rescue MemCache::MemCacheError nil diff --git a/activesupport/lib/active_support/orchestra.rb b/activesupport/lib/active_support/orchestra.rb index 7c9c3074e3..7d4c25669d 100644 --- a/activesupport/lib/active_support/orchestra.rb +++ b/activesupport/lib/active_support/orchestra.rb @@ -66,7 +66,7 @@ module ActiveSupport def instrument(name, payload={}) payload[:time] = Time.now payload[:thread_id] = Thread.current.object_id - payload[:result] = yield + payload[:result] = yield if block_given? ensure payload[:duration] = 1000 * (Time.now.to_f - payload[:time].to_f) @publisher.publish(name, payload) @@ -147,7 +147,7 @@ module ActiveSupport end def publish(name, payload) - unless @pattern && name.to_s !~ @pattern + unless @pattern && !(@pattern === name.to_s) @queue << [name, payload] end end diff --git a/activesupport/test/orchestra_test.rb b/activesupport/test/orchestra_test.rb index 810d99ebeb..7a6e9208b4 100644 --- a/activesupport/test/orchestra_test.rb +++ b/activesupport/test/orchestra_test.rb @@ -90,18 +90,39 @@ class OrchestraMainTest < Test::Unit::TestCase assert_equal Hash[:payload => "orchestra"], @events.last.payload end + def test_event_is_pushed_even_without_block + ActiveSupport::Orchestra.instrument(:awesome, :payload => "orchestra") + sleep(0.1) + + assert_equal 1, @events.size + assert_equal :awesome, @events.last.name + assert_equal Hash[:payload => "orchestra"], @events.last.payload + end + def test_subscriber_with_pattern @another = [] - ActiveSupport::Orchestra.subscribe(/cache/) { |event| @another << event } + ActiveSupport::Orchestra.subscribe("cache"){ |event| @another << event } + ActiveSupport::Orchestra.instrument(:cache){ 1 } + + sleep(0.1) + + assert_equal 1, @another.size + assert_equal :cache, @another.first.name + assert_equal 1, @another.first.result + end + + def test_subscriber_with_pattern_as_regexp + @another = [] + ActiveSupport::Orchestra.subscribe(/cache/){ |event| @another << event } ActiveSupport::Orchestra.instrument(:something){ 0 } - ActiveSupport::Orchestra.instrument(:cache){ 10 } + ActiveSupport::Orchestra.instrument(:cache){ 1 } sleep(0.1) assert_equal 1, @another.size assert_equal :cache, @another.first.name - assert_equal 10, @another.first.result + assert_equal 1, @another.first.result end def test_with_several_consumers_and_several_events -- cgit v1.2.3