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.

1 files changed, 13 insertions, 0 deletions

diff --git a/actionpack/test/activerecord/controller_runtime_test.rb b/actionpack/test/activerecord/controller_runtime_test.rb
index c030315d2b..b87b9f9c47 100644
--- a/actionpack/test/activerecord/controller_runtime_test.rb
+++ b/actionpack/test/activerecord/controller_runtime_test.rb
@@ -11,6 +11,10 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     def show
       render :inline => "<%= Project.all %>"
     end
+
+    def zero
+      render :inline => "Zero DB runtime"
+    end
   end
 
   include ActiveSupport::LogSubscriber::TestHelper
@@ -39,4 +43,13 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     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