aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorEileen Uchitelle <eileencodes@gmail.com>2018-10-09 14:08:25 -0400
committerEileen Uchitelle <eileencodes@gmail.com>2018-10-10 08:07:12 -0400
commite8c1be4ae7797f3ede588d2cf04a0155b4d6ce4a (patch)
tree99a96136ddf8581c53da3ce08f3b88660eaa92f8
parent168a9728dd00069efe04fec4b59d29e3752fbfb3 (diff)
downloadrails-e8c1be4ae7797f3ede588d2cf04a0155b4d6ce4a.tar.gz
rails-e8c1be4ae7797f3ede588d2cf04a0155b4d6ce4a.tar.bz2
rails-e8c1be4ae7797f3ede588d2cf04a0155b4d6ce4a.zip
Add allocations to template renderer subscription
This PR adds the allocations to the instrumentation for template and partial rendering. Before: ``` Rendering posts/new.html.erb within layouts/application Rendered posts/_form.html.erb (9.7ms) Rendered posts/new.html.erb within layouts/application (10.9ms) Completed 200 OK in 902ms (Views: 890.8ms | ActiveRecord: 0.8ms) ``` After: ``` Rendering posts/new.html.erb within layouts/application 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) ```
-rw-r--r--actionpack/lib/action_controller/log_subscriber.rb7
-rw-r--r--actionview/CHANGELOG.md12
-rw-r--r--actionview/lib/action_view/log_subscriber.rb6
-rw-r--r--actionview/test/activerecord/controller_runtime_test.rb10
-rw-r--r--actionview/test/template/log_subscriber_test.rb4
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