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) ```
This commit is contained in:
parent
168a9728dd
commit
e8c1be4ae7
@ -18,14 +18,17 @@ def start_processing(event)
|
|||||||
|
|
||||||
def process_action(event)
|
def process_action(event)
|
||||||
info do
|
info do
|
||||||
payload = event.payload
|
payload = event.payload
|
||||||
additions = ActionController::Base.log_process_action(payload)
|
additions = ActionController::Base.log_process_action(payload)
|
||||||
|
|
||||||
status = payload[:status]
|
status = payload[:status]
|
||||||
|
|
||||||
if status.nil? && payload[:exception].present?
|
if status.nil? && payload[:exception].present?
|
||||||
exception_class_name = payload[:exception].first
|
exception_class_name = payload[:exception].first
|
||||||
status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
|
status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
|
||||||
end
|
end
|
||||||
|
|
||||||
|
additions << "Allocations: #{event.allocations}"
|
||||||
|
|
||||||
message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
|
message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
|
||||||
message << " (#{additions.join(" | ")})" unless additions.empty?
|
message << " (#{additions.join(" | ")})" unless additions.empty?
|
||||||
message << "\n\n" if defined?(Rails.env) && Rails.env.development?
|
message << "\n\n" if defined?(Rails.env) && Rails.env.development?
|
||||||
|
@ -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
|
* Respect the `only_path` option passed to `url_for` when the options are passed in as an array
|
||||||
|
|
||||||
Fixes #33237.
|
Fixes #33237.
|
||||||
|
@ -18,7 +18,7 @@ def render_template(event)
|
|||||||
info do
|
info do
|
||||||
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
|
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
|
||||||
message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
|
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
|
||||||
end
|
end
|
||||||
|
|
||||||
@ -26,7 +26,7 @@ def render_partial(event)
|
|||||||
info do
|
info do
|
||||||
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
|
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
|
||||||
message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
|
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 << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil?
|
||||||
message
|
message
|
||||||
end
|
end
|
||||||
@ -37,7 +37,7 @@ def render_collection(event)
|
|||||||
|
|
||||||
info do
|
info do
|
||||||
" Rendered collection of #{from_rails_root(identifier)}" \
|
" 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
|
||||||
end
|
end
|
||||||
|
|
||||||
|
@ -68,7 +68,7 @@ def test_log_with_active_record
|
|||||||
wait
|
wait
|
||||||
|
|
||||||
assert_equal 2, @logger.logged(:info).size
|
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
|
end
|
||||||
|
|
||||||
def test_runtime_reset_before_requests
|
def test_runtime_reset_before_requests
|
||||||
@ -77,20 +77,20 @@ def test_runtime_reset_before_requests
|
|||||||
wait
|
wait
|
||||||
|
|
||||||
assert_equal 2, @logger.logged(:info).size
|
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
|
end
|
||||||
|
|
||||||
def test_log_with_active_record_when_post
|
def test_log_with_active_record_when_post
|
||||||
post :create
|
post :create
|
||||||
wait
|
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
|
end
|
||||||
|
|
||||||
def test_log_with_active_record_when_redirecting
|
def test_log_with_active_record_when_redirecting
|
||||||
get :redirect
|
get :redirect
|
||||||
wait
|
wait
|
||||||
assert_equal 3, @logger.logged(:info).size
|
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
|
end
|
||||||
|
|
||||||
def test_include_time_query_time_after_rendering
|
def test_include_time_query_time_after_rendering
|
||||||
@ -98,6 +98,6 @@ def test_include_time_query_time_after_rendering
|
|||||||
wait
|
wait
|
||||||
|
|
||||||
assert_equal 2, @logger.logged(:info).size
|
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
|
||||||
end
|
end
|
||||||
|
@ -129,14 +129,14 @@ def test_render_uncached_outer_partial_with_inner_cached_partial_wont_mix_cache_
|
|||||||
wait
|
wait
|
||||||
*, cached_inner, uncached_outer = @logger.logged(:info)
|
*, cached_inner, uncached_outer = @logger.logged(:info)
|
||||||
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner)
|
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.
|
# 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") })
|
@view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
|
||||||
wait
|
wait
|
||||||
*, cached_inner, uncached_outer = @logger.logged(:info)
|
*, cached_inner, uncached_outer = @logger.logged(:info)
|
||||||
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner)
|
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
|
||||||
end
|
end
|
||||||
|
|
||||||
|
Loading…
Reference in New Issue
Block a user