diff options
5 files changed, 19 insertions, 16 deletions
diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb index 91d454f0c3..e0c75c9e44 100644 --- a/actionpack/lib/action_controller/metal/instrumentation.rb +++ b/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 diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb index d6a71afc23..c21305ac8f 100644 --- a/actionpack/lib/action_controller/railties/subscriber.rb +++ b/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" diff --git a/actionpack/test/activerecord/controller_runtime_test.rb b/actionpack/test/activerecord/controller_runtime_test.rb index 6c9a24a760..37c7738301 100644 --- a/actionpack/test/activerecord/controller_runtime_test.rb +++ b/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 diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb index 374dd63a7d..b2888dc4c2 100644 --- a/actionpack/test/controller/subscriber_test.rb +++ b/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 diff --git a/activerecord/lib/active_record/railties/controller_runtime.rb b/activerecord/lib/active_record/railties/controller_runtime.rb index 535e967ec3..a4f4e15c2e 100644 --- a/activerecord/lib/active_record/railties/controller_runtime.rb +++ b/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 |