Reset ActiveRecord::LogSubscriber runtime at the start of each request

Previously the runtime was reset implicitly when #cleanup_view_runtime was called at the end of most requests. However, this doesn't happen when the request redirects, or send_file is called.  Consequently, the ActiveRecord runtime recorded in the logs included the time taken for both the current request and the previous redirect.  Explicitly resetting at the start of each request ensures that this can't happen, no matter what occurs previously.
This commit is contained in:
Tom Ward 2011-05-14 10:31:00 +01:00
parent 518ffcd168
commit 6d96124284
2 changed files with 18 additions and 0 deletions

@ -11,6 +11,10 @@ class LogSubscriberController < ActionController::Base
def show
render :inline => "<%= Project.all %>"
end
def zero
render :inline => "Zero DB runtime"
end
end
include ActiveSupport::LogSubscriber::TestHelper
@ -39,4 +43,13 @@ def test_log_with_active_record
assert_equal 2, @logger.logged(:info).size
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms\)/, @logger.logged(:info)[1])
end
def test_runtime_reset_before_requests
ActiveRecord::LogSubscriber.runtime += 12345
get :zero
wait
assert_equal 2, @logger.logged(:info).size
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: 0.0ms\)/, @logger.logged(:info)[1])
end
end

@ -9,6 +9,11 @@ module ControllerRuntime
attr_internal :db_runtime
def process_action(action, *args)
ActiveRecord::LogSubscriber.reset_runtime
super
end
def cleanup_view_runtime
if ActiveRecord::Base.connected?
db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime