Merge pull request #1228 from fcheung/db_time_fix2

Take into account time spent in AR even if a redirect occurs or if it is after the render

actionpack/test/activerecord/controller_runtime_test.rb

@@ -15,6 +15,17 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     def zero
       render :inline => "Zero DB runtime"
     end
+    
+    def redirect
+      Project.all
+      redirect_to :action => 'show'
+    end
+
+    def db_after_render
+      render :inline => "Hello world"
+      Project.all
+      ActiveRecord::LogSubscriber.runtime += 100
+    end
   end
 
   include ActiveSupport::LogSubscriber::TestHelper
@@ -52,4 +63,19 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     assert_equal 2, @logger.logged(:info).size
     assert_match(/\(Views: [\d.]+ms \| ActiveRecord: 0.0ms\)/, @logger.logged(:info)[1])
   end
+  
+  def test_log_with_active_record_when_redirecting
+    get :redirect
+    wait
+    assert_equal 3, @logger.logged(:info).size
+    assert_match(/\(ActiveRecord: [\d.]+ms\)/, @logger.logged(:info)[2])
+  end
+  
+  def test_include_time_query_time_after_rendering
+    get :db_after_render
+    wait
+    
+    assert_equal 2, @logger.logged(:info).size
+    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms\)/, @logger.logged(:info)[1])
+  end
 end

activerecord/lib/active_record/railties/controller_runtime.rb

@@ -32,7 +32,9 @@ module ActiveRecord
 
       def append_info_to_payload(payload)
         super
-        payload[:db_runtime] = db_runtime
+        if ActiveRecord::Base.connected?
+          payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::LogSubscriber.reset_runtime
+        end
       end
 
       module ClassMethods