Tidy up ActiveRecord and Views runtime information on process action logger.

actionpack/lib/action_controller/metal/instrumentation.rb

@@ -66,11 +66,13 @@ module ActionController
 
     module ClassMethods
       # A hook which allows other frameworks to log what happened during
-      # controller process action.
+      # controller process action. This method should return an awway
+      # with the messages to be added.
       # :api: plugin
       def log_process_action(controller) #:nodoc:
-        view_runtime = controller.send :view_runtime
-        logger.info("  View runtime: %.1fms" % view_runtime.to_f) if view_runtime
+        messages, view_runtime = [], controller.send(:view_runtime)
+        messages << ("Views: %.1fms" % view_runtime.to_f) if view_runtime
+        messages
       end
     end
   end

actionpack/lib/action_controller/railties/subscriber.rb

@@ -12,9 +12,10 @@ module ActionController
         params = controller.send(:filter_parameters, request.params)
         info "  Parameters: #{params.inspect}" unless params.empty?
 
-        ActionController::Base.log_process_action(controller)
+        additions = ActionController::Base.log_process_action(controller)
 
         message = "Completed in %.0fms" % event.duration
+        message << " (#{additions.join(" | ")})" unless additions.blank?
         message << " | #{controller.response.status}"
         message << " [#{request.request_uri rescue "unknown"}]\n\n"
 

actionpack/test/activerecord/controller_runtime_test.rb

@@ -37,8 +37,8 @@ module ControllerRuntimeSubscriberTest
     get :show
     wait
 
-    assert_equal 4, @logger.logged(:info).size
-    assert_match /ActiveRecord runtime/, @logger.logged(:info)[2]
+    assert_equal 2, @logger.logged(:info).size
+    assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[1]
   end
 
   class SyncSubscriberTest < ActionController::TestCase

actionpack/test/controller/subscriber_test.rb

@@ -66,7 +66,7 @@ module ActionControllerSubscriberTest
   def test_process_action
     get :show
     wait
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_match /Processed\sAnother::SubscribersController#show/, logs[0]
   end
 
@@ -80,14 +80,14 @@ module ActionControllerSubscriberTest
     get :show, :id => '10'
     wait
 
-    assert_equal 4, logs.size
+    assert_equal 3, logs.size
     assert_equal 'Parameters: {"id"=>"10"}', logs[1]
   end
 
   def test_process_action_with_view_runtime
     get :show
     wait
-    assert_match /View runtime/, logs[1]
+    assert_match /\(Views: [\d\.]+ms\)/, logs[1]
   end
 
   def test_process_action_with_status_and_request_uri
@@ -123,7 +123,7 @@ module ActionControllerSubscriberTest
     get :data_sender
     wait
 
-    assert_equal 4, logs.size
+    assert_equal 3, logs.size
     assert_match /Sent data omg\.txt/, logs[0]
   end
 
@@ -131,7 +131,7 @@ module ActionControllerSubscriberTest
     get :file_sender
     wait
 
-    assert_equal 4, logs.size
+    assert_equal 3, logs.size
     assert_match /Sent file/, logs[0]
     assert_match /test\/fixtures\/company\.rb/, logs[0]
   end
@@ -150,7 +150,7 @@ module ActionControllerSubscriberTest
     get :with_fragment_cache
     wait
 
-    assert_equal 5, logs.size
+    assert_equal 4, logs.size
     assert_match /Exist fragment\? views\/foo/, logs[0]
     assert_match /Write fragment views\/foo/, logs[1]
   ensure
@@ -162,7 +162,7 @@ module ActionControllerSubscriberTest
     get :with_page_cache
     wait
 
-    assert_equal 4, logs.size
+    assert_equal 3, logs.size
     assert_match /Write page/, logs[0]
     assert_match /\/index\.html/, logs[0]
   ensure

activerecord/lib/active_record/railties/controller_runtime.rb

@@ -21,9 +21,9 @@ module ActiveRecord
 
       module ClassMethods
         def log_process_action(controller)
-          super
-          db_runtime = controller.send :db_runtime
-          logger.info("  ActiveRecord runtime: %.1fms" % db_runtime.to_f) if db_runtime
+          messages, db_runtime = super, controller.send(:db_runtime)
+          messages << ("ActiveRecord: %.1fms" % db_runtime.to_f) if db_runtime
+          messages
         end
       end
     end