diff options
author | Joshua Peek <josh@joshpeek.com> | 2009-09-24 12:13:09 -0500 |
---|---|---|
committer | Joshua Peek <josh@joshpeek.com> | 2009-09-24 12:13:09 -0500 |
commit | 9f96708f53b4eee8830554dd8f0a482160ef4c73 (patch) | |
tree | c2899c3716b0ae6715cd617d1d6b443f84da205b /actionpack/lib/action_controller/metal/benchmarking.rb | |
parent | c2f8b4e92f8487b83a7c7bd0f19e535a9122d20e (diff) | |
download | rails-9f96708f53b4eee8830554dd8f0a482160ef4c73.tar.gz rails-9f96708f53b4eee8830554dd8f0a482160ef4c73.tar.bz2 rails-9f96708f53b4eee8830554dd8f0a482160ef4c73.zip |
Resurrect AC::Benchmarking [#3140 state:resolved]
Diffstat (limited to 'actionpack/lib/action_controller/metal/benchmarking.rb')
-rw-r--r-- | actionpack/lib/action_controller/metal/benchmarking.rb | 92 |
1 files changed, 92 insertions, 0 deletions
diff --git a/actionpack/lib/action_controller/metal/benchmarking.rb b/actionpack/lib/action_controller/metal/benchmarking.rb new file mode 100644 index 0000000000..d4cb1e122d --- /dev/null +++ b/actionpack/lib/action_controller/metal/benchmarking.rb @@ -0,0 +1,92 @@ +require '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 + if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? + db_runtime = ActiveRecord::Base.connection.reset_runtime + end + + render_output = nil + @view_runtime = Benchmark.ms { render_output = super } + + if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? + @db_rt_before_render = db_runtime + @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime + @view_runtime -= @db_rt_after_render + end + + render_output + else + super + end + end + + private + def process_action(*args) + if logger + ms = [Benchmark.ms { super }, 0.01].max + logging_view = defined?(@view_runtime) + logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? + + log_message = 'Completed in %.0fms' % ms + + if logging_view || logging_active_record + log_message << " (" + log_message << view_runtime if logging_view + + if logging_active_record + log_message << ", " if logging_view + log_message << active_record_runtime + ")" + else + ")" + end + end + + log_message << " | #{response.status}" + log_message << " [#{complete_request_uri rescue "unknown"}]" + + logger.info(log_message) + response.headers["X-Runtime"] = "%.0f" % ms + else + super + end + end + + def view_runtime + "View: %.0f" % @view_runtime + end + + def active_record_runtime + db_runtime = ActiveRecord::Base.connection.reset_runtime + db_runtime += @db_rt_before_render if @db_rt_before_render + db_runtime += @db_rt_after_render if @db_rt_after_render + "DB: %.0f" % db_runtime + end + end +end |