diff options
| -rw-r--r-- | actionpack/lib/action_controller.rb | 7 | ||||
| -rw-r--r-- | actionpack/lib/action_controller/base.rb | 1 | ||||
| -rw-r--r-- | actionpack/lib/action_controller/metal/benchmarking.rb | 92 | ||||
| -rw-r--r-- | actionpack/test/controller/logging_test.rb | 23 |
4 files changed, 108 insertions, 15 deletions
diff --git a/actionpack/lib/action_controller.rb b/actionpack/lib/action_controller.rb index c0b7234cbf..6702cb47f8 100644 --- a/actionpack/lib/action_controller.rb +++ b/actionpack/lib/action_controller.rb @@ -1,10 +1,12 @@ module ActionController autoload :Base, "action_controller/base" + autoload :Benchmarking, "action_controller/metal/benchmarking" autoload :ConditionalGet, "action_controller/metal/conditional_get" + autoload :Helpers, "action_controller/metal/helpers" autoload :HideActions, "action_controller/metal/hide_actions" + autoload :Layouts, "action_controller/metal/layouts" autoload :Metal, "action_controller/metal" autoload :Middleware, "action_controller/middleware" - autoload :Layouts, "action_controller/metal/layouts" autoload :RackConvenience, "action_controller/metal/rack_convenience" autoload :Rails2Compatibility, "action_controller/metal/compatibility" autoload :Redirector, "action_controller/metal/redirector" @@ -12,10 +14,9 @@ module ActionController autoload :RenderOptions, "action_controller/metal/render_options" autoload :Rescue, "action_controller/metal/rescuable" autoload :Responder, "action_controller/metal/responder" + autoload :Session, "action_controller/metal/session" autoload :Testing, "action_controller/metal/testing" autoload :UrlFor, "action_controller/metal/url_for" - autoload :Session, "action_controller/metal/session" - autoload :Helpers, "action_controller/metal/helpers" # Ported modules # require 'action_controller/routing' diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index f5bd0a00a1..5338a70104 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -14,6 +14,7 @@ module ActionController include ActionController::Layouts include ActionController::ConditionalGet include ActionController::RackConvenience + include ActionController::Benchmarking # Legacy modules include SessionManagement 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 diff --git a/actionpack/test/controller/logging_test.rb b/actionpack/test/controller/logging_test.rb index 98ffbc3813..2b5e8d8bde 100644 --- a/actionpack/test/controller/logging_test.rb +++ b/actionpack/test/controller/logging_test.rb @@ -12,11 +12,11 @@ class LoggingTest < ActionController::TestCase class MockLogger attr_reader :logged attr_accessor :level - + def initialize @level = Logger::DEBUG end - + def method_missing(method, *args, &blk) @logged ||= [] @logged << args.first @@ -31,25 +31,24 @@ class LoggingTest < ActionController::TestCase def test_logging_without_parameters get :show - assert_equal 2, logs.size + assert_equal 3, logs.size assert_nil logs.detect {|l| l =~ /Parameters/ } end def test_logging_with_parameters get :show, :id => '10' - assert_equal 3, logs.size + assert_equal 4, logs.size params = logs.detect {|l| l =~ /Parameters/ } assert_equal 'Parameters: {"id"=>"10"}', params end - + private + def set_logger + @controller.logger = MockLogger.new + end - def set_logger - @controller.logger = MockLogger.new - end - - def logs - @logs ||= @controller.logger.logged.compact.map {|l| l.to_s.strip} - end + def logs + @logs ||= @controller.logger.logged.compact.map {|l| l.to_s.strip} + end end |