Unify benchmark APIs.

3 files changed, 147 insertions, 0 deletions

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/activesupport/test/benchmarkable_test.rb b/activesupport/test/benchmarkable_test.rb
new file mode 100644
index 0000000000..e807bcb732
--- /dev/null
+++ b/activesupport/test/benchmarkable_test.rb
@@ -0,0 +1,87 @@
+require 'abstract_unit'
+require 'action_view/helpers/benchmark_helper'
+
+class BenchmarkableTest < ActiveSupport::TestCase
+  include ActiveSupport::Benchmarkable
+
+  def teardown
+    logger.send(:clear_buffer)
+  end
+
+  def test_without_block
+    assert_raise(LocalJumpError) { benchmark }
+    assert buffer.empty?
+  end
+
+  def test_defaults
+    i_was_run = false
+    benchmark { i_was_run = true }
+    assert i_was_run
+    assert_last_logged
+  end
+
+  def test_with_message
+    i_was_run = false
+    benchmark('test_run') { i_was_run = true }
+    assert i_was_run
+    assert_last_logged 'test_run'
+  end
+
+  def test_with_message_and_deprecated_level
+    i_was_run = false
+
+    assert_deprecated do
+      benchmark('debug_run', :debug) { i_was_run = true }
+    end
+
+    assert i_was_run
+    assert_last_logged 'debug_run'
+  end
+
+  def test_within_level
+    logger.level = ActiveSupport::BufferedLogger::DEBUG
+    benchmark('included_debug_run', :level => :debug) { }
+    assert_last_logged 'included_debug_run'
+  end
+
+  def test_outside_level
+    logger.level = ActiveSupport::BufferedLogger::ERROR
+    benchmark('skipped_debug_run', :level => :debug) { }
+    assert_no_match(/skipped_debug_run/, buffer.last)
+  ensure
+    logger.level = ActiveSupport::BufferedLogger::DEBUG
+  end
+
+  def test_without_silencing
+    benchmark('debug_run', :silence => false) do
+      logger.info "not silenced!"
+    end
+
+    assert_equal 2, buffer.size
+  end
+
+  def test_with_silencing
+    benchmark('debug_run', :silence => true) do
+      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
+      logger.send(:buffer)
+    end
+
+    def assert_last_logged(message = 'Benchmarking')
+      assert_match(/^#{message} \(.*\)$/, buffer.last)
+    end
+end