diff options
25 files changed, 461 insertions, 374 deletions
diff --git a/.gitignore b/.gitignore index da296e7e11..ea0d8bbba7 100644 --- a/.gitignore +++ b/.gitignore @@ -28,6 +28,9 @@ railties/guides/output *.swp *.swo actionpack/bin +activerecord/bin vendor/gems/ */vendor/gems/ railties/tmp +activerecord/vendor +actionpack/vendor diff --git a/actionmailer/lib/action_mailer/base.rb b/actionmailer/lib/action_mailer/base.rb index 24be66d197..df3bfb3620 100644 --- a/actionmailer/lib/action_mailer/base.rb +++ b/actionmailer/lib/action_mailer/base.rb @@ -394,7 +394,7 @@ module ActionMailer #:nodoc: def controller_path self.class.controller_path end - + def formats @template.formats end @@ -583,9 +583,9 @@ module ActionMailer #:nodoc: if template.respond_to?(:mime_type) @current_template_content_type = template.mime_type && template.mime_type.to_sym.to_s end - + @template = initialize_template_class(body) - layout = _pick_layout(layout, true) unless + layout = _pick_layout(layout, true) unless ActionController::Base.exempt_from_layout.include?(template.handler) @template._render_template(template, layout, {}) ensure @@ -601,16 +601,16 @@ module ActionMailer #:nodoc: def render(opts) opts[:locals] ||= {} layout, file = opts.delete(:layout), opts[:file] - + begin @template = initialize_template_class(opts.delete(:body)) - + if file prefix = mailer_name unless file =~ /\// template = view_paths.find(file, {:formats => formats}, prefix) end - layout = _pick_layout(layout, + layout = _pick_layout(layout, !template || ActionController::Base.exempt_from_layout.include?(template.handler)) if template @@ -649,7 +649,7 @@ module ActionMailer #:nodoc: def sort_parts(parts, order = []) order = order.collect { |s| s.downcase } - + parts = parts.sort do |a, b| a_ct = a.content_type.downcase b_ct = b.content_type.downcase @@ -690,7 +690,7 @@ module ActionMailer #:nodoc: headers.each { |k, v| m[k] = v } real_content_type, ctype_attrs = parse_content_type - + if @parts.empty? m.set_content_type(real_content_type, nil, ctype_attrs) m.body = normalize_new_lines(body) diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index f3130fa5e8..27ba5be45f 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -1,4 +1,5 @@ require 'active_support/core_ext/logger' +require 'active_support/benchmarkable' module AbstractController module Logger @@ -6,22 +7,7 @@ module AbstractController included do cattr_accessor :logger - end - - module ClassMethods #:nodoc: - # Logs a message appending the value measured. - def log_with_time(message, time, log_level=::Logger::DEBUG) - return unless logger && logger.level >= log_level - logger.add(log_level, "#{message} (%.1fms)" % time) - end - - # Silences the logger for the duration of the block. - def silence - old_logger_level, logger.level = logger.level, ::Logger::ERROR if logge - yield - ensure - logger.level = old_logger_level if logger - end + extend ActiveSupport::Benchmarkable end # A class that allows you to defer expensive processing @@ -47,7 +33,7 @@ module AbstractController # Override process_action in the AbstractController::Base # to log details about the method. def process_action(action) - event = ActiveSupport::Notifications.instrument(:process_action, + result = ActiveSupport::Notifications.instrument(:process_action, :controller => self, :action => action) do super end @@ -56,13 +42,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 d30c2625a6..8c1167d526 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 <tt>content</tt> to the location signified by <tt>key</tt> (see <tt>expire_fragment</tt> for acceptable formats) def write_fragment(key, content, options = nil) return content unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Notifications.instrument(:write_fragment, :key => key) do + + ActiveSupport::Notifications.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 <tt>key</tt> (see <tt>expire_fragment</tt> for acceptable formats) def read_fragment(key, options = nil) return unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Notifications.instrument(:read_fragment, :key => key) do + + ActiveSupport::Notifications.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 <tt>key</tt> exists (see <tt>expire_fragment</tt> for acceptable formats) def fragment_exist?(key, options = nil) return unless cache_configured? - key = fragment_cache_key(key) - event = ActiveSupport::Notifications.instrument(:fragment_exist?, :key => key) do + + ActiveSupport::Notifications.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 <tt>delete_matched</tt>, 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::Notifications.instrument(:expire_fragment, :key => key) do + ActiveSupport::Notifications.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 0cf245360a..d46f528c7e 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::Notifications.instrument(:expire_page, :path => path) do + ActiveSupport::Notifications.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::Notifications.instrument(:cache_page, :path => path) do + ActiveSupport::Notifications.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/metal/benchmarking.rb b/actionpack/lib/action_controller/metal/benchmarking.rb index d4cb1e122d..e58df69172 100644 --- a/actionpack/lib/action_controller/metal/benchmarking.rb +++ b/actionpack/lib/action_controller/metal/benchmarking.rb @@ -1,4 +1,4 @@ -require 'benchmark' +require 'active_support/core_ext/benchmark' module ActionController #:nodoc: # The benchmarking module times the performance of actions and reports to the logger. If the Active Record @@ -6,25 +6,6 @@ module ActionController #:nodoc: module Benchmarking #:nodoc: extend ActiveSupport::Concern - module ClassMethods - # Log and benchmark the workings of a single block and silence whatever logging that may have happened inside it - # (unless <tt>use_silence</tt> is set to false). - # - # The benchmark is only recorded if the current level of the logger matches the <tt>log_level</tt>, which makes it - # easy to include benchmarking statements in production software that will remain inexpensive because the benchmark - # will only be conducted if the log level is low enough. - def benchmark(title, log_level = Logger::DEBUG, use_silence = true) - if logger && logger.level == log_level - result = nil - ms = Benchmark.ms { result = use_silence ? silence { yield } : yield } - logger.add(log_level, "#{title} (#{('%.1f' % ms)}ms)") - result - else - yield - end - end - end - protected def render(*args, &block) if logger @@ -45,7 +26,7 @@ module ActionController #:nodoc: else super end - end + end private def process_action(*args) diff --git a/actionpack/lib/action_controller/notifications.rb b/actionpack/lib/action_controller/notifications.rb new file mode 100644 index 0000000000..4ec88193d5 --- /dev/null +++ b/actionpack/lib/action_controller/notifications.rb @@ -0,0 +1,8 @@ +require 'active_support/notifications' + +ActiveSupport::Notifications.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |event| + if logger = ActionController::Base.logger + human_name = event.name.to_s.humanize + logger.info("#{human_name} (%.1fms)" % event.duration) + end +end diff --git a/actionpack/lib/action_view/helpers.rb b/actionpack/lib/action_view/helpers.rb index d63e8602f1..3d088678fc 100644 --- a/actionpack/lib/action_view/helpers.rb +++ b/actionpack/lib/action_view/helpers.rb @@ -1,10 +1,11 @@ +require 'active_support/benchmarkable' + module ActionView #:nodoc: module Helpers #:nodoc: autoload :ActiveModelHelper, 'action_view/helpers/active_model_helper' autoload :AjaxHelper, 'action_view/helpers/ajax_helper' autoload :AssetTagHelper, 'action_view/helpers/asset_tag_helper' autoload :AtomFeedHelper, 'action_view/helpers/atom_feed_helper' - autoload :BenchmarkHelper, 'action_view/helpers/benchmark_helper' autoload :CacheHelper, 'action_view/helpers/cache_helper' autoload :CaptureHelper, 'action_view/helpers/capture_helper' autoload :DateHelper, 'action_view/helpers/date_helper' @@ -33,10 +34,11 @@ module ActionView #:nodoc: include SanitizeHelper::ClassMethods end + include ActiveSupport::Benchmarkable + include ActiveModelHelper include AssetTagHelper include AtomFeedHelper - include BenchmarkHelper include CacheHelper include CaptureHelper include DateHelper diff --git a/actionpack/lib/action_view/helpers/benchmark_helper.rb b/actionpack/lib/action_view/helpers/benchmark_helper.rb deleted file mode 100644 index c13a069a35..0000000000 --- a/actionpack/lib/action_view/helpers/benchmark_helper.rb +++ /dev/null @@ -1,54 +0,0 @@ -require 'active_support/core_ext/benchmark' - -module ActionView - module Helpers - # This helper offers a method to measure the execution time of a block - # in a template. - module BenchmarkHelper - # Allows you to measure the execution time of a block - # in a template and records the result to the log. Wrap this block around - # expensive operations or possible bottlenecks to get a time reading - # for the operation. For example, let's say you thought your file - # processing method was taking too long; you could wrap it in a benchmark block. - # - # <% benchmark "Process data files" do %> - # <%= expensive_files_operation %> - # <% end %> - # - # That would add something like "Process data files (345.2ms)" to the log, - # which you can then use to compare timings when optimizing your code. - # - # You may give an optional logger level as the :level option. - # (:debug, :info, :warn, :error); the default value is :info. - # - # <% benchmark "Low-level files", :level => :debug do %> - # <%= lowlevel_files_operation %> - # <% end %> - # - # Finally, you can pass true as the third argument to silence all log activity - # inside the block. This is great for boiling down a noisy block to just a single statement: - # - # <% benchmark "Process data files", :level => :info, :silence => true do %> - # <%= expensive_and_chatty_files_operation %> - # <% end %> - def benchmark(message = "Benchmarking", options = {}) - if controller.logger - if options.is_a?(Symbol) - ActiveSupport::Deprecation.warn("use benchmark('#{message}', :level => :#{options}) instead", caller) - options = { :level => options, :silence => false } - else - options.assert_valid_keys(:level, :silence) - options[:level] ||= :info - end - - result = nil - ms = Benchmark.ms { result = options[:silence] ? controller.logger.silence { yield } : yield } - controller.logger.send(options[:level], '%s (%.1fms)' % [ message, ms ]) - result - else - yield - end - end - end - end -end diff --git a/actionpack/lib/action_view/template/template.rb b/actionpack/lib/action_view/template/template.rb index d02feb5e1e..d1970ca3c7 100644 --- a/actionpack/lib/action_view/template/template.rb +++ b/actionpack/lib/action_view/template/template.rb @@ -30,7 +30,7 @@ module ActionView ActiveSupport::Notifications.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 1e13e21419..df2dee8228 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::Notifications.register listener + ActiveSupport::Notifications.queue.expects(:publish).times(2) 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::Notifications.unregister listener end end diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb index 283aa7ddfc..76dbd00ad9 100755 --- a/activerecord/lib/active_record/base.rb +++ b/activerecord/lib/active_record/base.rb @@ -1,5 +1,7 @@ +require 'benchmark' require 'yaml' require 'set' +require 'active_support/benchmarkable' require 'active_support/dependencies' require 'active_support/time' require 'active_support/core_ext/class/attribute_accessors' @@ -1463,38 +1465,6 @@ module ActiveRecord #:nodoc: connection.quote(object) end - # Log and benchmark multiple statements in a single block. Example: - # - # Project.benchmark("Creating project") do - # project = Project.create("name" => "stuff") - # project.create_manager("name" => "David") - # project.milestones << Milestone.find(:all) - # end - # - # The benchmark is only recorded if the current level of the logger is less than or equal to the <tt>log_level</tt>, - # which makes it easy to include benchmarking statements in production software that will remain inexpensive because - # the benchmark will only be conducted if the log level is low enough. - # - # The logging of the multiple statements is turned off unless <tt>use_silence</tt> is set to false. - def benchmark(title, log_level = Logger::DEBUG, use_silence = true) - if logger && logger.level <= log_level - result = nil - ms = Benchmark.ms { result = use_silence ? silence { yield } : yield } - logger.add(log_level, '%s (%.1fms)' % [title, ms]) - result - else - yield - end - end - - # Silences the logger for the duration of the block. - def silence - old_logger_level, logger.level = logger.level, Logger::ERROR if logger - yield - ensure - logger.level = old_logger_level if logger - end - # Overwrite the default class equality method to provide support for association proxies. def ===(object) object.is_a?(self) @@ -3153,6 +3123,8 @@ module ActiveRecord #:nodoc: Base.class_eval do extend ActiveModel::Naming extend QueryCache::ClassMethods + extend ActiveSupport::Benchmarkable + include Validations include Locking::Optimistic, Locking::Pessimistic include AttributeMethods diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb index 9b65d68fec..8fae26b790 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::Notifications.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::Notifications.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/notifications.rb b/activerecord/lib/active_record/notifications.rb new file mode 100644 index 0000000000..a5ce7ac524 --- /dev/null +++ b/activerecord/lib/active_record/notifications.rb @@ -0,0 +1,5 @@ +require 'active_support/notifications' + +ActiveSupport::Notifications.subscribe("sql") do |event| + ActiveRecord::Base.connection.log_info(event.payload[:sql], event.payload[:name], event.duration) +end diff --git a/activerecord/test/cases/base_test.rb b/activerecord/test/cases/base_test.rb index bfb2df313b..5c2911eca1 100755 --- a/activerecord/test/cases/base_test.rb +++ b/activerecord/test/cases/base_test.rb @@ -2195,9 +2195,9 @@ class BasicsTest < ActiveRecord::TestCase log = StringIO.new ActiveRecord::Base.logger = Logger.new(log) ActiveRecord::Base.logger.level = Logger::WARN - ActiveRecord::Base.benchmark("Debug Topic Count", Logger::DEBUG) { Topic.count } - ActiveRecord::Base.benchmark("Warn Topic Count", Logger::WARN) { Topic.count } - ActiveRecord::Base.benchmark("Error Topic Count", Logger::ERROR) { Topic.count } + ActiveRecord::Base.benchmark("Debug Topic Count", :level => :debug) { Topic.count } + ActiveRecord::Base.benchmark("Warn Topic Count", :level => :warn) { Topic.count } + ActiveRecord::Base.benchmark("Error Topic Count", :level => :error) { Topic.count } assert_no_match /Debug Topic Count/, log.string assert_match /Warn Topic Count/, log.string assert_match /Error Topic Count/, log.string @@ -2209,8 +2209,8 @@ class BasicsTest < ActiveRecord::TestCase original_logger = ActiveRecord::Base.logger log = StringIO.new ActiveRecord::Base.logger = Logger.new(log) - ActiveRecord::Base.benchmark("Logging", Logger::DEBUG, true) { ActiveRecord::Base.logger.debug "Loud" } - ActiveRecord::Base.benchmark("Logging", Logger::DEBUG, false) { ActiveRecord::Base.logger.debug "Quiet" } + ActiveRecord::Base.benchmark("Logging", :level => :debug, :silence => true) { ActiveRecord::Base.logger.debug "Loud" } + ActiveRecord::Base.benchmark("Logging", :level => :debug, :silence => false) { ActiveRecord::Base.logger.debug "Quiet" } assert_no_match /Loud/, log.string assert_match /Quiet/, log.string ensure diff --git a/activesupport/lib/active_support/autoload.rb b/activesupport/lib/active_support/autoload.rb index da12ecceca..63f7338a68 100644 --- a/activesupport/lib/active_support/autoload.rb +++ b/activesupport/lib/active_support/autoload.rb @@ -2,6 +2,7 @@ module ActiveSupport autoload :BacktraceCleaner, 'active_support/backtrace_cleaner' autoload :Base64, 'active_support/base64' autoload :BasicObject, 'active_support/basic_object' + autoload :Benchmarkable, 'active_support/benchmarkable' autoload :BufferedLogger, 'active_support/buffered_logger' autoload :Cache, 'active_support/cache' autoload :Callbacks, 'active_support/callbacks' @@ -17,9 +18,9 @@ module ActiveSupport autoload :MessageVerifier, 'active_support/message_verifier' autoload :Multibyte, 'active_support/multibyte' autoload :OptionMerger, 'active_support/option_merger' - autoload :Notifications, 'active_support/notifications' autoload :OrderedHash, 'active_support/ordered_hash' autoload :OrderedOptions, 'active_support/ordered_options' + autoload :Notifications, 'active_support/notifications' autoload :Rescuable, 'active_support/rescuable' autoload :SecureRandom, 'active_support/secure_random' autoload :StringInquirer, 'active_support/string_inquirer' diff --git a/activesupport/lib/active_support/benchmarkable.rb b/activesupport/lib/active_support/benchmarkable.rb new file mode 100644 index 0000000000..6a41aab166 --- /dev/null +++ b/activesupport/lib/active_support/benchmarkable.rb @@ -0,0 +1,59 @@ +require 'active_support/core_ext/benchmark' + +module ActiveSupport + module Benchmarkable + # Allows you to measure the execution time of a block + # in a template and records the result to the log. Wrap this block around + # expensive operations or possible bottlenecks to get a time reading + # for the operation. For example, let's say you thought your file + # processing method was taking too long; you could wrap it in a benchmark block. + # + # <% benchmark "Process data files" do %> + # <%= expensive_files_operation %> + # <% end %> + # + # That would add something like "Process data files (345.2ms)" to the log, + # which you can then use to compare timings when optimizing your code. + # + # You may give an optional logger level as the :level option. + # (:debug, :info, :warn, :error); the default value is :info. + # + # <% benchmark "Low-level files", :level => :debug do %> + # <%= lowlevel_files_operation %> + # <% end %> + # + # Finally, you can pass true as the third argument to silence all log activity + # inside the block. This is great for boiling down a noisy block to just a single statement: + # + # <% benchmark "Process data files", :level => :info, :silence => true do %> + # <%= expensive_and_chatty_files_operation %> + # <% end %> + def benchmark(message = "Benchmarking", options = {}) + if logger + if options.is_a?(Symbol) + ActiveSupport::Deprecation.warn("use benchmark('#{message}', :level => :#{options}) instead", caller) + options = { :level => options, :silence => false } + else + options.assert_valid_keys(:level, :silence) + options[:level] ||= :info + end + + result = nil + ms = Benchmark.ms { result = options[:silence] ? logger.silence { yield } : yield } + logger.send(options[:level], '%s (%.1fms)' % [ message, ms ]) + result + else + yield + end + end + + # Silence the logger during the execution of the block. + # + def silence + old_logger_level, logger.level = logger.level, ::Logger::ERROR if logger + yield + ensure + logger.level = old_logger_level if logger + end + end +end diff --git a/activesupport/lib/active_support/cache.rb b/activesupport/lib/active_support/cache.rb index e0f671f283..818983fdd6 100644 --- a/activesupport/lib/active_support/cache.rb +++ b/activesupport/lib/active_support/cache.rb @@ -105,7 +105,7 @@ module ActiveSupport # cache.write("city", "Duckburgh") # cache.read("city") # => "Duckburgh" class Store - cattr_accessor :logger + cattr_accessor :logger, :instance_writter => false attr_reader :silence alias :silence? :silence @@ -122,6 +122,15 @@ module ActiveSupport @silence = previous_silence end + # Set to true if cache stores should be instrumented. By default is false. + def self.instrument=(boolean) + Thread.current[:instrument_cache_store] = boolean + end + + def self.instrument + Thread.current[:instrument_cache_store] || false + end + # Fetches data from the cache, using the given key. If there is data in # the cache with the given key, then that data is returned. # @@ -219,7 +228,6 @@ module ActiveSupport end def increment(key, amount = 1) - log("incrementing", key, amount) if num = read(key) write(key, num + amount) else @@ -228,7 +236,6 @@ module ActiveSupport end def decrement(key, amount = 1) - log("decrementing", key, amount) if num = read(key) write(key, num - amount) else @@ -244,16 +251,20 @@ module ActiveSupport end def instrument(operation, key, options, &block) - payload = { :key => key } - payload.merge!(options) if options.is_a?(Hash) + log(operation, key, options) - event = ActiveSupport::Notifications.instrument(:"cache_#{operation}", payload, &block) - log("#{operation} (%.1fms)" % event.duration, key, options) - event.result + if self.class.instrument + payload = { :key => key } + payload.merge!(options) if options.is_a?(Hash) + ActiveSupport::Notifications.instrument(:"cache_#{operation}", payload, &block) + else + yield + end 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/notifications.rb b/activesupport/lib/active_support/notifications.rb index 6335686196..7e9ffca13f 100644 --- a/activesupport/lib/active_support/notifications.rb +++ b/activesupport/lib/active_support/notifications.rb @@ -1,103 +1,171 @@ require 'thread' +require 'active_support/core_ext/module/delegation' +require 'active_support/core_ext/module/attribute_accessors' module ActiveSupport - # Notifications provides an instrumentation API for Ruby. To instrument an action - # in Ruby you just need to: + # Notifications provides an instrumentation API for Ruby. To instrument an + # action in Ruby you just need to do: # # ActiveSupport::Notifications.instrument(:render, :extra => :information) do # render :text => "Foo" # end # - # Those actions are consumed by listeners. A listener is anything that responds - # to push. You can even register an array: + # You can consume those events and the information they provide by registering + # a subscriber. For instance, let's store all instrumented events in an array: # - # @listener = [] - # ActiveSupport::Notifications.register @listener + # @events = [] + # + # ActiveSupport::Notifications.subscribe do |event| + # @events << event + # end # # ActiveSupport::Notifications.instrument(:render, :extra => :information) do # render :text => "Foo" # end # - # event #=> ActiveSupport::Notifications::Event + # event = @events.first + # event.class #=> ActiveSupport::Notifications::Event # event.name #=> :render # event.duration #=> 10 (in miliseconds) # event.result #=> "Foo" # event.payload #=> { :extra => :information } # - # Notifications ships with a default listener implementation which puts events in - # a stream and consume them in a Thread. This implementation is thread safe - # and is available at ActiveSupport::Notifications::Listener. + # When subscribing to Notifications, you can pass a pattern, to only consume + # events that match the pattern: + # + # ActiveSupport::Notifications.subscribe(/render/) do |event| + # @render_events << event + # end + # + # Notifications ships with a queue implementation that consumes and publish events + # to subscribers in a thread. You can use any queue implementation you want. # module Notifications - @stacked_events = Hash.new { |h,k| h[k] = [] } - @listeners = [] - - def self.instrument(name, payload=nil) - stack = @stacked_events[Thread.current.object_id] - event = Event.new(name, stack.last, payload) - stack << event - event.result = yield - event - ensure - event.finish! - stack.delete(event) - @listeners.each { |s| s.push(event) } + mattr_accessor :queue + + class << self + delegate :instrument, :to => :instrumenter + + def instrumenter + Thread.current[:notifications_instrumeter] ||= Instrumenter.new(publisher) + end + + def publisher + @publisher ||= Publisher.new(queue) + end + + def subscribe(pattern=nil, &block) + Subscriber.new(queue).bind(pattern).subscribe(&block) + end end - def self.register(listener) - @listeners << listener + class Instrumenter + def initialize(publisher) + @publisher = publisher + end + + def instrument(name, payload={}) + payload[:time] = Time.now + payload[:thread_id] = Thread.current.object_id + payload[:result] = yield if block_given? + ensure + payload[:duration] = 1000 * (Time.now.to_f - payload[:time].to_f) + @publisher.publish(name, payload) + end end - def self.unregister(listener) - @listeners.delete(listener) + class Publisher + def initialize(queue) + @queue = queue + end + + def publish(name, payload) + @queue.publish(name, payload) + end + end + + class Subscriber + def initialize(queue) + @queue = queue + end + + def bind(pattern) + @pattern = pattern + self + end + + def subscribe + @queue.subscribe(@pattern) do |name, payload| + yield Event.new(name, payload) + end + end end class Event - attr_reader :name, :time, :duration, :parent, :thread_id, :payload - attr_accessor :result + attr_reader :name, :time, :duration, :thread_id, :result, :payload - def initialize(name, parent=nil, payload=nil) + def initialize(name, payload) @name = name - @time = Time.now - @thread_id = Thread.current.object_id - @parent = parent - @payload = payload + @payload = payload.dup + @time = @payload.delete(:time) + @thread_id = @payload.delete(:thread_id) + @result = @payload.delete(:result) + @duration = @payload.delete(:duration) end - def finish! - @duration = 1000 * (Time.now.to_f - @time.to_f) + def parent_of?(event) + start = (self.time - event.time) * 1000 + start <= 0 && (start + self.duration >= event.duration) end end - class Listener - attr_reader :mutex, :signaler, :thread - + # This is a default queue implementation that ships with Notifications. It + # consumes events in a thread and publish them to all registered subscribers. + # + class LittleFanout def initialize - @mutex, @signaler = Mutex.new, ConditionVariable.new - @stream = [] - @thread = Thread.new do - loop do - (event = @stream.shift) ? consume(event) : wait - end - end + @listeners, @stream = [], Queue.new + @thread = Thread.new { consume } end - def wait - @mutex.synchronize do - @signaler.wait(@mutex) - end + def publish(*event) + @stream.push(event) + end + + def subscribe(pattern=nil, &block) + @listeners << Listener.new(pattern, &block) end - def push(event) - @mutex.synchronize do - @stream.push(event) - @signaler.broadcast + def consume + while event = @stream.shift + @listeners.each { |l| l.publish(*event) } end end - def consume(event) - raise NotImplementedError + class Listener + attr_reader :thread + + def initialize(pattern, &block) + @pattern = pattern + @subscriber = block + @queue = Queue.new + @thread = Thread.new { consume } + end + + def publish(name, payload) + unless @pattern && !(@pattern === name.to_s) + @queue << [name, payload] + end + end + + def consume + while event = @queue.shift + @subscriber.call(*event) + end + end end end end + + Notifications.queue = Notifications::LittleFanout.new end diff --git a/actionpack/test/template/benchmark_helper_test.rb b/activesupport/test/benchmarkable_test.rb index ac31fc6503..e807bcb732 100644 --- a/actionpack/test/template/benchmark_helper_test.rb +++ b/activesupport/test/benchmarkable_test.rb @@ -1,17 +1,11 @@ require 'abstract_unit' require 'action_view/helpers/benchmark_helper' -class BenchmarkHelperTest < ActionView::TestCase - tests ActionView::Helpers::BenchmarkHelper - - def setup - super - controller.logger = ActiveSupport::BufferedLogger.new(StringIO.new) - controller.logger.auto_flushing = false - end +class BenchmarkableTest < ActiveSupport::TestCase + include ActiveSupport::Benchmarkable def teardown - controller.logger.send(:clear_buffer) + logger.send(:clear_buffer) end def test_without_block @@ -45,22 +39,22 @@ class BenchmarkHelperTest < ActionView::TestCase end def test_within_level - controller.logger.level = ActiveSupport::BufferedLogger::DEBUG + logger.level = ActiveSupport::BufferedLogger::DEBUG benchmark('included_debug_run', :level => :debug) { } assert_last_logged 'included_debug_run' end def test_outside_level - controller.logger.level = ActiveSupport::BufferedLogger::ERROR + logger.level = ActiveSupport::BufferedLogger::ERROR benchmark('skipped_debug_run', :level => :debug) { } assert_no_match(/skipped_debug_run/, buffer.last) ensure - controller.logger.level = ActiveSupport::BufferedLogger::DEBUG + logger.level = ActiveSupport::BufferedLogger::DEBUG end def test_without_silencing benchmark('debug_run', :silence => false) do - controller.logger.info "not silenced!" + logger.info "not silenced!" end assert_equal 2, buffer.size @@ -68,18 +62,25 @@ class BenchmarkHelperTest < ActionView::TestCase def test_with_silencing benchmark('debug_run', :silence => true) do - controller.logger.info "silenced!" + logger.info "silenced!" end assert_equal 1, buffer.size end - private + def logger + @logger ||= begin + logger = ActiveSupport::BufferedLogger.new(StringIO.new) + logger.auto_flushing = false + logger + end + end + def buffer - controller.logger.send(:buffer) + logger.send(:buffer) end - + def assert_last_logged(message = 'Benchmarking') assert_match(/^#{message} \(.*\)$/, buffer.last) end diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb index 8f00eff106..561ee2b0ba 100644 --- a/activesupport/test/notifications_test.rb +++ b/activesupport/test/notifications_test.rb @@ -1,161 +1,164 @@ require 'abstract_unit' -class NotificationsEventTest < Test::Unit::TestCase - def setup - @parent = ActiveSupport::Notifications::Event.new(:parent) +# Allow LittleFanout to be cleaned. +class ActiveSupport::Notifications::LittleFanout + def clear + @listeners.clear end +end - def test_initialization_with_name_and_parent_and_payload - event = ActiveSupport::Notifications::Event.new(:awesome, @parent, :payload => "notifications") - assert_equal(:awesome, event.name) - assert_equal(@parent, event.parent) - assert_equal({ :payload => "notifications" }, event.payload) +class NotificationsEventTest < Test::Unit::TestCase + def test_events_are_initialized_with_name_and_payload + event = event(:foo, :payload => :bar) + assert_equal :foo, event.name + assert_equal Hash[:payload => :bar], event.payload end - def test_thread_id_is_set_on_initialization - event = ActiveSupport::Notifications::Event.new(:awesome) - assert_equal Thread.current.object_id, event.thread_id - end + def test_events_consumes_information_given_as_payload + event = event(:foo, :time => (time = Time.now), :result => 1, :duration => 10) - def test_current_time_is_set_on_initialization - previous_time = Time.now.utc - event = ActiveSupport::Notifications::Event.new(:awesome) - assert_kind_of Time, event.time - assert event.time.to_f >= previous_time.to_f + assert_equal Hash.new, event.payload + assert_equal time, event.time + assert_equal 1, event.result + assert_equal 10, event.duration end - def test_duration_is_set_when_event_finishes - event = ActiveSupport::Notifications::Event.new(:awesome) - sleep(0.1) - event.finish! - assert_in_delta 100, event.duration, 30 + def test_event_is_parent_based_on_time_frame + parent = event(:foo, :time => Time.utc(2009), :duration => 10000) + child = event(:foo, :time => Time.utc(2009, 01, 01, 0, 0, 1), :duration => 1000) + not_child = event(:foo, :time => Time.utc(2009, 01, 01, 0, 0, 1), :duration => 10000) + + assert parent.parent_of?(child) + assert !child.parent_of?(parent) + assert !parent.parent_of?(not_child) + assert !not_child.parent_of?(parent) end + + protected + + def event(*args) + ActiveSupport::Notifications::Event.new(*args) + end end class NotificationsMainTest < Test::Unit::TestCase def setup - @listener = [] - ActiveSupport::Notifications.register @listener + @events = [] + Thread.abort_on_exception = true + ActiveSupport::Notifications.subscribe { |event| @events << event } end def teardown - ActiveSupport::Notifications.unregister @listener + Thread.abort_on_exception = false + ActiveSupport::Notifications.queue.clear end - def test_notifications_allows_any_action_to_be_instrumented - event = ActiveSupport::Notifications.instrument(:awesome, "notifications") do - sleep(0.1) - end - - assert_equal :awesome, event.name - assert_equal "notifications", event.payload - assert_in_delta 100, event.duration, 30 - end - - def test_block_result_is_stored - event = ActiveSupport::Notifications.instrument(:awesome, "notifications") do + def test_notifications_returns_action_result + result = ActiveSupport::Notifications.instrument(:awesome, :payload => "notifications") do 1 + 1 end - assert_equal 2, event.result + assert_equal 2, result end def test_events_are_published_to_a_listener - event = ActiveSupport::Notifications.instrument(:awesome, "notifications") do + ActiveSupport::Notifications.instrument(:awesome, :payload => "notifications") do 1 + 1 end - assert_equal 1, @listener.size - assert_equal :awesome, @listener.last.name - assert_equal "notifications", @listener.last.payload + sleep(0.1) + + assert_equal 1, @events.size + assert_equal :awesome, @events.last.name + assert_equal Hash[:payload => "notifications"], @events.last.payload end def test_nested_events_can_be_instrumented - ActiveSupport::Notifications.instrument(:awesome, "notifications") do - ActiveSupport::Notifications.instrument(:wot, "child") do - sleep(0.1) + ActiveSupport::Notifications.instrument(:awesome, :payload => "notifications") do + ActiveSupport::Notifications.instrument(:wot, :payload => "child") do + 1 + 1 end - assert_equal 1, @listener.size - assert_equal :wot, @listener.first.name - assert_equal "child", @listener.first.payload + sleep(0.1) - assert_nil @listener.first.parent.duration - assert_in_delta 100, @listener.first.duration, 30 + assert_equal 1, @events.size + assert_equal :wot, @events.first.name + assert_equal Hash[:payload => "child"], @events.first.payload end - assert_equal 2, @listener.size - assert_equal :awesome, @listener.last.name - assert_equal "notifications", @listener.last.payload - assert_in_delta 100, @listener.first.parent.duration, 30 + sleep(0.1) + + assert_equal 2, @events.size + assert_equal :awesome, @events.last.name + assert_equal Hash[:payload => "notifications"], @events.last.payload + assert_in_delta 100, @events.last.duration, 70 end def test_event_is_pushed_even_if_block_fails - ActiveSupport::Notifications.instrument(:awesome, "notifications") do + ActiveSupport::Notifications.instrument(:awesome, :payload => "notifications") do raise "OMG" end rescue RuntimeError - assert_equal 1, @listener.size - assert_equal :awesome, @listener.last.name - assert_equal "notifications", @listener.last.payload + sleep(0.1) + + assert_equal 1, @events.size + assert_equal :awesome, @events.last.name + assert_equal Hash[:payload => "notifications"], @events.last.payload end -end -class NotificationsListenerTest < Test::Unit::TestCase - class MyListener < ActiveSupport::Notifications::Listener - attr_reader :consumed + def test_event_is_pushed_even_without_block + ActiveSupport::Notifications.instrument(:awesome, :payload => "notifications") + sleep(0.1) - def consume(event) - @consumed ||= [] - @consumed << event - end + assert_equal 1, @events.size + assert_equal :awesome, @events.last.name + assert_equal Hash[:payload => "notifications"], @events.last.payload end - def setup - @listener = MyListener.new - ActiveSupport::Notifications.register @listener - end + def test_subscriber_with_pattern + @another = [] + ActiveSupport::Notifications.subscribe("cache"){ |event| @another << event } + ActiveSupport::Notifications.instrument(:cache){ 1 } - def teardown - ActiveSupport::Notifications.unregister @listener - end + sleep(0.1) - def test_thread_is_exposed_by_listener - assert_kind_of Thread, @listener.thread + assert_equal 1, @another.size + assert_equal :cache, @another.first.name + assert_equal 1, @another.first.result end - def test_event_is_consumed_when_an_action_is_instrumented - ActiveSupport::Notifications.instrument(:sum) do - 1 + 1 - end - sleep 0.1 - assert_equal 1, @listener.consumed.size - assert_equal :sum, @listener.consumed.first.name - assert_equal 2, @listener.consumed.first.result + def test_subscriber_with_pattern_as_regexp + @another = [] + ActiveSupport::Notifications.subscribe(/cache/){ |event| @another << event } + + ActiveSupport::Notifications.instrument(:something){ 0 } + ActiveSupport::Notifications.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_with_sevaral_consumers_and_several_events - @another = MyListener.new - ActiveSupport::Notifications.register @another + def test_with_several_consumers_and_several_events + @another = [] + ActiveSupport::Notifications.subscribe { |event| @another << event } 1.upto(100) do |i| - ActiveSupport::Notifications.instrument(:value) do - i - end + ActiveSupport::Notifications.instrument(:value){ i } end sleep 0.1 - assert_equal 100, @listener.consumed.size - assert_equal :value, @listener.consumed.first.name - assert_equal 1, @listener.consumed.first.result - assert_equal 100, @listener.consumed.last.result - - assert_equal 100, @another.consumed.size - assert_equal :value, @another.consumed.first.name - assert_equal 1, @another.consumed.first.result - assert_equal 100, @another.consumed.last.result - ensure - ActiveSupport::Notifications.unregister @another + assert_equal 100, @events.size + assert_equal :value, @events.first.name + assert_equal 1, @events.first.result + assert_equal 100, @events.last.result + + assert_equal 100, @another.size + assert_equal :value, @another.first.name + assert_equal 1, @another.first.result + assert_equal 100, @another.last.result end end diff --git a/railties/lib/rails/application.rb b/railties/lib/rails/application.rb index a0e5d6a5a5..fe2dc3769e 100644 --- a/railties/lib/rails/application.rb +++ b/railties/lib/rails/application.rb @@ -487,5 +487,16 @@ module Rails Rails::Generators.options.deep_merge! config.generators.options end end + + # For each framework, search for instrument file with Notifications hooks. + # + initializer :load_notifications_hooks do + config.frameworks.each do |framework| + begin + require "#{framework}/notifications" + rescue LoadError => e + end + end + end end end diff --git a/railties/lib/rails/configuration.rb b/railties/lib/rails/configuration.rb index 322590f108..3cb39245ff 100644 --- a/railties/lib/rails/configuration.rb +++ b/railties/lib/rails/configuration.rb @@ -290,6 +290,14 @@ module Rails end end + # Allows Notifications queue to be modified. + # + # config.notifications.queue = MyNewQueue.new + # + def notifications + ActiveSupport::Notifications + end + class Generators #:nodoc: attr_accessor :aliases, :options, :colorize_logging diff --git a/railties/test/application/notifications_test.rb b/railties/test/application/notifications_test.rb new file mode 100644 index 0000000000..c861d10c35 --- /dev/null +++ b/railties/test/application/notifications_test.rb @@ -0,0 +1,50 @@ +require "isolation/abstract_unit" + +module ApplicationTests + class NotificationsTest < Test::Unit::TestCase + include ActiveSupport::Testing::Isolation + + class MyQueue + attr_reader :events, :subscribers + + def initialize + @events = [] + @subscribers = [] + end + + def publish(name, payload=nil) + @events << name + end + + def subscribe(pattern=nil, &block) + @subscribers << pattern + end + end + + def setup + build_app + boot_rails + + require "active_support/notifications" + Rails::Initializer.run do |c| + c.notifications.queue = MyQueue.new + c.notifications.subscribe(/listening/) do + puts "Cool" + end + end + end + + test "new queue is set" do + ActiveSupport::Notifications.instrument(:foo) + assert_equal :foo, ActiveSupport::Notifications.queue.events.first + end + + test "frameworks subscribers are loaded" do + assert_equal 1, ActiveSupport::Notifications.queue.subscribers.count { |s| s == "sql" } + end + + test "configuration subscribers are loaded" do + assert_equal 1, ActiveSupport::Notifications.queue.subscribers.count { |s| s == /listening/ } + end + end +end |