Skip to content

Commit

Permalink
Browse files Browse the repository at this point in the history
Resurrect AC::Benchmarking [#3140 state:resolved]
  • Loading branch information
josh committed Sep 24, 2009
1 parent c2f8b4e commit 9f96708
Show file tree
Hide file tree
Showing 4 changed files with 108 additions and 15 deletions.
7 changes: 4 additions & 3 deletions actionpack/lib/action_controller.rb
@@ -1,21 +1,22 @@
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"
autoload :RenderingController, "action_controller/metal/rendering_controller"
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'
Expand Down
1 change: 1 addition & 0 deletions actionpack/lib/action_controller/base.rb
Expand Up @@ -14,6 +14,7 @@ class Base < Metal
include ActionController::Layouts
include ActionController::ConditionalGet
include ActionController::RackConvenience
include ActionController::Benchmarking

# Legacy modules
include SessionManagement
Expand Down
92 changes: 92 additions & 0 deletions 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
23 changes: 11 additions & 12 deletions actionpack/test/controller/logging_test.rb
Expand Up @@ -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
Expand All @@ -31,25 +31,24 @@ def setup

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

0 comments on commit 9f96708

Please sign in to comment.