Unify benchmark APIs.

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

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

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)

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

actionpack/lib/action_view/helpers/benchmark_helper.rb

@@ -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

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

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

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'

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

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 buffer
-      controller.logger.send(:buffer)
+    def logger
+      @logger ||= begin
+        logger = ActiveSupport::BufferedLogger.new(StringIO.new)
+        logger.auto_flushing = false
+        logger
+      end
     end
-  
+
+    def buffer
+      logger.send(:buffer)
+    end
+
     def assert_last_logged(message = 'Benchmarking')
       assert_match(/^#{message} \(.*\)$/, buffer.last)
     end