diff options
| -rw-r--r-- | actionpack/lib/abstract_controller/logger.rb | 18 | ||||
| -rw-r--r-- | actionpack/lib/action_controller/instrument.rb | 6 | ||||
| -rw-r--r-- | actionpack/lib/action_controller/metal/benchmarking.rb | 23 | ||||
| -rw-r--r-- | actionpack/lib/action_view/helpers.rb | 6 | ||||
| -rw-r--r-- | actionpack/lib/action_view/helpers/benchmark_helper.rb | 54 | ||||
| -rwxr-xr-x | activerecord/lib/active_record/base.rb | 36 | ||||
| -rwxr-xr-x | activerecord/test/cases/base_test.rb | 10 | ||||
| -rw-r--r-- | activesupport/lib/active_support/autoload.rb | 1 | ||||
| -rw-r--r-- | activesupport/lib/active_support/benchmarkable.rb | 59 | ||||
| -rw-r--r-- | activesupport/test/benchmarkable_test.rb (renamed from actionpack/test/template/benchmark_helper_test.rb) | 35 |
10 files changed, 98 insertions, 150 deletions
diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index cf1a6f1240..ebdeab3dfb 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(message, log_level=::Logger::DEBUG) - return unless logger && logger.level >= log_level - 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 logger - yield - ensure - logger.level = old_logger_level if logger - end + extend ActiveSupport::Benchmarkable end # A class that allows you to defer expensive processing diff --git a/actionpack/lib/action_controller/instrument.rb b/actionpack/lib/action_controller/instrument.rb index 00888c425f..2c87ed7391 100644 --- a/actionpack/lib/action_controller/instrument.rb +++ b/actionpack/lib/action_controller/instrument.rb @@ -1,6 +1,8 @@ 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) + 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_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_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/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb index eae59dfad7..76dbd00ad9 100755 --- a/activerecord/lib/active_record/base.rb +++ b/activerecord/lib/active_record/base.rb @@ -1,6 +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' @@ -12,7 +13,6 @@ 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: @@ -1465,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) @@ -3155,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/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 a0fc2bb123..fa657ac99a 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' 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/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 |