diff options
| -rw-r--r-- | actionpack/lib/action_controller/log_subscriber.rb | 7 | ||||
| -rw-r--r-- | actionview/CHANGELOG.md | 12 | ||||
| -rw-r--r-- | actionview/lib/action_view/log_subscriber.rb | 6 | ||||
| -rw-r--r-- | actionview/test/activerecord/controller_runtime_test.rb | 10 | ||||
| -rw-r--r-- | actionview/test/template/log_subscriber_test.rb | 4 |
5 files changed, 27 insertions, 12 deletions
diff --git a/actionpack/lib/action_controller/log_subscriber.rb b/actionpack/lib/action_controller/log_subscriber.rb index 6de1fb2c19..afbd38e7fe 100644 --- a/actionpack/lib/action_controller/log_subscriber.rb +++ b/actionpack/lib/action_controller/log_subscriber.rb @@ -18,14 +18,17 @@ module ActionController def process_action(event) info do - payload = event.payload + payload = event.payload additions = ActionController::Base.log_process_action(payload) - status = payload[:status] + if status.nil? && payload[:exception].present? exception_class_name = payload[:exception].first status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name) end + + additions << "Allocations: #{event.allocations}" + message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms" message << " (#{additions.join(" | ")})" unless additions.empty? message << "\n\n" if defined?(Rails.env) && Rails.env.development? diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md index 252fce6472..fd8bae0cdf 100644 --- a/actionview/CHANGELOG.md +++ b/actionview/CHANGELOG.md @@ -1,3 +1,15 @@ +* Add allocations to template rendering instrumentation. + + Adds the allocations for template and partial rendering to the server output on render. + + ``` + Rendered posts/_form.html.erb (Duration: 7.1ms | Allocations: 6004) + Rendered posts/new.html.erb within layouts/application (Duration: 8.3ms | Allocations: 6654) + Completed 200 OK in 858ms (Views: 848.4ms | ActiveRecord: 0.4ms | Allocations: 1539564) + ``` + + *Eileen M. Uchitelle*, *Aaron Patterson* + * Respect the `only_path` option passed to `url_for` when the options are passed in as an array Fixes #33237. diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb index db07b9d7fb..227f025385 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -18,7 +18,7 @@ module ActionView info do message = +" Rendered #{from_rails_root(event.payload[:identifier])}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] - message << " (#{event.duration.round(1)}ms)" + message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" end end @@ -26,7 +26,7 @@ module ActionView info do message = +" Rendered #{from_rails_root(event.payload[:identifier])}" message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] - message << " (#{event.duration.round(1)}ms)" + message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" message << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil? message end @@ -37,7 +37,7 @@ module ActionView info do " Rendered collection of #{from_rails_root(identifier)}" \ - " #{render_count(event.payload)} (#{event.duration.round(1)}ms)" + " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" end end diff --git a/actionview/test/activerecord/controller_runtime_test.rb b/actionview/test/activerecord/controller_runtime_test.rb index 7cbd3aaf89..563044f11e 100644 --- a/actionview/test/activerecord/controller_runtime_test.rb +++ b/actionview/test/activerecord/controller_runtime_test.rb @@ -68,7 +68,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) end def test_runtime_reset_before_requests @@ -77,20 +77,20 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: 0\.0ms\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) end def test_log_with_active_record_when_post post :create wait - assert_match(/ActiveRecord: ([1-9][\d.]+)ms\)/, @logger.logged(:info)[2]) + assert_match(/ActiveRecord: ([1-9][\d.]+)ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[2]) 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]) + assert_match(/\(ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[2]) end def test_include_time_query_time_after_rendering @@ -98,6 +98,6 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase wait assert_equal 2, @logger.logged(:info).size - assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms\)/, @logger.logged(:info)[1]) + assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1]) end end diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb index 7f4fd25573..9fcf80bb24 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -129,14 +129,14 @@ class AVLogSubscriberTest < ActiveSupport::TestCase wait *, cached_inner, uncached_outer = @logger.logged(:info) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner) - assert_match(/Rendered test\/_nested_cached_customer\.erb \(.*?ms\)$/, uncached_outer) + assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) # Second render hits the cache for the _cached_customer partial. Outer template's log shouldn't be affected. @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") }) wait *, cached_inner, uncached_outer = @logger.logged(:info) assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner) - assert_match(/Rendered test\/_nested_cached_customer\.erb \(.*?ms\)$/, uncached_outer) + assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer) end end |