Browse files

Unify benchmark APIs.

  • Loading branch information...
1 parent aeaabc6 commit a15e02d44ac2afb27a7e8e652c98a796d271b645 @josevalim josevalim committed Oct 9, 2009
View
18 actionpack/lib/abstract_controller/logger.rb
@@ -1,27 +1,13 @@
require 'active_support/core_ext/logger'
+require 'active_support/benchmarkable'
module AbstractController
module Logger
extend ActiveSupport::Concern
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
View
6 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
View
23 actionpack/lib/action_controller/metal/benchmarking.rb
@@ -1,30 +1,11 @@
-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
# package has been included, a separate timing section for database calls will be added as well.
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 @@ def render(*args, &block)
else
super
end
- end
+ end
private
def process_action(*args)
View
6 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 ClassMethods
include SanitizeHelper::ClassMethods
end
+ include ActiveSupport::Benchmarkable
+
include ActiveModelHelper
include AssetTagHelper
include AtomFeedHelper
- include BenchmarkHelper
include CacheHelper
include CaptureHelper
include DateHelper
View
54 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
View
36 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/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 @@ def sanitize(object) #: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 @@ def object_from_yaml(string)
Base.class_eval do
extend ActiveModel::Naming
extend QueryCache::ClassMethods
+ extend ActiveSupport::Benchmarkable
+
include Validations
include Locking::Optimistic, Locking::Pessimistic
include AttributeMethods
View
10 activerecord/test/cases/base_test.rb
@@ -2195,9 +2195,9 @@ def test_benchmark_with_log_level
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 @@ def test_benchmark_with_use_silence
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
View
1 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'
View
59 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
View
35 ...ck/test/template/benchmark_helper_test.rb → 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,41 +39,48 @@ def test_with_message_and_deprecated_level
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
end
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

0 comments on commit a15e02d

Please sign in to comment.